log: avoid stack lookups when not needed/used (#28069)

Avoids the somewhat expensive stack.Caller invocation by checking if it is needed
This commit is contained in:
Martin Holst Swende 2023-09-07 14:48:49 +02:00 committed by GitHub
parent c60f7dd08d
commit a8d7201ec5
No known key found for this signature in database
GPG Key ID: 4AEE18F83AFDEB23
5 changed files with 99 additions and 5 deletions

View File

@ -25,6 +25,7 @@ import (
"reflect" "reflect"
"strings" "strings"
"testing" "testing"
"time"
) )
func TestBytesConversion(t *testing.T) { func TestBytesConversion(t *testing.T) {
@ -583,3 +584,14 @@ func TestAddressEIP55(t *testing.T) {
t.Fatal("Unexpected address after unmarshal") 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)
}

View File

@ -33,8 +33,16 @@ var locationTrims = []string{
// format output. // format output.
func PrintOrigins(print bool) { func PrintOrigins(print bool) {
locationEnabled.Store(print) 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 // locationEnabled is an atomic flag controlling whether the terminal formatter
// should append the log locations too when printing entries. // should append the log locations too when printing entries.
var locationEnabled atomic.Bool var locationEnabled atomic.Bool

View File

@ -139,7 +139,10 @@ func (h *GlogHandler) Vmodule(ruleset string) error {
h.patterns = filter h.patterns = filter
h.siteCache = make(map[uintptr]Lvl) h.siteCache = make(map[uintptr]Lvl)
h.override.Store(len(filter) != 0) h.override.Store(len(filter) != 0)
// Enable location storage (globally)
if len(h.patterns) > 0 {
stackEnabled.Store(true)
}
return nil return nil
} }
@ -172,7 +175,8 @@ func (h *GlogHandler) BacktraceAt(location string) error {
h.location = location h.location = location
h.backtrace.Store(len(location) > 0) h.backtrace.Store(len(location) > 0)
// Enable location storage (globally)
stackEnabled.Store(true)
return nil return nil
} }

View File

@ -177,19 +177,22 @@ type logger struct {
} }
func (l *logger) write(msg string, lvl Lvl, ctx []interface{}, skip int) { func (l *logger) write(msg string, lvl Lvl, ctx []interface{}, skip int) {
l.h.Log(&Record{ record := &Record{
Time: time.Now(), Time: time.Now(),
Lvl: lvl, Lvl: lvl,
Msg: msg, Msg: msg,
Ctx: newContext(l.ctx, ctx), Ctx: newContext(l.ctx, ctx),
Call: stack.Caller(skip),
KeyNames: RecordKeyNames{ KeyNames: RecordKeyNames{
Time: timeKey, Time: timeKey,
Msg: msgKey, Msg: msgKey,
Lvl: lvlKey, Lvl: lvlKey,
Ctx: ctxKey, Ctx: ctxKey,
}, },
}) }
if stackEnabled.Load() {
record.Call = stack.Caller(skip)
}
l.h.Log(record)
} }
func (l *logger) New(ctx ...interface{}) Logger { func (l *logger) New(ctx ...interface{}) Logger {

67
log/logger_test.go Normal file
View File

@ -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)
}
}