From f60080437285e33cdafd10f241df19fc49e56c79 Mon Sep 17 00:00:00 2001 From: Jeremy Quirke Date: Sun, 13 Aug 2023 18:19:18 -0700 Subject: [PATCH] Add WithLazy Logger method 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 method on Logger, WithLazy, 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. 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 WithLazy is called. Additionally, cases such as logging objects where the object is modified between the WithLazy 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.go | 17 +++++ logger_bench_test.go | 19 ++++- logger_test.go | 153 +++++++++++++++++++++++++++----------- zapcore/lazy_with.go | 54 ++++++++++++++ zapcore/lazy_with_test.go | 149 +++++++++++++++++++++++++++++++++++++ 5 files changed, 343 insertions(+), 49 deletions(-) create mode 100644 zapcore/lazy_with.go create mode 100644 zapcore/lazy_with_test.go diff --git a/logger.go b/logger.go index 9b45b07b0..475a4801e 100644 --- a/logger.go +++ b/logger.go @@ -184,6 +184,23 @@ func (log *Logger) With(fields ...Field) *Logger { return l } +// WithLazy creates a child logger and lazily encodes structured context if the +// child logger is ever further chained with With() or is written to with any +// of the log level methods. Until the occurs, the logger may retain references +// to references in objects, etc, and logging will reflect the state of an object +// at the time of logging, not the time of WithLazy(). 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). +// Fields added to the child don't affect the parent, and vice versa. +func (log *Logger) WithLazy(fields ...Field) *Logger { + if len(fields) == 0 { + return log + } + return log.WithOptions(WrapCore(func(core zapcore.Core) zapcore.Core { + return zapcore.NewLazyWith(core, fields) + })) +} + // Level reports the minimum enabled level for this logger. // // For NopLoggers, this is [zapcore.InvalidLevel]. diff --git a/logger_bench_test.go b/logger_bench_test.go index c7207afd5..431cce529 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, (*Logger).With, 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, (*Logger).With, 5, false) +} + +func Benchmark5WithLazysUsed(b *testing.B) { + benchmarkWithUsed(b, (*Logger).WithLazy, 5, true) +} + +// This benchmark will be used in future as a +// baseline for improving +func Benchmark5WithLazysNotUsed(b *testing.B) { + benchmarkWithUsed(b, (*Logger).WithLazy, 5, false) } -func benchmarkWithUsed(b *testing.B, N int, use bool) { +func benchmarkWithUsed(b *testing.B, withMethodExpr func(*Logger, ...zapcore.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 = withMethodExpr(log, String(keys[i], values[i])) } if use { log.Info("used") diff --git a/logger_test.go b/logger_test.go index 5b1d77b97..890280b2f 100644 --- a/logger_test.go +++ b/logger_test.go @@ -124,58 +124,121 @@ 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 + initialFields []Field + withMethodExpr func(*Logger, ...Field) *Logger + }{ + { + "regular non lazy logger", + []Field{Int("foo", 42)}, + (*Logger).With, + }, + { + "regular non lazy logger no initial fields", + []Field{}, + (*Logger).With, + }, + { + "lazy with logger", + []Field{Int("foo", 42)}, + (*Logger).WithLazy, + }, + { + "lazy with logger no initial fields", + []Field{}, + (*Logger).WithLazy, + }, + } { + t.Run(tt.name, func(t *testing.T) { + withLogger(t, DebugLevel, opts(Fields(tt.initialFields...)), 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.withMethodExpr(logger).Info("") + tt.withMethodExpr(logger, String("one", "two")).Info("") + tt.withMethodExpr(logger, String("three", "four")).Info("") + tt.withMethodExpr(logger, String("five", "six")).With(String("seven", "eight")).Info("") + logger.Info("") + + assert.Equal(t, []observer.LoggedEntry{ + {Context: tt.initialFields}, + {Context: append(tt.initialFields, String("one", "two"))}, + {Context: append(tt.initialFields, String("three", "four"))}, + {Context: append(tt.initialFields, String("five", "six"), String("seven", "eight"))}, + {Context: tt.initialFields}, + }, 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 + withMethodExpr func(*Logger, ...Field) *Logger + wantJSON [2]string + }{ + { + name: "regular with captures arguments at time of With", + withMethodExpr: (*Logger).With, + wantJSON: [2]string{ + `{ + "m": "hello", + "a": [0], + "b": [1] + }`, + `{ + "m": "world", + "a": [0], + "c": [2] + }`, + }, + }, + { + name: "lazy with captures arguments at time of With or Logging", + withMethodExpr: (*Logger).WithLazy, + 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.withMethodExpr(logger, Array("a", arr)) + x = 1 + logger.Info("hello", Array("b", arr)) + x = 2 + logger = tt.withMethodExpr(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/zapcore/lazy_with.go b/zapcore/lazy_with.go new file mode 100644 index 000000000..05288d6a8 --- /dev/null +++ b/zapcore/lazy_with.go @@ -0,0 +1,54 @@ +// 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 +} + +// NewLazyWith wraps a Core with a "lazy" Core 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) +} diff --git a/zapcore/lazy_with_test.go b/zapcore/lazy_with_test.go new file mode 100644 index 000000000..fca16f36f --- /dev/null +++ b/zapcore/lazy_with_test.go @@ -0,0 +1,149 @@ +// 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_test + +import ( + "sync/atomic" + "testing" + + "github.com/stretchr/testify/assert" + "go.uber.org/zap/zapcore" + "go.uber.org/zap/zaptest/observer" +) + +type proxyCore struct { + zapcore.Core + + withCount atomic.Int64 + checkCount atomic.Int64 +} + +func newProxyCore(inner zapcore.Core) *proxyCore { + return &proxyCore{Core: inner} +} + +func (p *proxyCore) With(fields []zapcore.Field) zapcore.Core { + p.withCount.Add(1) + return p.Core.With(fields) +} + +func (p *proxyCore) Check(e zapcore.Entry, ce *zapcore.CheckedEntry) *zapcore.CheckedEntry { + p.checkCount.Add(1) + return p.Core.Check(e, ce) +} + +func withLazyCore(f func(zapcore.Core, *proxyCore, *observer.ObservedLogs), initialFields ...zapcore.Field) { + infoLogger, infoLogs := observer.New(zapcore.InfoLevel) + proxyCore := newProxyCore(infoLogger) + lazyCore := zapcore.NewLazyWith(proxyCore, initialFields) + f(lazyCore, proxyCore, infoLogs) +} + +func TestLazyCore(t *testing.T) { + for _, tt := range []struct { + name string + entries []zapcore.Entry + initialFields []zapcore.Field + withChains [][]zapcore.Field + wantLogs []observer.LoggedEntry + }{ + { + name: "no logging, no with, inner core with never called, inner core check never called", + wantLogs: []observer.LoggedEntry{}, + }, + { + name: "2 logs, 1 dropped, no with, inner core with called once, inner core check never called", + entries: []zapcore.Entry{ + {Level: zapcore.DebugLevel, Message: "log-at-debug"}, + {Level: zapcore.WarnLevel, Message: "log-at-warn"}, + }, + wantLogs: []observer.LoggedEntry{ + {Entry: zapcore.Entry{ + Level: zapcore.WarnLevel, + Message: "log-at-warn"}, + Context: []zapcore.Field{}, + }, + }, + }, + { + name: "no logs, 2-chained with, inner core with called once, inner core check never called", + withChains: [][]zapcore.Field{ + {makeInt64Field("a", 11), makeInt64Field("b", 22)}, + {makeInt64Field("c", 33), makeInt64Field("d", 44)}, + }, + wantLogs: []observer.LoggedEntry{}, + }, + { + name: "2 logs, 1 dropped, 2-chained with, inner core with called once, inner core check never called", + entries: []zapcore.Entry{ + {Level: zapcore.DebugLevel, Message: "log-at-debug"}, + {Level: zapcore.WarnLevel, Message: "log-at-warn"}, + }, + withChains: [][]zapcore.Field{ + {makeInt64Field("a", 11), makeInt64Field("b", 22)}, + {makeInt64Field("c", 33), makeInt64Field("d", 44)}, + }, + wantLogs: []observer.LoggedEntry{ + {Entry: zapcore.Entry{ + Level: zapcore.WarnLevel, + Message: "log-at-warn"}, + Context: []zapcore.Field{ + makeInt64Field("a", 11), + makeInt64Field("b", 22), + makeInt64Field("c", 33), + makeInt64Field("d", 44), + }, + }, + }, + }, + } { + t.Run(tt.name, func(t *testing.T) { + withLazyCore(func(lazy zapcore.Core, proxy *proxyCore, logs *observer.ObservedLogs) { + checkCounts := func(withCount int64, msg string) { + assert.Equal(t, withCount, proxy.withCount.Load(), msg) + } + checkCounts(0, "expected no with calls because the logger is not used yet") + + for _, chain := range tt.withChains { + lazy = lazy.With(chain) + } + if len(tt.withChains) > 0 { + checkCounts(1, "expected with calls because the logger was with-chained") + } else { + checkCounts(0, "expected no with calls because the logger is not used yet") + } + + for _, ent := range tt.entries { + if ce := lazy.Check(ent, nil); ce != nil { + ce.Write() + } + } + if len(tt.entries) > 0 || len(tt.withChains) > 0 { + checkCounts(1, "expected with calls because the logger had entries or with chains") + } else { + checkCounts(0, "expected no with calls because the logger is not used yet") + } + assert.Zero(t, proxy.checkCount.Load(), "expected no check calls because the inner core is copied") + assert.Equal(t, tt.wantLogs, logs.AllUntimed()) + }, tt.initialFields...) + }) + } +}