ロギングライブラリzapの高速化技術とI/Oボトルネック

こんにちは、TalentX バックエンドエンジニアの伊東と申します。 採用MAサービス MyTalentの開発を担当しています。

MyTalentではGo言語を採用しており、ロギングライブラリには zap (go.uber.org/zap) を使用しています。 以前、パフォーマンス問題の調査のため、多数のゴルーチン上でzapでのログ出力をしたところ、そのデバッグログの出力自体がボトルネックとなるという失敗を経験しました。

そこで本記事では、ロギングのパフォーマンスに影響を与える裏側の仕組みを理解することを目的に、zapの高速化技術とI/Oのボトルネックについて分析・解説します。

github.com

発生したパフォーマンス問題

前述のとおり、一部機能の遅延原因を究明するため、開発環境下でzapによるデバッグログを多数のゴルーチンが同時に処理を行うホットパスに大量に挿入しました。しかしそのログ出力がパフォーマンスを低下させ、システムの新たなボトルネックとなり、調べたかったボトルネックが分からなくなってしまいました。

本来、このようなパフォーマンス調査にはpprofなどのプロファイリングツールの利用が適切かと思いますが、この経験から、ログ出力はI/Oを伴う高コストな処理であるということを身をもって学びました。

ここで以下のような疑問が生じ、今回調べることにしました。

• 高速ロギングを謳っているzapでは、どの処理工程をどのように高速化しているのか
• 多数のゴルーチン上ではなぜパフォーマンスが落ちるのか

zap の高速化の仕組み

zapが高速を謳うのは、主にログを書き出すまでのエンコード処理の効率化によるものです。 それに関して、zapのドキュメントには「It includes a reflection-free, zero-allocation JSON encoder ...」とありますが、Reflection-free、Zero-allocationとはどういうことか解説します。

1. Reflection-free（リフレクションフリー）

fmt.Printlnは引数がany型であるため、型をランタイムでreflectパッケージを用いて動的に分析（リフレクション）する必要があります。この処理はCPUコストを伴います。

// fmt
func Println(a ...any) (n int, err error)

zapはこれを回避するため、zap.String(), zap.Int() のように基底型ごとに固有の関数を提供しています。これにより呼び出し時点で型が確定しているため、ランタイムでのリフクレクションによる動的な型判定が不要となります。

// zap
func String(key string, val string) Field
func Int(key string, val int) Field

ただし、zap.Any()を利用する場合にはリフレクションが発生します。そのため、構造体の場合には各フィールドを指定してロギングしたほうが良いです。

ベンチマークによる比較

リフレクションの有無による差を検証するために、zap.Anyを使った場合(A)と、フィールドごとに指定した場合(B)でベンチマークをとって比較しました。

※ Darwin (Apple M3 Pro, arm64)、Go1.24.6環境にて実施。

var testUser = User{ID: 100, Name: "伊東太郎", Email: "taro.itou@example.com"}

// A: zap.Any
func BenchmarkZapAny(b *testing.B) {
    for i := 0; i < b.N; i++ {
        logger.Info("User logged in", zap.Any("user", testUser))
    }
}

// B: フィールドごとに指定
func BenchmarkZapTyped(b *testing.B) {
    for i := 0; i < b.N; i++ {
        logger.Info("User logged in",
            zap.Int("id", testUser.ID),
            zap.String("name", testUser.Name),
            zap.String("email", testUser.Email),
        )
    }
}

go test -bench=.を実行し、下記の結果を得ました。（ns/opは処理時間（ナノ秒）です。） AとBとの割合比較でいうと25%ほど処理が速くなったと言えます。

• zap.Any(A) : 39.66 ns/op
• フィールドごと指定(B) : 28.72 ns/op

2. Zero-allocation（ゼロアロケーション）

zapでは、ログをエンコードするためのバッファをログ呼び出しごとに新規作成するのではなく、sync.Poolから取得して再利用しています。sync.Poolによりヒープアロケーション低減をしているようです。

（以下、zapのソースコードより抜粋）

package zapcore

var _jsonPool = pool.New(func() *jsonEncoder {
    return &jsonEncoder{}
})

package pool

func New[T any](fn func() T) *Pool[T] {
    return &Pool[T]{
        pool: sync.Pool{
            New: func() any {
                return fn()
            },
        },
    }
}

zapが公開しているベンチマークでも見られるように全ての状況でアロケーションがゼロになるわけではないため、Zero-allocationとはこの再利用などの工夫によってアロケーションを減らしている状態を意味するものと思われます。

ベンチマークによる比較

sync.Poolを使用したバッファの再利用による差を検証するために、sync.Poolを使わない場合(A)と、使う場合(B)でベンチマークをとって比較しました。

// A: sync.Poolを使わない場合
func BenchmarkLogWithoutPool(b *testing.B) {
    b.ReportAllocs()
    b.RunParallel(func(pb *testing.PB) {
        for pb.Next() {
            entry := &LogEntry{
                Timestamp: time.Now(),
                Level:     "INFO",
                Message:   "User logged in",
            }

            buf := &bytes.Buffer{}
            json.NewEncoder(buf).Encode(entry)
            dummyOutput.Write(buf.Bytes())
        }
    })
}

