From c27b7e95e58068f538c466677b5b4857c3b41177 Mon Sep 17 00:00:00 2001 From: Vincent Bernat Date: Wed, 5 Nov 2025 08:21:19 +0100 Subject: [PATCH] common/reporter: optimize stack trace walking when logging Instead of computing the same time the call site, use an intermediate structure with lazily-evaluated functions. --- common/reporter/logger/root.go | 18 ++--- common/reporter/metrics/root.go | 6 +- common/reporter/stack/root.go | 113 ++++++++++++++++++----------- common/reporter/stack/root_test.go | 77 +++++++++++++++++++- 4 files changed, 154 insertions(+), 60 deletions(-) diff --git a/common/reporter/logger/root.go b/common/reporter/logger/root.go index 1b00bebd..88b72eb7 100644 --- a/common/reporter/logger/root.go +++ b/common/reporter/logger/root.go @@ -42,22 +42,20 @@ func (h contextHook) Run(e *zerolog.Event, _ zerolog.Level, _ string) { callStack = callStack[3:] // Trial and error, there is a test to check it works. // We want to get the first caller that is in our module and isn't preferably in logs.go. - var candidateCall stack.Call - var candidateModule string + var candidateInfo *stack.CallInfo for _, call := range callStack { - module := call.FunctionName() - if !strings.HasPrefix(module, stack.ModuleName) { + info := call.Info() + if !strings.HasPrefix(info.FunctionName(), stack.ModuleName) { continue } - candidateCall = call - candidateModule = strings.SplitN(module, ".", 2)[0] - if strings.HasSuffix(call.FileName(), "/logs.go") { + candidateInfo = info + if strings.HasSuffix(info.FileName(), "/logs.go") { continue } break } - if candidateCall != stack.Call(0) { - e.Str("caller", candidateCall.SourceFile(true)) - e.Str("module", candidateModule) + if candidateInfo != nil { + e.Str("caller", candidateInfo.SourceFile()) + e.Str("module", strings.SplitN(candidateInfo.FunctionName(), ".", 2)[0]) } } diff --git a/common/reporter/metrics/root.go b/common/reporter/metrics/root.go index 10e9a20b..b9dd0351 100644 --- a/common/reporter/metrics/root.go +++ b/common/reporter/metrics/root.go @@ -74,7 +74,7 @@ func getPrefix(module string) (moduleName string) { func (m *Metrics) Factory(skipCallstack int) *Factory { callStack := stack.Callers() call := callStack[1+skipCallstack] // Trial and error, there is a test to check it works - module := call.FunctionName() + module := call.Info().FunctionName() // Hotpath if factory := func() *Factory { @@ -105,7 +105,7 @@ func (m *Metrics) Factory(skipCallstack int) *Factory { func (m *Metrics) RegisterCollector(skipCallStack int, c prometheus.Collector) { callStack := stack.Callers() call := callStack[1+skipCallStack] // Should be the same as above ! - prefix := getPrefix(call.FunctionName()) + prefix := getPrefix(call.Info().FunctionName()) prometheus.WrapRegistererWithPrefix(prefix, m.registry).MustRegister(c) } @@ -113,6 +113,6 @@ func (m *Metrics) RegisterCollector(skipCallStack int, c prometheus.Collector) { func (m *Metrics) UnregisterCollector(skipCallStack int, c prometheus.Collector) { callStack := stack.Callers() call := callStack[1+skipCallStack] // Should be the same as above ! - prefix := getPrefix(call.FunctionName()) + prefix := getPrefix(call.Info().FunctionName()) prometheus.WrapRegistererWithPrefix(prefix, m.registry).Unregister(c) } diff --git a/common/reporter/stack/root.go b/common/reporter/stack/root.go index 559d52e5..4f324196 100644 --- a/common/reporter/stack/root.go +++ b/common/reporter/stack/root.go @@ -40,72 +40,97 @@ func Callers() Trace { return cs } -// FunctionName provides the function name associated with the call -// point. It includes the module name as well. -func (pc Call) FunctionName() string { - pcFix := uintptr(pc) - 1 - fn := runtime.FuncForPC(pcFix) - if fn == nil { - return "(nofunc)" - } - - name := fn.Name() - return name +// CallInfo contains lazily-evaluated information from a Call. +// It performs a single runtime.FuncForPC lookup and caches values as they're accessed. +type CallInfo struct { + pc uintptr + fn *runtime.Func + functionName string + fileName string + sourceFile string + line int + initialized bool } -// FileName returns the file name of the call point. -func (pc Call) FileName() string { - pcFix := uintptr(pc) - 1 - fn := runtime.FuncForPC(pcFix) - if fn == nil { - return "(nofile)" +// Info creates a CallInfo that lazily extracts information from the call point. +// This is more efficient than calling FunctionName(), FileName(), and SourceFile() separately, +// and only computes values that are actually accessed. +func (pc Call) Info() *CallInfo { + return &CallInfo{ + pc: uintptr(pc) - 1, } - file, _ := fn.FileLine(pcFix) - return file } -// SourceFile returns the source file and optionally line number of -// the call point. The source file is relative to the import point -// (and includes it). -func (pc Call) SourceFile(withLine bool) string { - pcFix := uintptr(pc) - 1 - fn := runtime.FuncForPC(pcFix) - if fn == nil { - return "(nosource)" +func (ci *CallInfo) ensureInit() { + if ci.initialized { + return + } + ci.initialized = true + ci.fn = runtime.FuncForPC(ci.pc) + if ci.fn == nil { + ci.functionName = "(nofunc)" + ci.fileName = "(nofile)" + ci.sourceFile = "(nosource)" + return + } +} + +// FunctionName returns the function name. +func (ci *CallInfo) FunctionName() string { + ci.ensureInit() + if ci.functionName == "" { + ci.functionName = ci.fn.Name() + } + return ci.functionName +} + +// FileName returns the file name. +func (ci *CallInfo) FileName() string { + ci.ensureInit() + if ci.fileName == "" { + ci.fileName, ci.line = ci.fn.FileLine(ci.pc) + } + return ci.fileName +} + +// SourceFile returns the source file with line number. +func (ci *CallInfo) SourceFile() string { + ci.ensureInit() + if ci.sourceFile != "" { + return ci.sourceFile } const sep = "/" - file, line := fn.FileLine(pcFix) - functionName := fn.Name() + sourceFile := ci.FileName() + functionName := ci.FunctionName() impCnt := strings.Count(functionName, sep) - pathCnt := strings.Count(file, sep) + pathCnt := strings.Count(sourceFile, sep) for pathCnt > impCnt { - i := strings.Index(file, sep) + i := strings.Index(sourceFile, sep) if i == -1 { break } - file = file[i+len(sep):] + sourceFile = sourceFile[i+len(sep):] pathCnt-- } i := strings.Index(functionName, ".") if i == -1 { - return "(nosource)" + ci.sourceFile = "(nosource)" + } else { + moduleName := functionName[:i] + i = strings.Index(moduleName, "/") + if i != -1 { + moduleName = moduleName[:i] + } + ci.sourceFile = fmt.Sprintf("%s/%s:%d", moduleName, sourceFile, ci.line) } - moduleName := functionName[:i] - i = strings.Index(moduleName, "/") - if i != -1 { - moduleName = moduleName[:i] - } - if withLine { - return fmt.Sprintf("%s/%s:%d", moduleName, file, line) - } - return fmt.Sprintf("%s/%s", moduleName, file) + return ci.sourceFile } var ( ownPackageCall = Callers()[0] - ownPackageName = strings.SplitN(ownPackageCall.FunctionName(), ".", 2)[0] // akvorado/common/reporter/stack - parentPackageName = ownPackageName[0:strings.LastIndex(ownPackageName, "/")] // akvorado/common/reporter + ownPackageName = strings.SplitN(ownPackageCall.Info().FunctionName(), ".", 2)[0] // akvorado/common/reporter/stack + parentPackageName = ownPackageName[0:strings.LastIndex(ownPackageName, "/")] // akvorado/common/reporter // ModuleName is the name of the current module. This can be used to prefix stuff. ModuleName = strings.TrimSuffix(parentPackageName[0:strings.LastIndex(parentPackageName, "/")], "/common") // akvorado diff --git a/common/reporter/stack/root_test.go b/common/reporter/stack/root_test.go index 3b6cf6e2..90ab9576 100644 --- a/common/reporter/stack/root_test.go +++ b/common/reporter/stack/root_test.go @@ -15,7 +15,12 @@ func TestSourceFile(t *testing.T) { callers := stack.Callers() got := []string{} for _, caller := range callers[:len(callers)-1] { - got = append(got, caller.SourceFile(false)) + // Extract source file without line number + sourceFile := caller.Info().SourceFile() + if idx := strings.LastIndex(sourceFile, ":"); idx != -1 { + sourceFile = sourceFile[:idx] + } + got = append(got, sourceFile) } expected := []string{ "akvorado/common/reporter/stack/root_test.go", @@ -30,14 +35,14 @@ func TestFunctionName(t *testing.T) { callers := stack.Callers() got := []string{} for _, caller := range callers[:len(callers)-1] { - got = append(got, caller.FunctionName()) + got = append(got, caller.Info().FunctionName()) } expected := []string{ "akvorado/common/reporter/stack_test.TestFunctionName", "testing.tRunner", } if diff := helpers.Diff(got, expected); diff != "" { - t.Fatalf("SourceFile() (-got, +want):\n%s", diff) + t.Fatalf("FunctionName() (-got, +want):\n%s", diff) } } @@ -48,3 +53,69 @@ func TestModuleName(t *testing.T) { t.Errorf("moduleName:\n%s", diff) } } + +func TestInfo(t *testing.T) { + callers := stack.Callers() + if len(callers) == 0 { + t.Fatal("Callers() empty") + } + caller := callers[0] + info := caller.Info() + + // Verify basic properties + functionName := info.FunctionName() + if !strings.HasSuffix(functionName, ".TestInfo") { + t.Errorf("FunctionName() should end with .TestInfo, got %q", functionName) + } + + fileName := info.FileName() + if !strings.HasSuffix(fileName, "/root_test.go") { + t.Errorf("FileName() should end with /root_test.go, got %q", fileName) + } + + sourceFile := info.SourceFile() + if !strings.HasSuffix(sourceFile, "akvorado/common/reporter/stack/root_test.go:58") { + t.Errorf("SourceFile() should have complete path, got %q", sourceFile) + } +} + +func BenchmarkCallInfo(b *testing.B) { + callers := stack.Callers() + if len(callers) == 0 { + b.Fatal("no callers") + } + caller := callers[0] + + b.Run("Info() all fields", func(b *testing.B) { + for b.Loop() { + info := caller.Info() + _ = info.FunctionName() + _ = info.FileName() + _ = info.SourceFile() + } + }) + + b.Run("Info() function name", func(b *testing.B) { + for b.Loop() { + info := caller.Info() + _ = info.FunctionName() + } + }) + + b.Run("Info() function and filename", func(b *testing.B) { + // Simulates frames that match but we skip SourceFile computation + for b.Loop() { + info := caller.Info() + _ = info.FunctionName() + _ = info.FileName() + } + }) + + b.Run("Info() separate", func(b *testing.B) { + for b.Loop() { + _ = caller.Info().FunctionName() + _ = caller.Info().FileName() + _ = caller.Info().SourceFile() + } + }) +}