GoでLTSV形式でログ出力するライブラリを書いた

2016-06-13

なぜ書いたか

Goで高機能なサードパーティのログ出力ライブラリと言えばSirupsen/logrusが有名です。私もdoloopwhile/logrusltsvと組み合わせてLTSV形式のログ出力するのに使っていました。

しかし、logger のパフォーマンスについて [Go] - methaneのブログにも書かれていますが、logrus.WithFieldsはFields、つまり map[string]interface{} の値を渡す必要があります。これはGCに負荷をかけそうというのも気になりますが、Goのmapは順不同なのでログ出力の際にキーの順番がソースに書いた順番と必ずしも一致しないというのがイマイチだよなーと思っていました。

ログ出力ライブラリはライブラリによって違うものを使うのはよくないから、自作するよりメジャーなものを使うほうが良いと自重する思いもありました。

一方で、Let’s talk about logging | Dave Cheneyには賛同する点も多く、感銘を受けました。

で、一度自作してみようかなーと思っていたところに、uber-go/zapを見かけて、ログ出力の引数側を加工するという方式にインスパイアされ、ついに自分が欲しいものを自分で書いてみました。

githubレポジトリ: hnakamur/ltsvlog
APIドキュメント: ltsvlog - GoDoc

githubレポジトリのREADMEに使用例のコードがあります。

ltsvlogの設計と実装

ltsvlogのログレベル

Let’s talk about logging | Dave Cheneyにもありましたが、ログレベルが多すぎると使い分けで悩むので少ないほうが良いと私も思います。ただ、エラー以外にもなにかが成功したときに記録しておきたいことはあるので、ErrorとInfoは分けたほうが良いと思います。あと私はprintデバッグ信者なのでデバッグログ用のDebugレベルは必要です。

ということで、ltsvlogのログレベルはDebug, Info, Errorの3つです。

レベル毎に出力するかしないかの切り替えはDebugレベルのみ許可することにしました。InfoとErrorは本番運用時にもログ出力するものだけに使うという考えです。Debugレベルを出力するかどうかはNewLTSVLoggerでロガーを作るときに指定します。

またDebugレベルのログ出力は無効時には引数の評価もしたくないので、 LTSVLogger.DebugEnabled()というメソッドも用意しました。使用例はこんな感じです。

    if ltsvlog.Logger.DebugEnabled() {
        ltsvlog.Logger.Debug(ltsvlog.LV{"msg", "This is a debug message"},
            ltsvlog.LV{"key", "key1"}, ltsvlog.LV{"intValue", 234})
    }

スタックトレースの出力

LTSVLogger.ErrorWithStackでスタックトレース付きでログ出力できます。

LTSV形式ではログは1レコードで1行にする必要があります。runtime.Stackでスタックトレースをバッファに書いてくれるのですが、こちらは複数行の出力になっています。コードを適宜コピペして好きな形式で出力するようにしようかと思ったのですが、src/runtime/mprof.goのソースコードを見て思いとどまりました。

ということで、runtime.Stackの出力結果を加工するという方式で実装しています。実際のコードはltsvlog/stack.goです。コールスタックから不要な部分を取り除きつつ複数行から1行に変形するということで必ず元の長さより縮むので runtime.Stack で出力したバッファをそのまま使って変形しています。

runtime.Stackは呼び出し側がバッファを渡す必要があるのですが、サイズが小さいとスタックトレースが途中で切れてしまいます。デフォルトで 8192 というサイズにしたのですが、足りない場合は NewLTSVLoggerCustomFormat の引数でバッファサイズを指定できるようにしてます。

時刻とログレベルの出力

時刻はUTCでフォーマットは timeパッケージの RFC3339Nano = "2006-01-02T15:04:05.999999999Z07:00" に近いですが、ナノセカンドの部分は個人的な好みで9桁固定で出力するようにしました。

値の文字列化

上のコード例のようにラベルと値の組はltsvlog.LVで指定します。

将来 LV にフィールドが追加されるかもしれないと防御的に実装するなら、以下のように書いたほうが良いわけですが、LabelとValueでLVということでフィールド追加するつもりは無いので L: や V: は省略して、上記の例のように書いています。

    if ltsvlog.Logger.DebugEnabled() {
        ltsvlog.Logger.Debug(ltsvlog.LV{L: "msg", V: "This is a debug message"},
            ltsvlog.LV{L: "key", V: "key1"}, ltsvlog.LV{L: "intValue", V: 234})
    }

値の文字列化は https://github.com/hnakamur/ltsvlog/blob/v0.9.3/log.go#L175-L219 で行っています。Type switchesを使って、値の型に応じて文字列化しています。コメントにも書いていますが、byteとuint8、runeとuintは別のcaseとして書くとコンパイルエラーになったので諦めてuint8とuintのほうだけを残しています。

時刻とログレベルの出力形式と値の文字列化の方式を変えたい場合は関数を実装してNewLTSVLoggerCustomFormat の引数に指定すれば良いようにしてあります。

グローバルロガー

標準のlogパッケージではグローバルロガーの変数は非公開でlog.Printやlog.SetOutputの関数で操作するようになっています。

私は関数を増やすのが嫌だったのとグローバルロガーの変数は公開しても良いのではと思ったのでそうしました。ltsvlog.Loggerで参照できます。デフォルトでは標準出力にデバッグログありで出力するようになっています。デバッグログをオフにしたい場合はmain関数の最初のほうで(ログ出力する前に)以下のようにします。

 ltsvlog.Logger = ltsvlog.NewLTSVLogger(os.Stdout, false)

ログ出力中に設定を変えることはないという想定です。

LogWriterインタフェースと常に何も出力しないDiscard

後付ですがltsvlog.LogWriterというインタフェースも定義してみました。インタフェースは Logger という名前にしたいところでしたが、グローバルロガーに Logger という名前を使っていたので仕方なく LogWriter にしました。そして常に何も出力しない Discard というのも作りました。ただし、Infoなどの引数は評価されてしまうので実行コストが0なわけではないです。

おわりに

Benchmark resultに標準のlogパッケージと比較したベンチマーク結果を載せています。logパッケージよりは遅い手ですがほぼ同等だと言えると思います。

hnakamur/ltsvlogはコード量も大したことないので、保守で困ることはないと楽観視しています。

ということで自分で書くライブラリやアプリケーションではどんどん使っていきたいと思います。