runtime/pprof: frequent failures in TestCPUProfileRecursion as of CL 384239 #51568
Description
The earliest failure this year is at CL 384239 (for #50996), which appears to be closely related.
--- FAIL: TestCPUProfileRecursion (0.20s)
pprof_test.go:524: total 4 CPU profile samples collected:
1: 0x100143130 (runtime/pprof.inlinedCallee:304 runtime/pprof.recursionCallee:355) 0x100143167 (runtime/pprof.recursionCallee:356) 0x100143167 (runtime/pprof.recursionCallee:356) 0x1001430b3 (runtime/pprof.recursionCaller:347) 0x1001415ff (runtime/pprof.cpuHogger:41) 0x100142dbf (runtime/pprof.TestCPUProfileRecursion.func1:329) 0x10014354f (runtime/pprof.testCPUProfile:451) 0x100142e7f (runtime/pprof.TestCPUProfileRecursion:328) 0x1000d3b17 (testing.tRunner:1439) labels: map[]
1: 0x10014313c (runtime/pprof.cpuHog0:61 runtime/pprof.inlinedCallee:304 runtime/pprof.recursionCallee:355 runtime/pprof.recursionCallee:355) 0x100143167 (runtime/pprof.recursionCallee:356) 0x1001430b3 (runtime/pprof.recursionCaller:347) 0x1001415ff (runtime/pprof.cpuHogger:41) 0x100142dbf (runtime/pprof.TestCPUProfileRecursion.func1:329) 0x10014354f (runtime/pprof.testCPUProfile:451) 0x100142e7f (runtime/pprof.TestCPUProfileRecursion:328) 0x1000d3b17 (testing.tRunner:1439) labels: map[]
1: 0x100143150 (runtime/pprof.cpuHog0:64 runtime/pprof.inlinedCallee:304 runtime/pprof.recursionCallee:355 runtime/pprof.recursionCallee:355) 0x100143167 (runtime/pprof.recursionCallee:356) 0x1001430b3 (runtime/pprof.recursionCaller:347) 0x1001415ff (runtime/pprof.cpuHogger:41) 0x100142dbf (runtime/pprof.TestCPUProfileRecursion.func1:329) 0x10014354f (runtime/pprof.testCPUProfile:451) 0x100142e7f (runtime/pprof.TestCPUProfileRecursion:328) 0x1000d3b17 (testing.tRunner:1439) labels: map[]
1: 0x100143150 (runtime/pprof.cpuHog0:64 runtime/pprof.inlinedCallee:304 runtime/pprof.recursionCallee:355 runtime/pprof.recursionCallee:355) 0x100143167 (runtime/pprof.recursionCallee:356) 0x100143167 (runtime/pprof.recursionCallee:356) 0x1001430b3 (runtime/pprof.recursionCaller:347) 0x1001415ff (runtime/pprof.cpuHogger:41) 0x100142dbf (runtime/pprof.TestCPUProfileRecursion.func1:329) 0x10014354f (runtime/pprof.testCPUProfile:451) 0x100142e7f (runtime/pprof.TestCPUProfileRecursion:328) 0x1000d3b17 (testing.tRunner:1439) labels: map[]
pprof_test.go:595: runtime/pprof.inlinedCallee: 4
pprof_test.go:595: runtime/pprof.recursionCallee: 4
pprof_test.go:595: runtime/pprof.recursionCaller: 4
pprof_test.go:341: want at most one recursionCaller or recursionCallee in one Location, got a violating Location (index: 8):
PeriodType: cpu nanoseconds
Period: 10000000
Time: 2022-03-09 10:56:26.724549 -0600 CST
Duration: 200.689ms
Samples:
samples/count cpu/nanoseconds
1 10000000: 1 2 2 3 4 5 6 7 8
1 10000000: 9 2 3 4 5 6 7 8
1 10000000: 10 2 3 4 5 6 7 8
1 10000000: 10 2 2 3 4 5 6 7 8
Locations
1: 0x100143130 M=1 runtime/pprof.inlinedCallee /ramdisk8GB/workdir-host-aix-ppc64-osuosl/go/src/runtime/pprof/pprof_test.go:304 s=0
runtime/pprof.recursionCallee /ramdisk8GB/workdir-host-aix-ppc64-osuosl/go/src/runtime/pprof/pprof_test.go:355 s=0
2: 0x100143167 M=1 runtime/pprof.recursionCallee /ramdisk8GB/workdir-host-aix-ppc64-osuosl/go/src/runtime/pprof/pprof_test.go:356 s=0
3: 0x1001430b3 M=1 runtime/pprof.recursionCaller /ramdisk8GB/workdir-host-aix-ppc64-osuosl/go/src/runtime/pprof/pprof_test.go:347 s=0
4: 0x1001415ff M=1 runtime/pprof.cpuHogger /ramdisk8GB/workdir-host-aix-ppc64-osuosl/go/src/runtime/pprof/pprof_test.go:41 s=0
5: 0x100142dbf M=1 runtime/pprof.TestCPUProfileRecursion.func1 /ramdisk8GB/workdir-host-aix-ppc64-osuosl/go/src/runtime/pprof/pprof_test.go:329 s=0
6: 0x10014354f M=1 runtime/pprof.testCPUProfile /ramdisk8GB/workdir-host-aix-ppc64-osuosl/go/src/runtime/pprof/pprof_test.go:451 s=0
7: 0x100142e7f M=1 runtime/pprof.TestCPUProfileRecursion /ramdisk8GB/workdir-host-aix-ppc64-osuosl/go/src/runtime/pprof/pprof_test.go:328 s=0
8: 0x1000d3b17 M=1 testing.tRunner /ramdisk8GB/workdir-host-aix-ppc64-osuosl/go/src/testing/testing.go:1439 s=0
9: 0x10014313c M=1 runtime/pprof.cpuHog0 /ramdisk8GB/workdir-host-aix-ppc64-osuosl/go/src/runtime/pprof/pprof_test.go:61 s=0
runtime/pprof.inlinedCallee /ramdisk8GB/workdir-host-aix-ppc64-osuosl/go/src/runtime/pprof/pprof_test.go:304 s=0
runtime/pprof.recursionCallee /ramdisk8GB/workdir-host-aix-ppc64-osuosl/go/src/runtime/pprof/pprof_test.go:355 s=0
runtime/pprof.recursionCallee /ramdisk8GB/workdir-host-aix-ppc64-osuosl/go/src/runtime/pprof/pprof_test.go:355 s=0
10: 0x100143150 M=1 runtime/pprof.cpuHog0 /ramdisk8GB/workdir-host-aix-ppc64-osuosl/go/src/runtime/pprof/pprof_test.go:64 s=0
runtime/pprof.inlinedCallee /ramdisk8GB/workdir-host-aix-ppc64-osuosl/go/src/runtime/pprof/pprof_test.go:304 s=0
runtime/pprof.recursionCallee /ramdisk8GB/workdir-host-aix-ppc64-osuosl/go/src/runtime/pprof/pprof_test.go:355 s=0
runtime/pprof.recursionCallee /ramdisk8GB/workdir-host-aix-ppc64-osuosl/go/src/runtime/pprof/pprof_test.go:355 s=0
Mappings
1: 0x0/0x0/0x0 [FN]
FAIL
FAIL runtime/pprof 9.934s
greplogs --dashboard -md -l -e 'FAIL: TestCPUProfileRecursion' --since=2022-01-01
2022-03-09T16:08:24-7160e32/aix-ppc64
2022-03-09T06:51:37-c6d9b38/aix-ppc64
2022-03-09T06:51:37-c6d9b38/darwin-amd64-12_0
2022-03-09T06:51:37-c6d9b38/linux-arm64-packet
2022-03-09T06:51:37-c6d9b38/linux-ppc64le-power9osu
2022-03-09T06:51:37-c6d9b38/openbsd-arm64-jsing
2022-03-09T05:28:28-1045faa/aix-ppc64
2022-03-09T05:28:28-1045faa/linux-ppc64le-power9osu
2022-03-09T05:28:28-1045faa/openbsd-arm64-jsing
2022-03-08T23:18:30-20d333b/linux-ppc64le-power9osu
2022-03-08T23:18:30-20d333b/openbsd-arm64-jsing
2022-03-08T22:23:42-0add064/aix-ppc64
2022-03-08T22:23:42-0add064/openbsd-arm64-jsing
2022-03-08T22:10:32-4469557/linux-ppc64le-power9osu
2022-03-08T21:35:38-dbbe4cc/openbsd-arm64-jsing
2022-03-08T21:35:32-67f1a43/aix-ppc64
2022-03-08T21:35:32-67f1a43/linux-ppc64le-power9osu
2022-03-08T21:35:32-67f1a43/openbsd-arm64-jsing
2022-03-08T21:23:02-bd77d6e/aix-ppc64