diff --git a/common/types_test.go b/common/types_test.go index fc52878f15..7c2822854a 100644 --- a/common/types_test.go +++ b/common/types_test.go @@ -21,6 +21,7 @@ import ( "math/big" "strings" "testing" + "time" ) func TestBytesConversion(t *testing.T) { @@ -203,3 +204,14 @@ func TestStringToBinaryAddress(t *testing.T) { } } } + +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 fd14d6a975..bce4f439ad 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..1dd4764bda 100644 --- a/log/handler_glog.go +++ b/log/handler_glog.go @@ -139,6 +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 +176,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 6d89a17cd8..9bbfdc912c 100644 --- a/log/logger.go +++ b/log/logger.go @@ -176,19 +176,22 @@ type logger struct { } func (l *logger) write(msg string, lvl Lvl, ctx []interface{}) { - l.h.Log(&Record{ + record := &Record{ Time: time.Now(), Lvl: lvl, Msg: msg, Ctx: newContext(l.ctx, ctx), - Call: stack.Caller(2), KeyNames: RecordKeyNames{ Time: timeKey, Msg: msgKey, Lvl: lvlKey, Ctx: ctxKey, }, - }) + } + if stackEnabled.Load() { + record.Call = stack.Caller(2) + } + 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) + } +}