runtime/pprof: non-self-recursive function (runtime.pcvalue) shows self-calls

[rhysh]

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

This is broken in tip, working in go1.18.1

Does this issue reproduce with the latest release?

No, working in go1.18.1

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

go env Output

$ go env
GO111MODULE=""
GOARCH="arm64"
GOBIN=""
GOCACHE="/Users/rhys/Library/Caches/go-build"
GOENV="/Users/rhys/Library/Application Support/go/env"
GOEXE=""
GOEXPERIMENT=""
GOFLAGS=""
GOHOSTARCH="arm64"
GOHOSTOS="darwin"
GOINSECURE=""
GOMODCACHE="/Users/rhys/go/pkg/mod"
GONOPROXY="*"
GONOSUMDB="*"
GOOS="darwin"
GOPATH="/Users/rhys/go"
GOPRIVATE="*"
GOPROXY="direct"
GOROOT="/usr/local/go"
GOSUMDB="sum.golang.org"
GOTMPDIR=""
GOTOOLDIR="/usr/local/go/pkg/tool/darwin_arm64"
GOVCS=""
GOVERSION="go1.18.1"
GCCGO="gccgo"
AR="ar"
CC="clang"
CXX="clang++"
CGO_ENABLED="1"
GOMOD="/dev/null"
GOWORK=""
CGO_CFLAGS="-g -O2"
CGO_CPPFLAGS=""
CGO_CXXFLAGS="-g -O2"
CGO_FFLAGS="-g -O2"
CGO_LDFLAGS="-g -O2"
PKG_CONFIG="pkg-config"
GOGCCFLAGS="-fPIC -arch arm64 -pthread -fno-caret-diagnostics -Qunused-arguments -fmessage-length=0 -fdebug-prefix-map=/var/folders/lf/n4ry0qv5639_3z0nhyhy3z7c0000gs/T/go-build4034971770=/tmp/go-build -gno-record-gcc-switches -fno-common"

What did you do?

I added a test to src/runtime/pprof/pprof_test.go for the duplicate runtime.pcvalue entries I saw in #52693.

func TestCPUProfileDupFrameInlining(t *testing.T) {
	var stk [32]uintptr
	matches := matchAndAvoidStacks(stackContains, []string{"runtime.pcvalue"}, avoidFunctions())
	p := testCPUProfile(t, matches, func(dur time.Duration) {
		cpuHogger(func(i int) int {
			_ = runtime.Callers(0, stk[:])
			return i
		}, &salt1, dur)
	})

	for _, sam := range p.Sample {
		var stack []string
		var bad string
		for _, loc := range sam.Location {
			for _, line := range loc.Line {
				name := fmt.Sprintf("%s:%d", line.Function.Name, line.Line)
				if len(stack) != 0 && name == stack[len(stack)-1] {
					bad = name
				}
				stack = append(stack, name)
			}
		}
		if bad != "" {
			t.Logf("found repeated function entry %q in stack %q", bad, stack)
			if strings.HasPrefix(bad, "runtime.pcvalue:") {
				// The profile may show legitimate recursive functions, but we
				// know that runtime.pcvalue does not call itself and so should
				// not appear to in the profile.
				t.Fail()
			}
		}
	}
}

What did you expect to see?

Because runtime.pcvalue does not call itself, the CPU profiler should never indicate that it does.

What did you see instead?

The test fails on the development branch / tip about 25% of the time on my darwin/arm64 machine. (The failures are much less likely in -short mode.) It does not fail with go1.18.1 (passes 60+ times).

found repeated function entry "runtime.pcvalue:932" in stack ["runtime.fastrand:135" "runtime.fastrandn:157" "runtime.pcvalue:932" "runtime.pcvalue:932" "runtime.pcdatavalue:1076" "runtime.gentraceback:364" "runtime.callers.func1:914" "runtime.systemstack:233" "runtime.callers:913" "runtime.Callers:237" "runtime/pprof.TestCPUProfileDupFrameInlining.func1.1:343" "runtime/pprof.cpuHogger:41" "runtime/pprof.TestCPUProfileDupFrameInlining.func1:342" "runtime/pprof.testCPUProfile:497" "runtime/pprof.TestCPUProfileDupFrameInlining:341" "testing.tRunner:1449"]

Maybe this is a recurrence of #50996, or maybe the fix for that broke this behavior? I plan to bisect. CC @prattmic

[rhysh]

Yes, the bisect points to bd77d6e (for #50996) as the cause.

[gopherbot]

Change https://go.dev/cl/404995 mentions this issue: runtime/pprof: fix allFrames cache

[bcmills]

(Just adding some detail for searchability.)

--- FAIL: TestTraceCPUProfile (1.20s)
    trace_test.go:715: CPU profile included 1 samples at stack "runtime.fastrand:136 runtime.fastrandn:157 runtime.pcvalue:932 runtime.pcvalue:932 runtime.funcspdelta:1041 runtime.gentraceback:191 runtime.gcallers:920 runtime.traceStackID:792 runtime.traceEventLocked:667 runtime.traceEvent:601 runtime.traceGoSched:1280 runtime.gosched_m:3376 runtime.mcall:448" not present in execution trace

greplogs -l -e 'runtime\.pcvalue:932 runtime\.pcvalue:932' --since=2022-01-01
2022-05-08T17:19:07-4c565a5/linux-amd64-wsl
2022-05-06T17:37:38-2049649/linux-mips-rtrk
2022-05-06T04:25:34-f87e28d/openbsd-arm-jsing
2022-05-05T23:41:16-f99511d/linux-mips64le-rtrk
2022-05-05T22:53:14-86536b9/linux-mips64le-rtrk
2022-05-05T18:48:17-e94fe09/linux-386-longtest