From 34182f225c44be646d77610b4a99123def329cbe Mon Sep 17 00:00:00 2001 From: Jeremy Quirke Date: Sun, 13 Aug 2023 18:19:18 -0700 Subject: [PATCH] [Work in progress] Proof of concept deferred withs As per internal Uber discussion --- exp/go.sum | 2 - logger.go | 6 +++ logger_bench_test.go | 57 +++++++++++++++++++++++++++++ logger_test.go | 17 +++++++++ options.go | 8 ++++ zapcore/deferred_with.go | 79 ++++++++++++++++++++++++++++++++++++++++ 6 files changed, 167 insertions(+), 2 deletions(-) create mode 100644 zapcore/deferred_with.go diff --git a/exp/go.sum b/exp/go.sum index 9df6ac4b4..7e0c3e06e 100644 --- a/exp/go.sum +++ b/exp/go.sum @@ -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= diff --git a/logger.go b/logger.go index 0e9548011..80d2d2a72 100644 --- a/logger.go +++ b/logger.go @@ -40,6 +40,7 @@ import ( type Logger struct { core zapcore.Core + deferWith bool development bool addCaller bool onFatal zapcore.CheckWriteHook // default is WriteThenFatal @@ -178,6 +179,11 @@ func (log *Logger) With(fields ...Field) *Logger { if len(fields) == 0 { return log } + if log.deferWith { + l := *log + l.core = zapcore.NewDeferredWith(log.core, fields) + return &l + } l := log.clone() l.core = l.core.With(fields) return l diff --git a/logger_bench_test.go b/logger_bench_test.go index bcf501a3f..304e5abb7 100644 --- a/logger_bench_test.go +++ b/logger_bench_test.go @@ -65,6 +65,21 @@ func withBenchedLogger(b *testing.B, f func(*Logger)) { }) } +func withBenchedDeferredLogger(b *testing.B, f func(*Logger)) { + logger := New( + zapcore.NewCore( + zapcore.NewJSONEncoder(NewProductionConfig().EncoderConfig), + &ztest.Discarder{}, + DebugLevel, + ), DeferWith()) + b.ResetTimer() + b.RunParallel(func(pb *testing.PB) { + for pb.Next() { + f(logger) + } + }) +} + func BenchmarkNoContext(b *testing.B) { withBenchedLogger(b, func(log *Logger) { log.Info("No context.") @@ -216,6 +231,48 @@ func Benchmark10Fields(b *testing.B) { }) } +func Benchmark5WithsUsed(b *testing.B) { + withBenchedLogger(b, func(log *Logger) { + l1 := log.With(String("k1", "v1")) + l2 := l1.With(String("k2", "v2")) + l3 := l2.With(String("k3", "v3")) + l4 := l3.With(String("k4", "v4")) + l5 := l4.With(String("k5", "v5")) + l5.Info("used") + }) +} + +func Benchmark5WithsNotUsed(b *testing.B) { + withBenchedLogger(b, func(log *Logger) { + l1 := log.With(String("k1", "v1")) + l2 := l1.With(String("k2", "v2")) + l3 := l2.With(String("k3", "v3")) + l4 := l3.With(String("k4", "v4")) + _ = l4.With(String("k5", "v5")) + }) +} + +func Benchmark5WithsDeferredUsed(b *testing.B) { + withBenchedDeferredLogger(b, func(log *Logger) { + l1 := log.With(String("k1", "v1")) + l2 := l1.With(String("k2", "v2")) + l3 := l2.With(String("k3", "v3")) + l4 := l3.With(String("k4", "v4")) + l5 := l4.With(String("k5", "v5")) + l5.Info("used") + }) +} + +func Benchmark5WithsDeferredNotUsed(b *testing.B) { + withBenchedDeferredLogger(b, func(log *Logger) { + l1 := log.With(String("k1", "v1")) + l2 := l1.With(String("k2", "v2")) + l3 := l2.With(String("k3", "v3")) + l4 := l3.With(String("k4", "v4")) + _ = l4.With(String("k5", "v5")) + }) +} + func Benchmark100Fields(b *testing.B) { const batchSize = 50 logger := New(zapcore.NewCore( diff --git a/logger_test.go b/logger_test.go index d4af57512..4b20339d7 100644 --- a/logger_test.go +++ b/logger_test.go @@ -140,6 +140,23 @@ func TestLoggerWith(t *testing.T) { }) } +func TestLoggerWithDeferred(t *testing.T) { + fieldOpts := opts(Fields(Int("foo", 42)), DeferWith()) + 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("") + + 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 TestLoggerLogPanic(t *testing.T) { for _, tt := range []struct { do func(*Logger) diff --git a/options.go b/options.go index c4f3bca3d..654d161c1 100644 --- a/options.go +++ b/options.go @@ -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. diff --git a/zapcore/deferred_with.go b/zapcore/deferred_with.go new file mode 100644 index 000000000..4527f96c8 --- /dev/null +++ b/zapcore/deferred_with.go @@ -0,0 +1,79 @@ +// 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) *deferredWithCore { + 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 { + d.initOnce() + return d.Core.With(fields) +} + +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) +} + +func (d *deferredWithCore) Sync() error { + d.initOnce() + return d.Core.Sync() +} + +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) +}