Go の logging ライブラリ、今はとりあえず標準ライブラリの log か google/glog を使っているんだけど、 log は機能不足が、 glog は Google 標準ライブラリなのでフォーマットを調整したり flag 以外でカスタマイズするために fork しないといけなかったりするので、他のロギングライブラリどれが良いか時々話題の logger を覗いてみていた。
結果、もう logrus で良いかなーと思っているんだけどそれはいったん置いておいて、選定基準の1つのパフォーマンスについて書いておく。
logger のパフォーマンスで一番重要なのは、ログを書かない時のパフォーマンスだ。 デバッグ用の詳細なログをいたるところに散りばめているアプリケーションでも、ログレベルを WARN にしておけば、 DEBUG レベルのログがパフォーマンスに与える影響を最低限にできるべきだ。
そのために理想的な logger の持つべき機能をまとめてみる
handler だけででなく logger が level を持つ
高機能なログライブラリは大抵、 logger が record を作成し、 handler に渡すという構成になっている。 handler はログを設定された通りにフォーマットしてテキストファイルに出力したり、エラーがあったらメールを送信したりする。
handler によって処理が異なるため、ログに必要な情報を全てまとめたものが record になる。 リッチな logger だと record がトレースバックなどの取得にコストがかかる情報を持っていたりするが、それが handler に利用されないと無駄になる。
logger が level を持つことで、 record の生成自体をスキップして、高コストな情報の取得を避けたり、不要オブジェクトの生成をせずにGCに優しくなることができる。
logger の level は必ずしも handler と別に設定できる必要はない。例えば handler の level を変更不可能にすれば、 logger に handler を追加するAPIで、 logger に登録されている handler の中で一番詳細なログレベルを logger の level にすることができる。
呼び出し側が、呼び出し自体を避けやすくする
「高コストな情報取得」はトレースバックだけではない。ログの中に含める情報の取得にコストがかかるケースも有る。
その場合、 logger の呼び出し自体を、 logger のログレベルで回避する必要が出てくる。 glog は type bool Verbose を使って上手くこれを実装している。
glog.V(2).Infof("val: %v", veryHeavy()) // ログが書かれない場合も veryHeavy() が呼ばれる if glog.V(2) { glog.Infof("val: %v", veryHeavy()) // これなら呼ばれない。 }
logrus も、glog ほどかっこ良くも無ければ効率も良くない (mutex 使ってるので) が、呼び出し自体のショートカットが可能だ。
if logrus.GetLevel() >= logrus.DebugLevel { logrus.Debugf("val: %v", veryHeavy()) }
structured logging について
最近は structured logging が人気だ。通常のテキストログが printf 形式でログのメッセージの中に値を直接埋め込むのに対して、 structured logging ではメッセージは固定文字列にして付加情報として key: value を持つ。
これは、ログをJSONやLTSVなどの形式にして後から利用しやすいという利点もあるし、出力形式が文字列フォーマットよりも軽い場合はテキストログに比べて性能が上がるケースも有る。
でも大抵の場合、何らかのデータ構造へのシリアライズはテキストフォーマットより重くなりがちだし、しかも logger に任意の key: value 形式の値を渡すためにたくさんの一時オブジェクトを利用してしまう (GCへの負荷が増える) ことになりがちだ。
logrus の structured logging は次のような API になっている。
log.WithFields(log.Fields{
"animal": "walrus",
"size": 10,
}).Info("A group of walrus emerges from the ocean")
log.Fields は map[string]interface{} なので、このAPIだと (Info() が出力されない場合ですら) map が生成されてしまうし、しかも interface{} に入った value 側の変数は全部エスケープ解析でエスケープすると判断される可能性が高く、本来ヒープアロケートが一切必要ないようなローカル変数ですらヒープにアロケートされてGCに負荷をかけてしまうだろう。
mgutz/logxi はより効率の良い structured logging の API を提供している。
log.Info("A group of wairus emerges from the ocean", "animal", "walrus", "size", 10)
プログラムのミスで key: value が逆になってしまう可能性に目を瞑れば、短くて効率がいい。 logrus に比べるとあまり使われてないし機能も少ないけど、性能と structured logging が絶対に必要であれば一考に値する。
