Go言語のLogger「zap」は何故高速に構造化されたログを出力する事が出来るのか

2016.06.15

Tweet
Pocket

daichエンジニア

こんにちは。開発部の平田です。

今回は、PHP製のWeb APIをGoに移植するプロジェクトでアプリケーションの情報やエラーを出力する為のLoggerを検討した際に、uber-go/zapというライブラリが公表しているパフォーマンスがその他ライブラリと比べて大分良かったので、どこでパフォーマンスの差を出しているのか、そのアプローチを簡単に紹介したいと思います。

Zap

初めに、簡単にzapの紹介をしておくと今年の2月にUberから公開されたまだ比較的新しいプロダクトです。その為開発ステータスはBetaの段階で出力もJSONしか対応していませんが、Github上で800以上のスターが付いており注目されているプロジェクトとなっています。

「Fast, structured, leveled logging in Go」とあるように、構造化されたログを出力するためのライブラリで、標準のlogのようなprintfスタイルの出力は提供していません。代わりにkeyとvalueに対応する構造体を渡します。この辺はlogrusなどでも同じ様な感じだったりしますね。

簡単な使い方を抜粋します。

logger := zap.NewJSON()

logger.Warn("第一引数の内容が msg に出力されます")
logger.Warn("第二引数以降の内容が、fieldsに出力されます", zap.String("string", "1"), zap.Int("int", 2))

// {"msg":"第一引数の内容が msg に出力されます","level":"warn","ts":1465874047,"fields":{}}
// {"msg":"第二引数以降の内容が、fieldsに出力されます","level":"warn","ts":1465874047,"fields":{"string":"1","int":2}}

// 他のLoggerにもあるようなコンテキストを添付することが出来ます。
child := logger.With(zap.String("common1", "1"), zap.Int("common2", 2))
child.Error("Error!")

// {"msg":"Error!","level":"error","ts":1465874047,"fields":{"common1":"1","common2":2}}

可能な限りリフレクションと文字列のフォーマットを行わないという方針で設計されているので、fieldを指定する際には１つ１つ zap.String("string", "1") のようなヘルパーメソッド経由で渡す必要があります。この辺の手間はパフォーマンスとのトレードオフという所でしょうか。

その他のデータ型としては以下が用意されています。

type KeyValue interface {
    AddBool(string, bool)
    AddFloat64(string, float64)
    AddInt(string, int)
    AddInt64(string, int64)
    AddMarshaler(string, LogMarshaler) error
    // AddObject uses reflection to serialize arbitrary objects, so it's slow and
    // allocation-heavy. Consider implementing the LogMarshaler interface instead.
    AddObject(string, interface{})
    AddString(string, string)
    Nest(string, func(KeyValue) error) error
}

パフォーマンス

それでは、実際にどのようにしてパフォーマンスを出しているかを見ていきしょう。

zapが公表しているベンチマークでは、README.mdにあるように、その他のライブラリと比べてかなり高速に動作しているようです。ベンチマークのコードはbenchmarks以下にあります。

その他のライブラリとのパフォーマンス面での最大の違いとして、「reflection-free, zero-allocation JSON encoder」と公式に謳っています。reflection-freeに関しては上の例でもあるように、渡すデータを構造体でラップして型情報をLoggerに渡すことでinterface{}でデータを受けることを回避しています。ではzero-allocationの部分に関してはどの様に実現しているのでしょう。

答えから先に言ってしまうと、JSONへのEncoderとBufferをFreeListで管理することで、ランタイムのアロケーションとGCを極力行わないような戦略となっています。FreeListの実装にはsync.Poolが使われています。

var jsonPool = sync.Pool{
    New: func() interface{} {
        return &jsonEncoder{
            // Pre-allocate a reasonably-sized buffer for each encoder.
            bytes: make([]byte, 0, _initialBufSize),
        }
    },
}

最初の例を元に流れを確認してみましょう。

