diff --git a/stack/stack.go b/stack/stack.go index 9252e7e..b5c1bb0 100644 --- a/stack/stack.go +++ b/stack/stack.go @@ -4,9 +4,9 @@ package stack import ( "fmt" "hash/crc32" - "os" "runtime" "strings" + "sync" ) var ( @@ -16,6 +16,29 @@ var ( "bitbucket.org/", "launchpad.net/", } + + // pcBufPool reuses the []uintptr scratch buffers that runtime.Callers writes + // into. BuildStack runs on every error, so recycling these avoids an 800-byte + // allocation per call. + pcBufPool = sync.Pool{ + New: func() interface{} { + b := make([]uintptr, 100) + return &b + }, + } + + // symCache memoises the symbolisation of a program counter. A PC always maps + // to the same frame(s) for the life of the process (code doesn't move), so + // resolving file/line/function names — the expensive part of building a stack + // — only has to happen once per distinct call site. The cache is bounded by + // the number of call sites in the binary, so it cannot grow without bound. + // + // We deliberately cache frames by value, not by pointer: BuildStack copies + // them into a fresh backing array on every call, so a caller that mutates a + // returned Frame only affects their own Stack and can never corrupt the + // shared cache (Frame is all strings and ints, so a struct copy is fully + // independent). + symCache sync.Map // map[uintptr][]Frame ) type Frame struct { @@ -28,10 +51,12 @@ type Frame struct { type Stack []*Frame func BuildStack(skip int) Stack { - stack := make(Stack, 0) - - // Look up to a maximum depth of 100 - ret := make([]uintptr, 100) + // Look up to a maximum depth of 100, reusing a pooled buffer. The buffer is + // only referenced by runtime.CallersFrames below, so it's safe to return it + // to the pool once we've finished iterating within this function. + bufp := pcBufPool.Get().(*[]uintptr) + ret := *bufp + defer pcBufPool.Put(bufp) // Note that indexes must be one higher when passed to Callers() // than they would be when passed to Caller() @@ -39,26 +64,63 @@ func BuildStack(skip int) Stack { index := runtime.Callers(skip+1, ret) if index == 0 { // We have no frames to report, skip must be too high - return stack + return Stack{} } - // This function takes a list of counters and gets function/file/line information - cf := runtime.CallersFrames(ret[:index]) + // Symbolise each PC, reusing cached results for call sites we've already + // resolved. We copy the cached frame values into a backing array that this + // call exclusively owns, so callers can freely mutate the returned frames + // without affecting the cache or any other Stack. A PC can expand to more + // than one frame when calls are inlined, so index is a lower bound. + frames := make([]Frame, 0, index) + for _, pc := range ret[:index] { + frames = append(frames, framesForPC(pc)...) + } + // Now the backing array is stable we can hand out pointers into it. + stack := make(Stack, len(frames)) + for i := range frames { + stack[i] = &frames[i] + } + return stack +} + +// framesForPC resolves a single program counter to its frame(s), memoising the +// result. Symbolisation (decoding the runtime's line tables) is the dominant +// cost of building a stack, and the mapping is stable for the life of the +// process, so we only pay it once per distinct PC. +// +// The returned slice is the shared, cached copy and must not be mutated; +// callers append it into a private backing array (see BuildStack). +func framesForPC(pc uintptr) []Frame { + if cached, ok := symCache.Load(pc); ok { + return cached.([]Frame) + } + + // A single PC can expand into multiple frames due to inlining, so we still + // have to iterate CallersFrames. Processing one PC at a time yields the same + // frames as processing the whole slice at once (verified in the tests). + cf := runtime.CallersFrames([]uintptr{pc}) + var frames []Frame for { - frame, ok := cf.Next() - stack = append(stack, &Frame{ + frame, more := cf.Next() + frames = append(frames, Frame{ Filename: shortenFilePath(frame.File), - Method: functionName(frame.PC), - Line: frame.Line, - PC: frame.PC, + // frame.Function already carries the fully-qualified name, so we use + // it directly rather than doing a second runtime.FuncForPC lookup. + Method: functionName(frame.Function), + Line: frame.Line, + PC: frame.PC, }) - if !ok { - // This was the last valid caller + if !more { break } } - return stack + + // LoadOrStore keeps a single canonical slice per PC even if two goroutines + // race to symbolise the same one concurrently. + actual, _ := symCache.LoadOrStore(pc, frames) + return actual.([]Frame) } // Create a fingerprint that uniquely identify a given message. We use the full @@ -182,12 +244,11 @@ func shortenFilePath(s string) string { return s } -func functionName(pc uintptr) string { - fn := runtime.FuncForPC(pc) - if fn == nil { +func functionName(name string) string { + if name == "" { return "???" } - name := fn.Name() - end := strings.LastIndex(name, string(os.PathSeparator)) + // Function names are always '/'-separated regardless of the host OS. + end := strings.LastIndex(name, "/") return name[end+1:] } diff --git a/stack/stack_test.go b/stack/stack_test.go index 095a431..08fd260 100644 --- a/stack/stack_test.go +++ b/stack/stack_test.go @@ -2,8 +2,10 @@ package stack import ( - "github.com/stretchr/testify/assert" + "runtime" "testing" + + "github.com/stretchr/testify/assert" ) func TestBuildStack(t *testing.T) { @@ -13,6 +15,58 @@ func TestBuildStack(t *testing.T) { assert.NotZero(t, frame.Line, "Frame line number") } +// symboliseBulk resolves a slice of PCs the "classic" way — one CallersFrames +// pass over the whole slice — so we can prove our per-PC cached symbolisation +// produces byte-for-byte identical frames, including where the compiler has +// inlined calls (which makes a single PC expand into several frames). +func symboliseBulk(pcs []uintptr) []Frame { + cf := runtime.CallersFrames(pcs) + var s []Frame + for { + frame, more := cf.Next() + s = append(s, Frame{ + Filename: shortenFilePath(frame.File), + Method: functionName(frame.Function), + Line: frame.Line, + PC: frame.PC, + }) + if !more { + break + } + } + return s +} + +func TestFramesForPCMatchesBulkSymbolisation(t *testing.T) { + // Capture a real, reasonably deep stack including this test's callers. + pcs := make([]uintptr, 100) + n := runtime.Callers(0, pcs) + pcs = pcs[:n] + + bulk := symboliseBulk(pcs) + + var perPC []Frame + for _, pc := range pcs { + perPC = append(perPC, framesForPC(pc)...) + } + + assert.Equal(t, len(bulk), len(perPC), "per-PC symbolisation produced a different number of frames") + for i := range bulk { + assert.Equal(t, bulk[i].Filename, perPC[i].Filename, "frame %d filename", i) + assert.Equal(t, bulk[i].Method, perPC[i].Method, "frame %d method", i) + assert.Equal(t, bulk[i].Line, perPC[i].Line, "frame %d line", i) + assert.Equal(t, bulk[i].PC, perPC[i].PC, "frame %d pc", i) + } +} + +func TestFramesForPCIsCached(t *testing.T) { + pc := BuildStack(0)[0].PC + first := framesForPC(pc) + second := framesForPC(pc) + // A cache hit must return the very same backing slice, not re-symbolise. + assert.Equal(t, &first[0], &second[0], "expected cached frames to be reused") +} + func TestStackFingerprint(t *testing.T) { tests := []struct { Fingerprint string @@ -177,3 +231,25 @@ func assertHasCommonAncestry(t *testing.T, current Stack, other Stack) bool { func assertHasNoCommonAncestry(t *testing.T, current Stack, other Stack) bool { return assert.False(t, current.HasCommonAncestry(other), "Stack current should not have common ancestry with other: current:%v\nother:%v\n", current, other) } + +// buildStackAtDepth recurses to a given depth before building a stack, so the +// benchmark exercises a stack of a realistic size rather than the shallow one +// the test harness itself provides. +func buildStackAtDepth(depth int) Stack { + if depth > 0 { + return buildStackAtDepth(depth - 1) + } + return BuildStack(0) +} + +// BenchmarkBuildStack measures the steady state: repeated calls from call sites +// that have already been symbolised, which is what a busy service overwhelmingly +// sees once its hot error paths have run at least once. +func BenchmarkBuildStack(b *testing.B) { + var s Stack + b.ReportAllocs() + for i := 0; i < b.N; i++ { + s = buildStackAtDepth(20) + } + _ = s +}