runtime: runtime_expandFinalInlineFrame doesn't skip trailing wrappers

[korniltsev]

What version of Go are you using (go version)?

$ go version
go version devel go1.21-9222a01e65 Fri Feb 3 04:37:17 2023 +0000 darwin/amd64

Does this issue reproduce with the latest release?

Yes

What operating system and processor architecture are you using (go env)?

go env Output

$ go env
GO111MODULE=""
GOARCH="amd64"
GOBIN=""
GOCACHE="/Users/korniltsev/Library/Caches/go-build"
GOENV="/Users/korniltsev/Library/Application Support/go/env"
GOEXE=""
GOEXPERIMENT=""
GOFLAGS=""
GOHOSTARCH="amd64"
GOHOSTOS="darwin"
GOINSECURE=""
GOMODCACHE="/Users/korniltsev/go/pkg/mod"
GONOPROXY=""
GONOSUMDB=""
GOOS="darwin"
GOPATH="/Users/korniltsev/go"
GOPRIVATE=""
GOPROXY="https://proxy.golang.org,direct"
GOROOT="/Users/korniltsev/github/go-darwin-amd64-bootstrap"
GOSUMDB="sum.golang.org"
GOTMPDIR=""
GOTOOLDIR="/Users/korniltsev/github/go-darwin-amd64-bootstrap/pkg/tool/darwin_amd64"
GOVCS=""
GOVERSION="devel go1.21-9222a01e65 Fri Feb 3 04:37:17 2023 +0000"
GCCGO="gccgo"
GOAMD64="v1"
AR="ar"
CC="clang"
CXX="clang++"
CGO_ENABLED="1"
GOMOD="/Users/korniltsev/github/go/src/go.mod"
GOWORK=""
CGO_CFLAGS="-O2 -g"
CGO_CPPFLAGS=""
CGO_CXXFLAGS="-O2 -g"
CGO_FFLAGS="-O2 -g"
CGO_LDFLAGS="-O2 -g"
PKG_CONFIG="pkg-config"
GOGCCFLAGS="-fPIC -arch x86_64 -m64 -pthread -fno-caret-diagnostics -Qunused-arguments -fmessage-length=0 -fdebug-prefix-map=/var/folders/2t/v1n4q5yj48315c_ccftr_d_c0000gn/T/go-build2988258767=/tmp/go-build -gno-record-gcc-switches -fno-common"

What did you do?

I noticed an inconsistency in handling inline wrapper functions between runtime_expandFinalInlineFrame and gentraceback.
gentraceback ignores a wrapper function with an inlined function and runtime_expandFinalInlineFrame does not ignore and append to stacktrace. Because of that profileBuilder.appendLocsForStack may emit different locations for exactly the same stack, depending on the order of processed records. For example if a builder sees a wrapped function for the first time as a last item in the stack, it will be expanded with an extra pc of a wrapped function and emit a location with two functions. At the same time if a builder sees a wrapped function for the first time in the middle of the stack, it will emit a location with one function.
In order to reproduce the issue with pprof profiles you need to have a profile sample with a stacktrace ending(truncated) with a wrapper function(for example a heap profile with a stack[31] pointing to a wrapped inlined function).
An easier way to reproduce the inconsistency calling runtime_expandFinalInlineFrame directly:
https://go.dev/play/p/FW8j4zXCrqN

What did you expect to see?

======== stack ========
108a6f3 runtime.Callers
108a6dd main.stackHandler.handle
108a0d2 main.main
1031127 runtime.main
105ad21 runtime.goexit
======== truncated ========
108a6f3 runtime.Callers
108a6dd main.stackHandler.handle
======== expanded ========
108a6f3 runtime.Callers
108a6dd main.stackHandler.handle

What did you see instead?

======== stack ========
108a6d3 runtime.Callers
108a6bd main.stackHandler.handle
108a0b2 main.main
1031127 runtime.main
105ad01 runtime.goexit
======== truncated ========
108a6d3 runtime.Callers
108a6bd main.stackHandler.handle
======== expanded ========
108a6d3 runtime.Callers
108a6bd main.stackHandler.handle
108a6b8 main.(*stackHandler).handle

Possible fix

diff --git a/src/runtime/symtab.go b/src/runtime/symtab.go
index dead27e5f2..da83fd93ea 100644
--- a/src/runtime/symtab.go
+++ b/src/runtime/symtab.go
@@ -230,7 +230,11 @@ func runtime_expandFinalInlineFrame(stk []uintptr) []uintptr {
        }

        // N.B. we want to keep the last parentPC which is not inline.
-       stk = append(stk, pc)
+       if f.funcID == funcID_wrapper && elideWrapperCalling(lastFuncID) {
+               // Ignore wrapper functions (except when they trigger panics).
+       } else {
+               stk = append(stk, pc)
+       }

        return stk
 }

CC @prattmic

[prattmic]

Thanks, good catch. Would you like to send that patch as a CL yourself?

[mknyszek]

CC @golang/runtime

[cherrymui]

For profile, maybe we want to always include the wrapper frame, so it matches more closely to what actually happened at runtime? Not sure if this can be done easily with the current structure.

[prattmic]

Even if so, runtime_expandFinalInlineFrame would be the wrong play for that policy. runtime_expandFinalInlineFrame is only used on the very last PC in the stack (which might be a truncated inline stack due to the 64 PC limit), not on all PCs.

[cherrymui]

I agree that runtime_expandFinalInlineFrame would be the wrong play. I'm just wondering if we could instead include the wrapper frames consistently.

[gopherbot]

Change https://go.dev/cl/465097 mentions this issue: runtime: skip trailing wrappers in runtime_expandFinalInlineFrame