uber-go/zap の NewProductionConfig() では、ログのサンプリングがデフォルトで有効になっている

はじめに

Go のアプリケーションにおいて一部のログが想定より出力されていない事象があり、調査する中でこの記事の内容を知りました。

uber-go/zap におけるログのサンプリングについて

ログのサンプリングに関しては、FAQ に下記のような記載があります。

zap/FAQ.md at master · uber-go/zap

Why are some of my logs missing?
Logs are dropped intentionally by zap when sampling is enabled. The production configuration (as returned by NewProductionConfig() enables sampling which will cause repeated logs within a second to be sampled.

ログのサンプリングが有効になっている理由も記載されていて、アプリケーションによる同じようなエントリーのログ出力によって CPU, I/O を消費することを避けるためということが書かれています。

Why sample application logs?
Applications often experience runs of errors, either because of a bug or because of a misbehaving user. Logging errors is usually a good idea, but it can easily make this bad situation worse: not only is your application coping with a flood of errors, it's also spending extra CPU cycles and I/O logging those errors. Since writes are typically serialized, logging limits throughput when you need it most.
Sampling fixes this problem by dropping repetitive log entries. Under normal conditions, your application writes out every entry. When similar entries are logged hundreds or thousands of times each second, though, zap begins dropping duplicates to preserve throughput.

サンプリング用の config は SamplingConfig という構造体で設定を持っています。

https://github.com/uber-go/zap/blob/f463774cec89a976ec7b62be746d7a8e8e21f81d/config.go#L39-L43

NewProductionConfig() では、Initial = 100, Thereafter = 100がセットされた SamplingConfig が渡されます。

https://github.com/uber-go/zap/blob/f463774cec89a976ec7b62be746d7a8e8e21f81d/config.go#L157-L170

サンプリングの挙動としては、config_test.goにあるテストケースが参考になりそうです。
テストケースの中では 3 件のログと同一のログを 200 回出力して、103 件のログが出力される想定になっています。

https://github.com/uber-go/zap/blob/f463774cec89a976ec7b62be746d7a8e8e21f81d/config_test.go#L34-L86

expectN: 2 + 100 + 1, // 2 from initial logs, 100 initial sampled logs, 1 from off-by-one in sampler

サンプリングの実装について

サンプリングの処理は zapcore/sampler.go において実装されています。

https://github.com/uber-go/zap/blob/master/zapcore/sampler.go

NewProductionConfig()を利用する場合は、下記のように config の構造体を生成して Build() を呼び出すことで logger を生成しています。

config := zap.NewProductionConfig()
config.OutputPaths = []string{"stdout"}
logger, err := config.Build()

Build()の内部処理的には、buildOptions(errSink zapcore.WriteSyncer)が呼び出されています。

https://github.com/uber-go/zap/blob/f463774cec89a976ec7b62be746d7a8e8e21f81d/config.go#L283-L297

config.Sampling = nilのようにサンプリングが無効化されていない場合は、zapcore.NewSamplerWithOptions(core Core, tick time.Duration, first, thereafter int, opts ...SamplerOption)に設定値が渡されます。

https://github.com/uber-go/zap/blob/f463774cec89a976ec7b62be746d7a8e8e21f81d/zapcore/sampler.go#L152-L166

NewSamplerWithOptions(core Core, tick time.Duration, first, thereafter int, opts ...SamplerOption)のコメントにもサンプリングの挙動が記載されています。

同じレベルとメッセージを持つ最初の $(Initial) 個のエントリを毎秒取得し、その後の同じレベルとメッセージを持つエントリの中から $(Thereafter) 番目のエントリを取得し、残りのエントリを破棄するという挙動になっています。

Zap samples by logging the first N entries with a given level and message each tick. If more Entries with the same level and message are seen during the same interval, every Mth message is logged and the rest are dropped.

サンプリングのために各ログエントリをチェックする処理は Check(ent Entry, ce *CheckedEntry) で実装されていて、前述の通りログレベルとメッセージを見て同一のログの件数を counter で保持しています。

ログを drop する場合は、s.hook(ent, LogDropped)で config で渡すことのできる hook となる関数が実行され、新規のエントリではなくチェック済みのエントリのみを返しています。

https://github.com/uber-go/zap/blob/f463774cec89a976ec7b62be746d7a8e8e21f81d/zapcore/sampler.go#L214-L229