Go の有名なロギングライブラリ uber-go/zap にて、短時間に同一のログを出力しようとしたときに期待よりも出力される量が少ないことがあった。 具体的には、Webサーバーでアクセスログを出力しているのだが、実際にアクセスされた量よりもログの量が少なかった。
再現
package main
import (
"go.uber.org/zap"
)
func main() {
conf := zap.NewProductionConfig()
conf.OutputPaths = []string{"stdout"}
logger, _ := conf.Build()
for i := 0; i < 150; i++ {
logger.Info("test")
}
}❯ go run ./ | wc -l
100理由
https://github.com/uber-go/zap/blob/master/FAQ.md#why-are-some-of-my-logs-missing に書いてある。 CPU使用量やI/O回数を減らしてパフォーマンスへの影響を減らすためにこうしている。
サンプリングの設定値を変更する
zap.NewProductionConfig() で SamplingConfig{Initial: 100, Thereafter: 100} を渡している。
https://github.com/uber-go/zap/blob/d27427d23f81dba1f048d6034d5f286572049e1e/config.go#L157
ちなみに zap.NewDevelopmentConfig() ではこれが設定されていない気づくのが遅れた。
zap.Config.Sampling をnilにすると設定が無効になる。
package main
import (
"go.uber.org/zap"
)
func main() {
conf := zap.NewProductionConfig()
conf.OutputPaths = []string{"stdout"}
conf.Sampling = nil
logger, _ := conf.Build()
for i := 0; i < 150; i++ {
logger.Info("test")
}
}期待値通りの件数が出力される。
❯ go run ./ | wc -l
150各設定値について
Initial, Thereafter の設定値はそれぞれ次のような意味になる
Initial同一のログレベルとメッセージを持つ最初のN件のエントリは出力するThereafterその後の同一のログレベルとメッセージを持つエントリは、M件おきに出力し残りはドロップする
よって次のようにした場合、最初の50件 + 残りの50件は6件おきとなり合計58件出力される。
func main() {
conf := zap.NewProductionConfig()
conf.OutputPaths = []string{"stdout"}
conf.Sampling.Initial = 50
conf.Sampling.Thereafter = 6
conf.EncoderConfig.EncodeTime = zapcore.RFC3339TimeEncoder
logger, _ := conf.Build()
for i := 0; i < 100; i++ {
logger.Info("test")
}
}❯ go run ./ | wc -l
58その他の設定
他にもサンプリング時に実行されるHookを登録したり、サンプリング間隔(デフォルトは1秒)を変更したりもできる。詳細はgodoc
フィールドの変化は同一のログとみなされる
フィールドを可変にしても、メッセージが同じ場合はサンプリングされる
func main() {
conf := zap.NewProductionConfig()
conf.OutputPaths = []string{"stdout"}
conf.Sampling.Initial = 50
conf.Sampling.Thereafter = 6
conf.EncoderConfig.EncodeTime = zapcore.RFC3339TimeEncoder
logger, _ := conf.Build()
for i := 0; i < 100; i++ {
logger.Info("test", zap.Int("count", i))
}
}⇒ 58件
1秒時間を空けるとリセットされる
func main() {
conf := zap.NewProductionConfig()
conf.OutputPaths = []string{"stdout"}
conf.Sampling.Initial = 50
conf.Sampling.Thereafter = 6
conf.EncoderConfig.EncodeTime = zapcore.RFC3339TimeEncoder
logger, _ := conf.Build()
for i := 0; i < 100; i++ {
logger.Info("test", zap.Int("count", i))
}
time.Sleep(1 * time.Second)
for i := 0; i < 100; i++ {
logger.Info("test", zap.Int("count", i))
}
}⇒ 116件