Add LazyFields Logger option

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, LazyFields, which defers all of this expense
until the time of first use. This creates considerable performance improvement
for the cases where a logger is not regularly used. The above example would
therefore now be written as:

```
l := logger.WithOptions(LazyFields(zap.String("tripID", trip.ID)))
```

This does require an explicit opt in, because the author must be aware there
is the possibility of objects living longer than the scope of the method
wherein LazyFields is used. Additionally, cases such as logging objects where
the object is modified between the LazyFields and logging that will reflect
the state of the field at log time, rather than With time, which is something
authors need to be aware of.

```
 % go test -bench=Benchmark5With
goos: darwin
goarch: arm64
pkg: go.uber.org/zap/exp/lazylogger
Benchmark5WithsUsed-10           	  527385	      2390 ns/op
Benchmark5WithsNotUsed-10        	  563468	      2246 ns/op
Benchmark5WithLazysUsed-10       	  475064	      2642 ns/op
Benchmark5WithLazysNotUsed-10    	 2255786	       527.4 ns/op
PASS
```

Furthermore, one core microservice in Uber has seen a reduction of 10% heap
allocation by simply using this feature.

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")

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.")
+			}
+		})
 	}
 }
 

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,

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)
+}