Skip to content

Commit

Permalink
Add option to defer With composition to first log
Browse files Browse the repository at this point in the history
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, DeferWith which defers all of this expense
until the time of first use. This creates considerable performance improvement.

```
% go test -bench=Benchmark5Withs
goos: darwin
goarch: arm64
pkg: go.uber.org/zap
Benchmark5WithsUsed-10               	  495187	      2463 ns/op
Benchmark5WithsNotUsed-10            	  530983	      2379 ns/op
Benchmark5WithsDeferredUsed-10       	  956476	      1161 ns/op
Benchmark5WithsDeferredNotUsed-10    	 2602353	       462.9 ns/op
```

Furthermore, one core microservice in Uber has seen a reduction of 10% heap
allocation by simply using this option.
  • Loading branch information
jquirke committed Aug 14, 2023
1 parent 5da8736 commit 33743dc
Show file tree
Hide file tree
Showing 6 changed files with 193 additions and 16 deletions.
2 changes: 0 additions & 2 deletions exp/go.sum
Original file line number Diff line number Diff line change
Expand Up @@ -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=
Expand Down
6 changes: 6 additions & 0 deletions logger.go
Original file line number Diff line number Diff line change
Expand Up @@ -40,6 +40,7 @@ import (
type Logger struct {
core zapcore.Core

deferWith bool
development bool
addCaller bool
onFatal zapcore.CheckWriteHook // default is WriteThenFatal
Expand Down Expand Up @@ -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
Expand Down
40 changes: 39 additions & 1 deletion logger_bench_test.go
Original file line number Diff line number Diff line change
Expand Up @@ -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() {
Expand Down Expand Up @@ -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(
Expand Down
71 changes: 58 additions & 13 deletions logger_test.go
Original file line number Diff line number Diff line change
Expand Up @@ -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) {
Expand Down
8 changes: 8 additions & 0 deletions options.go
Original file line number Diff line number Diff line change
Expand Up @@ -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.
Expand Down
82 changes: 82 additions & 0 deletions zapcore/deferred_with.go
Original file line number Diff line number Diff line change
@@ -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)

Check warning on line 66 in zapcore/deferred_with.go

View check run for this annotation

Codecov / codecov/patch

zapcore/deferred_with.go#L64-L66

Added lines #L64 - L66 were not covered by tests
}

func (d *deferredWithCore) Sync() error {
d.initOnce()
return d.Core.Sync()

Check warning on line 71 in zapcore/deferred_with.go

View check run for this annotation

Codecov / codecov/patch

zapcore/deferred_with.go#L69-L71

Added lines #L69 - L71 were not covered by tests
}

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)

Check warning on line 81 in zapcore/deferred_with.go

View check run for this annotation

Codecov / codecov/patch

zapcore/deferred_with.go#L79-L81

Added lines #L79 - L81 were not covered by tests
}

0 comments on commit 33743dc

Please sign in to comment.