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

@@ -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 candidateInfo *stack.CallInfo
-	var candidateModule string
 	for _, call := range callStack {
-		module := call.FunctionName()
+		info := call.Info()
-		if !strings.HasPrefix(module, stack.ModuleName) {
+		if !strings.HasPrefix(info.FunctionName(), stack.ModuleName) {
 			continue
 		}
-		candidateCall = call
+		candidateInfo = info
-		candidateModule = strings.SplitN(module, ".", 2)[0]
+		if strings.HasSuffix(info.FileName(), "/logs.go") {
-		if strings.HasSuffix(call.FileName(), "/logs.go") {
 			continue
 		}
 		break
 	}
-	if candidateCall != stack.Call(0) {
+	if candidateInfo != nil {
-		e.Str("caller", candidateCall.SourceFile(true))
+		e.Str("caller", candidateInfo.SourceFile())
-		e.Str("module", candidateModule)
+		e.Str("module", strings.SplitN(candidateInfo.FunctionName(), ".", 2)[0])
 	}
 }

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

common/reporter/stack/root.go

@@ -40,72 +40,97 @@ func Callers() Trace {
 	return cs
 }
 
-// FunctionName provides the function name associated with the call
+// CallInfo contains lazily-evaluated information from a Call.
-// point. It includes the module name as well.
+// It performs a single runtime.FuncForPC lookup and caches values as they're accessed.
-func (pc Call) FunctionName() string {
+type CallInfo struct {
-	pcFix := uintptr(pc) - 1
+	pc           uintptr
-	fn := runtime.FuncForPC(pcFix)
+	fn           *runtime.Func
-	if fn == nil {
+	functionName string
-		return "(nofunc)"
+	fileName     string
-	}
+	sourceFile   string
-
+	line         int
-	name := fn.Name()
+	initialized  bool
-	return name
 }
 
-// FileName returns the file name of the call point.
+// Info creates a CallInfo that lazily extracts information from the call point.
-func (pc Call) FileName() string {
+// This is more efficient than calling FunctionName(), FileName(), and SourceFile() separately,
-	pcFix := uintptr(pc) - 1
+// and only computes values that are actually accessed.
-	fn := runtime.FuncForPC(pcFix)
+func (pc Call) Info() *CallInfo {
-	if fn == nil {
+	return &CallInfo{
-		return "(nofile)"
+		pc: uintptr(pc) - 1,
 	}
-	file, _ := fn.FileLine(pcFix)
-	return file
 }
 
-// SourceFile returns the source file and optionally line number of
+func (ci *CallInfo) ensureInit() {
-// the call point. The source file is relative to the import point
+	if ci.initialized {
-// (and includes it).
+		return
-func (pc Call) SourceFile(withLine bool) string {
+	}
-	pcFix := uintptr(pc) - 1
+	ci.initialized = true
-	fn := runtime.FuncForPC(pcFix)
+	ci.fn = runtime.FuncForPC(ci.pc)
-	if fn == nil {
+	if ci.fn == nil {
-		return "(nosource)"
+		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)
+	sourceFile := ci.FileName()
-	functionName := fn.Name()
+	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]
+	return ci.sourceFile
-	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)
 }
 
 var (
 	ownPackageCall    = Callers()[0]
-	ownPackageName    = strings.SplitN(ownPackageCall.FunctionName(), ".", 2)[0] // akvorado/common/reporter/stack
+	ownPackageName    = strings.SplitN(ownPackageCall.Info().FunctionName(), ".", 2)[0] // akvorado/common/reporter/stack
-	parentPackageName = ownPackageName[0:strings.LastIndex(ownPackageName, "/")] // akvorado/common/reporter
+	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

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()
+		}
+	})
+}