diff --git a/logger_bench_test.go b/logger_bench_test.go index c7207afd5..9bc941fff 100644 --- a/logger_bench_test.go +++ b/logger_bench_test.go @@ -199,17 +199,28 @@ func BenchmarkAddCallerAndStacktrace(b *testing.B) { } }) } + func Benchmark5WithsUsed(b *testing.B) { - benchmarkWithUsed(b, 5, true) + benchmarkWithUsed(b, func(l *Logger, fields ...Field) *Logger { return l.With(fields...) }, 5, true) } // This benchmark will be used in future as a // baseline for improving func Benchmark5WithsNotUsed(b *testing.B) { - benchmarkWithUsed(b, 5, false) + benchmarkWithUsed(b, func(l *Logger, fields ...Field) *Logger { return l.With(fields...) }, 5, false) +} + +func Benchmark5WithLazysUsed(b *testing.B) { + benchmarkWithUsed(b, func(l *Logger, fields ...Field) *Logger { return l.WithOptions(LazyFields(fields...)) }, 5, true) +} + +// This benchmark will be used in future as a +// baseline for improving +func Benchmark5WithLazysNotUsed(b *testing.B) { + benchmarkWithUsed(b, func(l *Logger, fields ...Field) *Logger { return l.WithOptions(LazyFields(fields...)) }, 5, false) } -func benchmarkWithUsed(b *testing.B, N int, use bool) { +func benchmarkWithUsed(b *testing.B, loggerDecorator func(*Logger, ...Field) *Logger, N int, use bool) { keys := make([]string, N) values := make([]string, N) for i := 0; i < N; i++ { @@ -221,7 +232,7 @@ func benchmarkWithUsed(b *testing.B, N int, use bool) { withBenchedLogger(b, func(log *Logger) { for i := 0; i < N; i++ { - log = log.With(String(keys[i], values[i])) + log = loggerDecorator(log, String(keys[i], values[i])) } if use { log.Info("used") diff --git a/logger_test.go b/logger_test.go index 5b1d77b97..ee8d2ff58 100644 --- a/logger_test.go +++ b/logger_test.go @@ -125,57 +125,105 @@ 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.With(String("five", "six")).With(String("seven", "eight")).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), String("five", "six"), String("seven", "eight")}}, - {Context: []Field{Int("foo", 42)}}, - }, logs.AllUntimed(), "Unexpected cross-talk between child loggers.") - }) + for _, tt := range []struct { + name string + loggerDecorator func(*Logger, ...Field) *Logger + }{ + { + "regular non lazy logger", + func(l *Logger, fields ...Field) *Logger { return l.With(fields...) }, + }, + { + "lazy field logger", + func(l *Logger, fields ...Field) *Logger { return l.WithOptions(LazyFields(fields...)) }, + }, + } { + t.Run(tt.name, func(t *testing.T) { + 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. + tt.loggerDecorator(logger, String("one", "two")).Info("") + tt.loggerDecorator(logger, String("three", "four")).Info("") + tt.loggerDecorator(logger, String("five", "six")).With(String("seven", "eight")).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), String("five", "six"), String("seven", "eight")}}, + {Context: []Field{Int("foo", 42)}}, + }, logs.AllUntimed(), "Unexpected cross-talk between child loggers.") + }) + }) + } } func TestLoggerWithCaptures(t *testing.T) { - enc := zapcore.NewJSONEncoder(zapcore.EncoderConfig{ - MessageKey: "m", - }) + for _, tt := range []struct { + name string + loggerDecorator func(*Logger, ...Field) *Logger + wantJSON [2]string + }{ + { + name: "regular with captures arguments at time of With", + loggerDecorator: func(l *Logger, fields ...Field) *Logger { return l.With(fields...) }, + wantJSON: [2]string{ + `{ + "m": "hello", + "a": [0], + "b": [1] + }`, + `{ + "m": "world", + "a": [0], + "c": [2] + }`, + }, + }, + { + name: "lazy fields logger captures arguments at time of next With or Logging operation", + loggerDecorator: func(l *Logger, fields ...Field) *Logger { return l.WithOptions(LazyFields(fields...)) }, + wantJSON: [2]string{ + `{ + "m": "hello", + "a": [1], + "b": [1] + }`, + `{ + "m": "world", + "a": [1], + "c": [2] + }`, + }, + }, + } { + t.Run(tt.name, func(t *testing.T) { + enc := zapcore.NewJSONEncoder(zapcore.EncoderConfig{ + MessageKey: "m", + }) - var bs ztest.Buffer - logger := New(zapcore.NewCore(enc, &bs, DebugLevel)) + var bs ztest.Buffer + logger := New(zapcore.NewCore(enc, &bs, DebugLevel)) - x := 0 - arr := zapcore.ArrayMarshalerFunc(func(enc zapcore.ArrayEncoder) error { - enc.AppendInt(x) - return nil - }) + x := 0 + arr := zapcore.ArrayMarshalerFunc(func(enc zapcore.ArrayEncoder) error { + enc.AppendInt(x) + return nil + }) - // Demonstrate the arguments are captured when With() and Info() are invoked. - logger = logger.With(Array("a", arr)) - x = 1 - logger.Info("hello", Array("b", arr)) - x = 2 - logger = logger.With(Array("c", arr)) - logger.Info("world") - - if lines := bs.Lines(); assert.Len(t, lines, 2) { - assert.JSONEq(t, `{ - "m": "hello", - "a": [0], - "b": [1] - }`, lines[0], "Unexpected output from first log.") - - assert.JSONEq(t, `{ - "m": "world", - "a": [0], - "c": [2] - }`, lines[1], "Unexpected output from second log.") + // Demonstrate the arguments are captured when With() and Info() are invoked. + logger = tt.loggerDecorator(logger, Array("a", arr)) + x = 1 + logger.Info("hello", Array("b", arr)) + x = 2 + logger = tt.loggerDecorator(logger, Array("c", arr)) + logger.Info("world") + + if lines := bs.Lines(); assert.Len(t, lines, 2) { + assert.JSONEq(t, tt.wantJSON[0], lines[0], "Unexpected output from first log.") + assert.JSONEq(t, tt.wantJSON[1], lines[1], "Unexpected output from second log.") + } + }) } } diff --git a/options.go b/options.go index c4f3bca3d..f16e973a9 100644 --- a/options.go +++ b/options.go @@ -65,6 +65,22 @@ func Fields(fs ...Field) Option { }) } +// LazyFields add fields to the Logger to be evaluated at logging time. +// Until the actual logging occurs, the logger may retain references +// to objects, etc, and logging will reflect the state of an object at the time +// of logging, not the time of the WithOptions(LazyFields(...)). +// However, is a worthwhile performance optimisation if one creates a +// contextual logger and the likelihood of using it is low (e.g. in error or +// rarely taken branches). +func LazyFields(fields ...Field) Option { + return optionFunc(func(log *Logger) { + if len(fields) == 0 { + return + } + log.core = zapcore.NewLazyWith(log.core, fields) + }) +} + // ErrorOutput sets the destination for errors generated by the Logger. Note // that this option only affects internal errors; for sample code that sends // error-level logs to a different location from info- and debug-level logs, diff --git a/zapcore/lazy_with.go b/zapcore/lazy_with.go new file mode 100644 index 000000000..0c7cce377 --- /dev/null +++ b/zapcore/lazy_with.go @@ -0,0 +1,56 @@ +// 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 lazyWithCore struct { + Core + sync.Once + fields []Field +} + +var _ Core = (*lazyWithCore)(nil) + +// NewLazyWith wraps a Core with a "lazy" ore that will only encode fields if +// the logger is written to (or is further chained in a lon-lazy manner). +func NewLazyWith(core Core, fields []Field) Core { + return &lazyWithCore{ + Core: core, + fields: fields, + } +} + +func (d *lazyWithCore) initOnce() { + d.Once.Do(func() { + d.Core = d.Core.With(d.fields) + }) +} + +func (d *lazyWithCore) With(fields []Field) Core { + d.initOnce() + return d.Core.With(fields) +} + +func (d *lazyWithCore) Check(e Entry, ce *CheckedEntry) *CheckedEntry { + d.initOnce() + return d.Core.Check(e, ce) +}