// B: sync.Poolを使う場合
func BenchmarkLogWithPool(b *testing.B) {
    bufferPool := &sync.Pool{
        New: func() interface{} {
            return &bytes.Buffer{}
        },
    }

    b.ReportAllocs()
    b.RunParallel(func(pb *testing.PB) {
        for pb.Next() {
            entry := &LogEntry{
                Timestamp: time.Now(),
                Level:     "INFO",
                Message:   "User logged in",
            }

            // バッファをプールから取得
            buf := bufferPool.Get().(*bytes.Buffer)
            buf.Reset()

            json.NewEncoder(buf).Encode(entry)
            dummyOutput.Write(buf.Bytes())

            // バッファをプールに戻す
            bufferPool.Put(buf)
        }
    })
}

go test -bench=.を実行し、下記の結果を得ました。（allocs/opはアロケーションが発生した回数です。） sync.Poolを使うことでアロケーションが減ったことが分かります。

• sync.Poolを使わない場合(A) : 4 allocs/op
• sync.Poolを使う場合(B) : 2 allocs/op

多数ゴルーチンにおけるI/Oボトルネック

前章までの検証により、zapのエンコード処理（JSON化）が高速化されていることがわかりました。しかし、この高速化はログメッセージを書き出すI/Oプロセスにはあまり影響しません。多数のゴルーチンが同時にロギングした際にパフォーマンスが低下した原因はこの書き込みプロセスにあります。

ロック競合による直列化

多数のゴルーチンが同時にロギングを行うと、これらは書き込みロックを奪い合う状態（ロック競合）になってしまいます。結果として、いくらエンコードが速くても書き込み処理はロックによって直列化され、並行処理のメリットが失われます。

ベンチマークによる比較

上記の原因を検証するために、シングルスレッドの場合(A)と、ゴルーチンで並行処理した場合(B)でベンチマークをとって比較しました。

// テスト用のフィールド
var fields = []zap.Field{
    zap.String("method", "GET"),
    zap.String("path", "/api/v1/user/profile"),
    zap.Int("status", 200),
    zap.Duration("duration", time.Millisecond*50),
}

// A. シングルスレッド
func BenchmarkZapSingleThread(b *testing.B) {
    b.ResetTimer()
    for i := 0; i < b.N; i++ {
        // ロギング処理を実行
        logger.Info("Request completed", fields...)
    }
}

// B. 多数ゴルーチン
func BenchmarkZapParallel(b *testing.B) {
    b.ResetTimer()

    // b.RunParallelを実行し、複数のゴルーチンで並行して処理を行う
    b.RunParallel(func(pb *testing.PB) {
        for pb.Next() {
            // 各Goroutineが並行してロギング処理を実行
            logger.Info("Request completed", fields...)
        }
    })
}

go test -bench=.を実行し、下記の結果を得ました。ほぼ同等で、処理速度に関しては並行処理による恩恵が得られていないことが分かります。

• シングルスレッドの場合(A) : 19801 ns/op
• ゴルーチンで並行処理した場合(B) : 19149 ns/op

pprofによるブロッキングプロファイル

また、pprofを使ったプロファイルにより、どのような処理でゴルーチンが待機（ブロッキング）しているのかを確認しました。

$ go test -bench=BenchmarkZapParallel -blockprofile block_prof.out -run=^$ ./...
$ go tool pprof block_prof.out
(pprof) top
       flat  flat%   sum%        cum   cum%
     22.34s 82.80% 82.80%     22.34s 82.80%  sync.(*Mutex).Lock (inline)
      2.32s  8.60% 91.41%      2.32s  8.60%  runtime.chanrecv1
      2.32s  8.59%   100%      2.32s  8.59%  sync.(*WaitGroup).Wait
      （以下略）

上記の結果はゴルーチンで並行処理した場合(B)のものですが、関数が費やした時間を示すflatという項目に着目するとsync.(*Mutex).Lockが22秒（全体の82%の時間）であり、長時間ロックの獲得待ちしていたことが分かります。

解決策

今回はロギングの仕組みを理解することを目的としているためI/O最適化については深く立ち入りませんが、解決策としては下記の選択肢がありそうです。

• ロギングレベルの調整：そもそもログレベルを見直す方針。要件を満たさない場合がある。
• バッファリングの強化：zapcore.BufferedWriteSyncerを使いバッファを確保し、I/Oの頻度を下げる。バッファサイズ分、メモリが占有される。
• 非同期（チャネル利用）：ログメッセージをチャネルに投げて、専用のゴルーチンがロギングする方針。実装が複雑化する。

各選択肢にはそれぞれ上記のようなトレードオフがありますので、闇雲に処理速度を求めるのでなく、必要になった場合に検討し取捨選択することが大事かと思います。

まとめ

本記事では、zapの高速化技術とロギングがI/Oに与える影響を調査・検証しました。普段は意識することがない、ロギングの裏側の仕組みを理解することができました。

これまではロギングをアプリケーションのおまけとして軽視してしまっていた部分もありましたが、今回の調査を通じて、パフォーマンス向上のために徹底して努力されているオープンソース開発者の方々に改めて敬意を持つことができました。

今回は経験した失敗をきっかけに、気になった事柄を調べましたが、今後も単なるミスで終わらせず、果敢な失敗から学びを得る姿勢で開発していきたいと思います。

最後に

最後までお読みいただきありがとうございました。

TalentXでは一緒に働く仲間を募集しております。 ご興味ある方は下記リンクの求人をご覧ください。 talentx.brandmedia.i-myrefer.jp

また、カジュアル面談も行っていますのでぜひご応募ください。 i-myrefer.jp