From a8d7201ec5440d54234ca02b24287674ac8449c6 Mon Sep 17 00:00:00 2001 From: Martin Holst Swende Date: Thu, 7 Sep 2023 14:48:49 +0200 Subject: [PATCH] log: avoid stack lookups when not needed/used (#28069) Avoids the somewhat expensive stack.Caller invocation by checking if it is needed --- common/types_test.go | 12 ++++++++ log/format.go | 8 ++++++ log/handler_glog.go | 8 ++++-- log/logger.go | 9 ++++-- log/logger_test.go | 67 ++++++++++++++++++++++++++++++++++++++++++++ 5 files changed, 99 insertions(+), 5 deletions(-) create mode 100644 log/logger_test.go diff --git a/common/types_test.go b/common/types_test.go index ad892671b5..cec689ea39 100644 --- a/common/types_test.go +++ b/common/types_test.go @@ -25,6 +25,7 @@ import ( "reflect" "strings" "testing" + "time" ) func TestBytesConversion(t *testing.T) { @@ -583,3 +584,14 @@ func TestAddressEIP55(t *testing.T) { t.Fatal("Unexpected address after unmarshal") } } + +func BenchmarkPrettyDuration(b *testing.B) { + var x = PrettyDuration(time.Duration(int64(1203123912312))) + b.Logf("Pre %s", time.Duration(x).String()) + var a string + b.ResetTimer() + for i := 0; i < b.N; i++ { + a = x.String() + } + b.Logf("Post %s", a) +} diff --git a/log/format.go b/log/format.go index 6a03013b81..1adf79c17e 100644 --- a/log/format.go +++ b/log/format.go @@ -33,8 +33,16 @@ var locationTrims = []string{ // format output. func PrintOrigins(print bool) { locationEnabled.Store(print) + if print { + stackEnabled.Store(true) + } } +// stackEnabled is an atomic flag controlling whether the log handler needs +// to store the callsite stack. This is needed in case any handler wants to +// print locations (locationEnabled), use vmodule, or print full stacks (BacktraceAt). +var stackEnabled atomic.Bool + // locationEnabled is an atomic flag controlling whether the terminal formatter // should append the log locations too when printing entries. var locationEnabled atomic.Bool diff --git a/log/handler_glog.go b/log/handler_glog.go index 6db5f1a4c9..afca0808b3 100644 --- a/log/handler_glog.go +++ b/log/handler_glog.go @@ -139,7 +139,10 @@ func (h *GlogHandler) Vmodule(ruleset string) error { h.patterns = filter h.siteCache = make(map[uintptr]Lvl) h.override.Store(len(filter) != 0) - + // Enable location storage (globally) + if len(h.patterns) > 0 { + stackEnabled.Store(true) + } return nil } @@ -172,7 +175,8 @@ func (h *GlogHandler) BacktraceAt(location string) error { h.location = location h.backtrace.Store(len(location) > 0) - + // Enable location storage (globally) + stackEnabled.Store(true) return nil } diff --git a/log/logger.go b/log/logger.go index 4e471a22da..42e7e375d0 100644 --- a/log/logger.go +++ b/log/logger.go @@ -177,19 +177,22 @@ type logger struct { } func (l *logger) write(msg string, lvl Lvl, ctx []interface{}, skip int) { - l.h.Log(&Record{ + record := &Record{ Time: time.Now(), Lvl: lvl, Msg: msg, Ctx: newContext(l.ctx, ctx), - Call: stack.Caller(skip), KeyNames: RecordKeyNames{ Time: timeKey, Msg: msgKey, Lvl: lvlKey, Ctx: ctxKey, }, - }) + } + if stackEnabled.Load() { + record.Call = stack.Caller(skip) + } + l.h.Log(record) } func (l *logger) New(ctx ...interface{}) Logger { diff --git a/log/logger_test.go b/log/logger_test.go new file mode 100644 index 0000000000..2e59b3fdf0 --- /dev/null +++ b/log/logger_test.go @@ -0,0 +1,67 @@ +package log + +import ( + "bytes" + "os" + "strings" + "testing" +) + +// TestLoggingWithTrace checks that if BackTraceAt is set, then the +// gloghandler is capable of spitting out a stacktrace +func TestLoggingWithTrace(t *testing.T) { + defer stackEnabled.Store(stackEnabled.Load()) + out := new(bytes.Buffer) + logger := New() + { + glog := NewGlogHandler(StreamHandler(out, TerminalFormat(false))) + glog.Verbosity(LvlTrace) + if err := glog.BacktraceAt("logger_test.go:24"); err != nil { + t.Fatal(err) + } + logger.SetHandler(glog) + } + logger.Trace("a message", "foo", "bar") // Will be bumped to INFO + have := out.String() + if !strings.HasPrefix(have, "INFO") { + t.Fatalf("backtraceat should bump level to info: %s", have) + } + // The timestamp is locale-dependent, so we want to trim that off + // "INFO [01-01|00:00:00.000] a messag ..." -> "a messag..." + have = strings.Split(have, "]")[1] + wantPrefix := " a message\n\ngoroutine" + if !strings.HasPrefix(have, wantPrefix) { + t.Errorf("\nhave: %q\nwant: %q\n", have, wantPrefix) + } +} + +// TestLoggingWithVmodule checks that vmodule works. +func TestLoggingWithVmodule(t *testing.T) { + defer stackEnabled.Store(stackEnabled.Load()) + out := new(bytes.Buffer) + logger := New() + { + glog := NewGlogHandler(StreamHandler(out, TerminalFormat(false))) + glog.Verbosity(LvlCrit) + logger.SetHandler(glog) + logger.Warn("This should not be seen", "ignored", "true") + glog.Vmodule("logger_test.go=5") + } + logger.Trace("a message", "foo", "bar") + have := out.String() + // The timestamp is locale-dependent, so we want to trim that off + // "INFO [01-01|00:00:00.000] a messag ..." -> "a messag..." + have = strings.Split(have, "]")[1] + want := " a message foo=bar\n" + if have != want { + t.Errorf("\nhave: %q\nwant: %q\n", have, want) + } +} + +func BenchmarkTraceLogging(b *testing.B) { + Root().SetHandler(LvlFilterHandler(LvlInfo, StreamHandler(os.Stderr, TerminalFormat(true)))) + b.ResetTimer() + for i := 0; i < b.N; i++ { + Trace("a message", "v", i) + } +}