From 7ffacf597e4fd27232891656531e6c07220e3cfc Mon Sep 17 00:00:00 2001 From: Jeremy Quirke Date: Sun, 13 Aug 2023 18:19:18 -0700 Subject: [PATCH] Add option to defer With composition to first log One common performance problem we see is that Loggers and their children may be composed with one or more With() invocations, but the logger/s is/are not used in most invocations of the function. For example, an author might initialise a logger with some function-scoped contexttual information at the start of a function: ``` l := logger.With(zap.String("tripID", trip.ID)) ``` but never use 'l' except in seldom taken branches. However, in the majority cases the expensive with operation has been performed which can result in the wasted effort (in terms of alloc, CPU) of cloning (e.g of the JSON encoder). This commit adds a new option, DeferWith which defers all of this expense until the time of first use. This creates considerable performance improvement in the non error path at the slight expense of performance in the first-use path over the existing implementation: ``` % go test -bench=Benchmark5Withs goos: darwin goarch: arm64 pkg: go.uber.org/zap Benchmark5WithsUsed-10 495187 2463 ns/op Benchmark5WithsNotUsed-10 530983 2379 ns/op Benchmark5WithsDeferredUsed-10 956476 1161 ns/op Benchmark5WithsDeferredNotUsed-10 2602353 462.9 ns/op ``` Furthermore, one core microservice in Uber has seen a reduction of 10% heap allocation by simply using this option. --- exp/go.sum | 2 - logger.go | 6 +++ logger_bench_test.go | 40 +++++++++++++++++++- logger_test.go | 43 ++++++++++++++------- options.go | 8 ++++ zapcore/deferred_with.go | 81 ++++++++++++++++++++++++++++++++++++++++ 6 files changed, 163 insertions(+), 17 deletions(-) create mode 100644 zapcore/deferred_with.go diff --git a/exp/go.sum b/exp/go.sum index 9df6ac4b4..7e0c3e06e 100644 --- a/exp/go.sum +++ b/exp/go.sum @@ -19,8 +19,6 @@ go.uber.org/multierr v1.10.0 h1:S0h4aNzvfcFsC3dRF1jLoaov7oRaKqRGC/pUEJ2yvPQ= go.uber.org/multierr v1.10.0/go.mod h1:20+QtiLqy0Nd6FdQB9TLXag12DsQkrbs3htMFfDN80Y= go.uber.org/zap v1.24.0 h1:FiJd5l1UOLj0wCgbSE0rwwXHzEdAZS6hiiSnxJN/D60= go.uber.org/zap v1.24.0/go.mod h1:2kMP+WWQ8aoFoedH3T2sq6iJ2yDWpHbP0f6MQbS9Gkg= -golang.org/x/exp v0.0.0-20230425010034-47ecfdc1ba53 h1:5llv2sWeaMSnA3w2kS57ouQQ4pudlXrR0dCgw51QK9o= -golang.org/x/exp v0.0.0-20230425010034-47ecfdc1ba53/go.mod h1:V1LtkGg67GoY2N1AnLN78QLrzxkLyJw7RJb1gzOOz9w= golang.org/x/exp v0.0.0-20230801115018-d63ba01acd4b h1:r+vk0EmXNmekl0S0BascoeeoHk/L7wmaW2QF90K+kYI= golang.org/x/exp v0.0.0-20230801115018-d63ba01acd4b/go.mod h1:FXUEEKJgO7OQYeo8N01OfiKP8RXMtf6e8aTskBGqWdc= gopkg.in/check.v1 v0.0.0-20161208181325-20d25e280405 h1:yhCVgyC4o1eVCa2tZl7eS0r+SDo693bJlVdllGtEeKM= diff --git a/logger.go b/logger.go index 0e9548011..8bf9ce07e 100644 --- a/logger.go +++ b/logger.go @@ -40,6 +40,7 @@ import ( type Logger struct { core zapcore.Core + deferWith bool development bool addCaller bool onFatal zapcore.CheckWriteHook // default is WriteThenFatal @@ -178,6 +179,11 @@ func (log *Logger) With(fields ...Field) *Logger { if len(fields) == 0 { return log } + if log.deferWith { + l := log.clone() + l.core = zapcore.NewDeferredWith(log.core, fields) + return l + } l := log.clone() l.core = l.core.With(fields) return l diff --git a/logger_bench_test.go b/logger_bench_test.go index bcf501a3f..06bf2e0e7 100644 --- a/logger_bench_test.go +++ b/logger_bench_test.go @@ -51,12 +51,16 @@ var _jane = &user{ } func withBenchedLogger(b *testing.B, f func(*Logger)) { + withOptionedLogger(b, f) +} + +func withOptionedLogger(b *testing.B, f func(*Logger), opts ...Option) { logger := New( zapcore.NewCore( zapcore.NewJSONEncoder(NewProductionConfig().EncoderConfig), &ztest.Discarder{}, DebugLevel, - )) + ), opts...) b.ResetTimer() b.RunParallel(func(pb *testing.PB) { for pb.Next() { @@ -216,6 +220,40 @@ func Benchmark10Fields(b *testing.B) { }) } +func Benchmark5WithsUsed(b *testing.B) { + withBenchedLogger(b, func(log *Logger) { + make5chainedLoggers(log).Info("used") + }) +} + +func Benchmark5WithsNotUsed(b *testing.B) { + withBenchedLogger(b, func(log *Logger) { + l := make5chainedLoggers(log) + runtime.KeepAlive(l) + }) +} + +func Benchmark5WithsDeferredUsed(b *testing.B) { + withOptionedLogger(b, func(log *Logger) { + make5chainedLoggers(log).Info("used") + }, DeferWith()) +} + +func Benchmark5WithsDeferredNotUsed(b *testing.B) { + withOptionedLogger(b, func(log *Logger) { + l := make5chainedLoggers(log) + runtime.KeepAlive(l) + }, DeferWith()) +} + +func make5chainedLoggers(log *Logger) *Logger { + return log.With(String("k1", "v1")). + With(String("k2", "v2")). + With(String("k3", "v3")). + With(String("k4", "v4")). + With(String("k5", "v5")) +} + func Benchmark100Fields(b *testing.B) { const batchSize = 50 logger := New(zapcore.NewCore( diff --git a/logger_test.go b/logger_test.go index d4af57512..cf1a216bd 100644 --- a/logger_test.go +++ b/logger_test.go @@ -124,20 +124,35 @@ func TestLoggerInitialFields(t *testing.T) { } func TestLoggerWith(t *testing.T) { - fieldOpts := opts(Fields(Int("foo", 42))) - withLogger(t, DebugLevel, fieldOpts, func(logger *Logger, logs *observer.ObservedLogs) { - // Child loggers should have copy-on-write semantics, so two children - // shouldn't stomp on each other's fields or affect the parent's fields. - logger.With(String("one", "two")).Info("") - logger.With(String("three", "four")).Info("") - logger.Info("") - - assert.Equal(t, []observer.LoggedEntry{ - {Context: []Field{Int("foo", 42), String("one", "two")}}, - {Context: []Field{Int("foo", 42), String("three", "four")}}, - {Context: []Field{Int("foo", 42)}}, - }, logs.AllUntimed(), "Unexpected cross-talk between child loggers.") - }) + for _, tt := range []struct { + name string + opts []Option + }{ + { + "regular non deferred logger", + []Option{Fields(Int("foo", 42))}, + }, + { + "deferred logger", + []Option{Fields(Int("foo", 42)), DeferWith()}, + }, + } { + t.Run(tt.name, func(t *testing.T) { + withLogger(t, DebugLevel, tt.opts, func(logger *Logger, logs *observer.ObservedLogs) { + // Child loggers should have copy-on-write semantics, so two children + // shouldn't stomp on each other's fields or affect the parent's fields. + logger.With(String("one", "two")).Info("") + logger.With(String("three", "four")).Info("") + logger.Info("") + + assert.Equal(t, []observer.LoggedEntry{ + {Context: []Field{Int("foo", 42), String("one", "two")}}, + {Context: []Field{Int("foo", 42), String("three", "four")}}, + {Context: []Field{Int("foo", 42)}}, + }, logs.AllUntimed(), "Unexpected cross-talk between child loggers.") + }) + }) + } } func TestLoggerLogPanic(t *testing.T) { diff --git a/options.go b/options.go index c4f3bca3d..654d161c1 100644 --- a/options.go +++ b/options.go @@ -132,6 +132,14 @@ func IncreaseLevel(lvl zapcore.LevelEnabler) Option { }) } +// DeferWith defers any With operation unless the logger is actually +// used to emit a log. This can save heap allocation and CPU +func DeferWith() Option { + return optionFunc(func(log *Logger) { + log.deferWith = true + }) +} + // OnFatal sets the action to take on fatal logs. // // Deprecated: Use [WithFatalHook] instead. diff --git a/zapcore/deferred_with.go b/zapcore/deferred_with.go new file mode 100644 index 000000000..f6c5a1570 --- /dev/null +++ b/zapcore/deferred_with.go @@ -0,0 +1,81 @@ +// Copyright (c) 2023 Uber Technologies, Inc. +// +// Permission is hereby granted, free of charge, to any person obtaining a copy +// of this software and associated documentation files (the "Software"), to deal +// in the Software without restriction, including without limitation the rights +// to use, copy, modify, merge, publish, distribute, sublicense, and/or sell +// copies of the Software, and to permit persons to whom the Software is +// furnished to do so, subject to the following conditions: +// +// The above copyright notice and this permission notice shall be included in +// all copies or substantial portions of the Software. +// +// THE SOFTWARE IS PROVIDED "AS IS", WITHOUT WARRANTY OF ANY KIND, EXPRESS OR +// IMPLIED, INCLUDING BUT NOT LIMITED TO THE WARRANTIES OF MERCHANTABILITY, +// FITNESS FOR A PARTICULAR PURPOSE AND NONINFRINGEMENT. IN NO EVENT SHALL THE +// AUTHORS OR COPYRIGHT HOLDERS BE LIABLE FOR ANY CLAIM, DAMAGES OR OTHER +// LIABILITY, WHETHER IN AN ACTION OF CONTRACT, TORT OR OTHERWISE, ARISING FROM, +// OUT OF OR IN CONNECTION WITH THE SOFTWARE OR THE USE OR OTHER DEALINGS IN +// THE SOFTWARE. + +package zapcore + +import "sync" + +type deferredWithCore struct { + Core + sync.Once + fields []Field +} + +var ( + _ Core = (*deferredWithCore)(nil) + _ leveledEnabler = (*deferredWithCore)(nil) +) + +// NewDeferredWith wraps a Core with a "lazy" core that will. +// only execute With operations if the logger is actually used +func NewDeferredWith(core Core, fields []Field) Core { + return &deferredWithCore{ + Core: core, + fields: fields, + } +} + +func (d *deferredWithCore) initOnce() { + d.Once.Do(func() { + d.Core = d.Core.With(d.fields) + }) +} + +func (d *deferredWithCore) With(fields []Field) Core { + allFields := make([]Field, 0, len(fields)+len(d.fields)) + allFields = append(allFields, d.fields...) + allFields = append(allFields, fields...) + return d +} + +func (d *deferredWithCore) Check(e Entry, ce *CheckedEntry) *CheckedEntry { + d.initOnce() + return d.Core.Check(e, ce) +} + +func (d *deferredWithCore) Write(e Entry, fields []Field) error { + d.initOnce() + return d.Core.Write(e, fields) +} + +func (d *deferredWithCore) Sync() error { + d.initOnce() + return d.Core.Sync() +} + +func (d *deferredWithCore) Enabled(l Level) bool { + d.initOnce() + return d.Core.Enabled(l) +} + +func (d *deferredWithCore) Level() Level { + d.initOnce() + return LevelOf(d.Core) +}