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..eb31e695b 100644 --- a/logger_test.go +++ b/logger_test.go @@ -124,20 +124,65 @@ 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("") + 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.") + }) + }) + } +} - 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 TestLoggerWithDeferred(t *testing.T) { + 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")).With(String("three", "four")).Info("") + logger.Info("") + + assert.Equal(t, []observer.LoggedEntry{ + {Context: []Field{Int("foo", 42), String("one", "two"), 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..81ea21163 --- /dev/null +++ b/zapcore/deferred_with.go @@ -0,0 +1,82 @@ +// 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...) + d.fields = allFields + 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) +}