-
Notifications
You must be signed in to change notification settings - Fork 1.5k
Commit
This commit does not belong to any branch on this repository, and may belong to a fork outside of the repository.
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.
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.
```
% 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 option.- Loading branch information
Showing
6 changed files
with
295 additions
and
8 deletions.
There are no files selected for viewing
This file contains bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
This file contains bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
This file contains bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
| Original file line number | Diff line number | Diff line change |
|---|---|---|
| @@ -0,0 +1,44 @@ | ||
| // Package lazylogger provides an experimental logger that supports | ||
| // lazy with operations | ||
| package lazylogger | ||
|
|
||
| import ( | ||
| "go.uber.org/zap" | ||
| "go.uber.org/zap/zapcore" | ||
| ) | ||
|
|
||
| // LazyLogger is a proposed breaking change to logger that | ||
| // adds a WithLazy method | ||
| type LazyLogger struct { | ||
| *zap.Logger | ||
| } | ||
|
|
||
| // 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. | ||
| // Fields added to the child don't affect the parent, and vice versa. | ||
| func (log *LazyLogger) WithLazy(fields ...zap.Field) *LazyLogger { | ||
| if len(fields) == 0 { | ||
| return log | ||
| } | ||
| return &LazyLogger{ | ||
| log.WithOptions(zap.WrapCore(func(core zapcore.Core) zapcore.Core { | ||
| return zapcore.NewLazyWith(core, fields) | ||
| })), | ||
| } | ||
| } | ||
|
|
||
| // With is for testing in exp package only | ||
| func (log *LazyLogger) With(fields ...zap.Field) *LazyLogger { | ||
| return &LazyLogger{ | ||
| log.Logger.With(fields...), | ||
| } | ||
| } | ||
|
|
||
| // New is for testing in exp package only | ||
| func New(core zapcore.Core, options ...zap.Option) *LazyLogger { | ||
| return &LazyLogger{ | ||
| zap.New(core, options...), | ||
| } | ||
| } |
This file contains bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
| Original file line number | Diff line number | Diff line change |
|---|---|---|
| @@ -0,0 +1,64 @@ | ||
| package lazylogger | ||
|
|
||
| import ( | ||
| "runtime" | ||
| "strconv" | ||
| "testing" | ||
|
|
||
| "go.uber.org/zap" | ||
| "go.uber.org/zap/internal/ztest" | ||
| "go.uber.org/zap/zapcore" | ||
| ) | ||
|
|
||
| func Benchmark5WithsUsed(b *testing.B) { | ||
| benchmarkWithUsed(b, (*LazyLogger).With, 5, true) | ||
| } | ||
|
|
||
| func Benchmark5WithsNotUsed(b *testing.B) { | ||
| benchmarkWithUsed(b, (*LazyLogger).With, 5, false) | ||
| } | ||
|
|
||
| func Benchmark5WithLazysUsed(b *testing.B) { | ||
| benchmarkWithUsed(b, (*LazyLogger).WithLazy, 5, true) | ||
| } | ||
|
|
||
| func Benchmark5WithLazysNotUsed(b *testing.B) { | ||
| benchmarkWithUsed(b, (*LazyLogger).WithLazy, 5, false) | ||
| } | ||
|
|
||
| func benchmarkWithUsed(b *testing.B, withMethodExpr func(*LazyLogger, ...zapcore.Field) *LazyLogger, N int, use bool) { | ||
| keys := make([]string, N) | ||
| values := make([]string, N) | ||
| for i := 0; i < N; i++ { | ||
| keys[i] = "k" + strconv.Itoa(i) | ||
| values[i] = "v" + strconv.Itoa(i) | ||
| } | ||
|
|
||
| b.ResetTimer() | ||
|
|
||
| withBenchedLogger(b, func(log *LazyLogger) { | ||
| for i := 0; i < N; i++ { | ||
| log = withMethodExpr(log, zap.String(keys[i], values[i])) | ||
| } | ||
| if use { | ||
| log.Info("used") | ||
| return | ||
| } | ||
| runtime.KeepAlive(log) | ||
| }) | ||
| } | ||
|
|
||
| func withBenchedLogger(b *testing.B, f func(*LazyLogger)) { | ||
| logger := New( | ||
| zapcore.NewCore( | ||
| zapcore.NewJSONEncoder(zap.NewProductionConfig().EncoderConfig), | ||
| &ztest.Discarder{}, | ||
| zap.DebugLevel, | ||
| )) | ||
| b.ResetTimer() | ||
| b.RunParallel(func(pb *testing.PB) { | ||
| for pb.Next() { | ||
| f(logger) | ||
| } | ||
| }) | ||
| } |
This file contains bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
| Original file line number | Diff line number | Diff line change |
|---|---|---|
| @@ -0,0 +1,125 @@ | ||
| package lazylogger | ||
|
|
||
| import ( | ||
| "testing" | ||
|
|
||
| "github.com/stretchr/testify/assert" | ||
| "go.uber.org/zap" | ||
| "go.uber.org/zap/internal/ztest" | ||
| "go.uber.org/zap/zapcore" | ||
| "go.uber.org/zap/zaptest/observer" | ||
| ) | ||
|
|
||
| func TestLoggerWith(t *testing.T) { | ||
| fieldOpts := opts(zap.Fields(zap.Int("foo", 42))) | ||
| for _, tt := range []struct { | ||
| name string | ||
| withMethodExpr func(*LazyLogger, ...zap.Field) *LazyLogger | ||
| }{ | ||
| { | ||
| "regular non lazy logger", | ||
| (*LazyLogger).With, | ||
| }, | ||
| { | ||
| "lazy with logger", | ||
| (*LazyLogger).WithLazy, | ||
| }, | ||
| } { | ||
| t.Run(tt.name, func(t *testing.T) { | ||
| withLogger(t, zap.DebugLevel, fieldOpts, func(logger *LazyLogger, 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, zap.String("one", "two")).Info("") | ||
| tt.withMethodExpr(logger, zap.String("three", "four")).Info("") | ||
| tt.withMethodExpr(logger, zap.String("five", "six")).With(zap.String("seven", "eight")).Info("") | ||
| logger.Info("") | ||
|
|
||
| assert.Equal(t, []observer.LoggedEntry{ | ||
| {Context: []zap.Field{zap.Int("foo", 42), zap.String("one", "two")}}, | ||
| {Context: []zap.Field{zap.Int("foo", 42), zap.String("three", "four")}}, | ||
| {Context: []zap.Field{zap.Int("foo", 42), zap.String("five", "six"), zap.String("seven", "eight")}}, | ||
| {Context: []zap.Field{zap.Int("foo", 42)}}, | ||
| }, logs.AllUntimed(), "Unexpected cross-talk between child loggers.") | ||
| }) | ||
| }) | ||
| } | ||
| } | ||
|
|
||
| func withLogger(t testing.TB, e zapcore.LevelEnabler, opts []zap.Option, f func(*LazyLogger, *observer.ObservedLogs)) { | ||
| fac, logs := observer.New(e) | ||
| log := New(fac, opts...) | ||
| f(log, logs) | ||
| } | ||
|
|
||
| func opts(opts ...zap.Option) []zap.Option { | ||
| return opts | ||
| } | ||
|
|
||
| func TestLoggerWithCaptures(t *testing.T) { | ||
| for _, tt := range []struct { | ||
| name string | ||
| withMethodExpr func(*LazyLogger, ...zap.Field) *LazyLogger | ||
| wantJSON [2]string | ||
| }{ | ||
| { | ||
| name: "regular with captures arguments at time of With", | ||
| withMethodExpr: (*LazyLogger).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: (*LazyLogger).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, zap.DebugLevel)) | ||
|
|
||
| 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 = tt.withMethodExpr(logger, zap.Array("a", arr)) | ||
| x = 1 | ||
| logger.Info("hello", zap.Array("b", arr)) | ||
| x = 2 | ||
| logger = tt.withMethodExpr(logger, zap.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.") | ||
| } | ||
| }) | ||
| } | ||
| } |
This file contains bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
| Original file line number | Diff line number | Diff line change |
|---|---|---|
| @@ -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) | ||
| } |