func NewJSON(options ...Option) Logger {
    defaultLevel := atomic.NewInt32(int32(InfoLevel))
    jl := &jsonLogger{
        enc:   newJSONEncoder(),
        level: defaultLevel,
        errW:  os.Stderr,
        w:     os.Stdout,
    }

    ...
}

func newJSONEncoder() *jsonEncoder {
    enc := jsonPool.Get().(*jsonEncoder)
    enc.truncate()
    return enc
}

func (enc *jsonEncoder) truncate() {
    enc.bytes = enc.bytes[:0]
}

zap.NewJSON()でLoggerを生成した際に、sync.Poolから取得したEncoderをencにセットします。

ちょっと話が逸れてしまいますが、newJSONEncoderで取得できるEncoderは基本的に再利用される前提なのでenc.bytesには以前にencodeしたデータが残っています。その為、再利用する際にはenc.bytesを初期化する必要があります。ここではもう一度[]byteをアロケーティングしたりゼロクリアなどは行わずにfiltered sliceを用いて初期化しています。この辺のテクニックはgo/wikiにもあるので、まだ見ていない人は一度目を通しておくと良いかもしれません。

引き続き、書き込みの部分を見ていきます。

func (jl *jsonLogger) Warn(msg string, fields ...Field) {
    jl.log(WarnLevel, msg, fields)
}

func (jl *jsonLogger) log(lvl Level, msg string, fields []Field) {
    ...

    temp := jl.enc.Clone()
    if err := temp.AddFields(fields); err != nil {
        jl.internalError(err.Error())
    }

    ...

    if err := temp.WriteMessage(jl.w, lvl.String(), msg, now); err != nil {
        jl.internalError(err.Error())
    }
    temp.Free()

    ...
}

func (enc *jsonEncoder) Clone() encoder {
    clone := newJSONEncoder()
    clone.bytes = append(clone.bytes, enc.bytes...)
    return clone
}

jsonLogger.logの中で、最初に確保したEncoderをCloneしてもう一つのEncoderを確保しています。これはjl.encがWithで添付された共通のフィールドを保持している為です。AddFieldsに関しては単純に、enc.bytesに、JSONに対応する値をappendしたり文字のエスケープを行っている関数です。簡単な例だけ紹介しておくと、

func (enc *jsonEncoder) AddBool(key string, val bool) {
    enc.addKey(key)
    if val {
        enc.bytes = append(enc.bytes, "true"...)
        return
    }
    enc.bytes = append(enc.bytes, "false"...)
}

このように、各データ型に対してJSON文字列をどんどん詰めていきます。

func (enc *jsonEncoder) WriteMessage(sink io.Writer, lvl string, msg string, ts time.Time) error {
    final := newJSONEncoder()
    defer final.Free()

    final.bytes = append(final.bytes, `{"msg":"`...)
    final.safeAddString(msg)
    final.bytes = append(final.bytes, `","level":"`...)
    final.bytes = append(final.bytes, lvl...)
    final.bytes = append(final.bytes, `","ts":`...)
    final.bytes = strconv.AppendInt(final.bytes, ts.UnixNano(), 10)
    final.bytes = append(final.bytes, `,"fields":{`...)
    final.bytes = append(final.bytes, enc.bytes...)
    final.bytes = append(final.bytes, "}}\n"...)

    n, err := sink.Write(final.bytes)
    if err != nil {
        return err
    }
    if n != len(final.bytes) {
        return fmt.Errorf("incomplete write: only wrote %v of %v bytes", n, len(final.bytes))
    }
    return nil
}

func (enc *jsonEncoder) Free() {
    jsonPool.Put(enc)
}

WriteMessageで最終的な出力用のJSONを構築するためのEncoderを取得し、JSONを組み立ててio.Writerに書き込みます。使用済みのEncoderはFreeでFreeListに返します。

結構処理を省いていますが、ログを出力する部分の基本的な流れはこんな所でしょうか。