runtime/pprof: block and mutex profile stacks sometimes have "gowrap" root frames

[nsrip-dd]

Go version

go version go1.23.0 darwin/arm64

Output of go env in your module/workspace:

GO111MODULE=''
GOARCH='arm64'
GOBIN=''
GOCACHE='/Users/nick.ripley/Library/Caches/go-build'
GOENV='/Users/nick.ripley/Library/Application Support/go/env'
GOEXE=''
GOEXPERIMENT=''
GOFLAGS=''
GOHOSTARCH='arm64'
GOHOSTOS='darwin'
GOINSECURE=''
GOMODCACHE='/Users/nick.ripley/go/pkg/mod'
GONOPROXY='redacted'
GONOSUMDB='redacted'
GOOS='darwin'
GOPATH='/Users/nick.ripley/go'
GOPRIVATE='redacted'
GOPROXY='redacted'
GOROOT='/usr/local/go'
GOSUMDB='sum.golang.org'
GOTMPDIR=''
GOTOOLCHAIN='auto'
GOTOOLDIR='/usr/local/go/pkg/tool/darwin_arm64'
GOVCS=''
GOVERSION='go1.23.0'
GODEBUG=''
GOTELEMETRY='local'
GOTELEMETRYDIR='/Users/nick.ripley/Library/Application Support/go/telemetry'
GCCGO='gccgo'
GOARM64='v8.0'
AR='ar'
CC='clang'
CXX='clang++'
CGO_ENABLED='1'
GOMOD='/Users/nick.ripley/sandbox/go/gowrap/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 arm64 -pthread -fno-caret-diagnostics -Qunused-arguments -fmessage-length=0 -ffile-prefix-map=/var/folders/f3/g91d13pd6kd3vdxts_gsgd1r0000gn/T/go-build334561956=/tmp/go-build -gno-record-gcc-switches -fno-common'

What did you do?

Ran the following program:

package main

import (
	"os"
	"runtime"
	"runtime/pprof"
	"sync"
)

func block1(ch chan struct{}, wg *sync.WaitGroup) {
	defer wg.Done()
	ch <- struct{}{}
}

func block2(ch chan struct{}, wg *sync.WaitGroup) {
	defer wg.Done()
	<-ch
}

func main() {
	runtime.SetBlockProfileRate(1)
	ch := make(chan struct{})
	var wg sync.WaitGroup
	wg.Add(2)
	go block1(ch, &wg)
	go block2(ch, &wg)
	wg.Wait()
	pprof.Lookup("block").WriteTo(os.Stdout, 1)
}

Playground link: https://go.dev/play/p/f_80E-mywSz

EDIT: updated playground example that more clearly demonstrates how aggregation
changes with this issue: https://go.dev/play/p/2dMLkn2MOxt

What did you see happen?

I saw a gowrap function in the root frame:

--- contention:
cycles/second=3158102000
352356 1 @ 0x476488 0x4cc711 0x4380eb 0x46f8e1
#	0x476487	sync.(*WaitGroup).Wait+0x47	/usr/local/go-faketime/src/sync/waitgroup.go:118
#	0x4cc710	main.main+0xf0			/tmp/sandbox2366213254/prog.go:27
#	0x4380ea	runtime.main+0x28a		/usr/local/go-faketime/src/runtime/proc.go:272

2512 1 @ 0x406312 0x4cc565 0x4cc785 0x46f8e1
#	0x406311	runtime.chanrecv1+0x11	/usr/local/go-faketime/src/runtime/chan.go:489
#	0x4cc564	main.block2+0x44	/tmp/sandbox2366213254/prog.go:17
#	0x4cc784	main.main.gowrap2+0x24	/tmp/sandbox2366213254/prog.go:26

What did you expect to see?

I thought it would look roughly similar to what it looked like with Go 1.22:

--- contention:
cycles/second=2272924666
384662 1 @ 0x46bea8 0x4b4e91 0x437eeb 0x465641
#	0x46bea7	sync.(*WaitGroup).Wait+0x47	/usr/local/go-faketime/src/sync/waitgroup.go:116
#	0x4b4e90	main.main+0xf0			/tmp/sandbox198902667/prog.go:27
#	0x437eea	runtime.main+0x28a		/usr/local/go-faketime/src/runtime/proc.go:271

4166 1 @ 0x406852 0x4b4ce7 0x465641
#	0x406851	runtime.chanrecv1+0x11	/usr/local/go-faketime/src/runtime/chan.go:442
#	0x4b4ce6	main.block2+0x46	/tmp/sandbox198902667/prog.go:17

This change wasn't intentional, and I think it would affect how stacks from go foo() calls at different call sites are aggregated. Probably changed due to https://go.dev/cl/598515. I'm not sure exactly where main.main.gowrap2 would have come from. The stack for the mutex and block profile gets modified a few times (here and here) and I'm not sure if we're either failing to remove that wrapper or adding it back. We may also need to drop the wrapper frames at sample time.

[gabyhelp]

Related Issues and Documentation

• runtime/pprof: collecting mutex or block profiles add ~100ms of wall time #63078 (closed)
• runtime: MutexProfile has multiple records with equal stack #67548 (closed)
• runtime: async preemption causes short sleep in tickspersecond #63103 (closed)
• runtime/pprof: TestBlockProfile fails on windows #6975 (closed)
• runtime/pprof: collecting a CPU profile takes ~200ms of wall time #63043
• runtime: frame pointer check fails on arm64 for C-to-Go calls #59401
• runtime/pprof: blockprofile test fails in VMs #7696 (closed)
• runtime/pprof: under-samples work on short-lived threads #40435 (closed)
• sync: mutex profiling information is confusing (wrong?) for mutexes with >2 contenders #24877
• runtime: frame pointer unwinding can fail on system goroutines #63630

_{(Emoji vote if this was helpful or unhelpful; more detailed feedback welcome in this discussion.)}

[dmitshur]

CC @golang/runtime.

[gopherbot]

Change https://go.dev/cl/611241 mentions this issue: runtime/pprof: properly handle wrapper frames in block/mutex profiles