runtime/trace: TestTraceCPUProfile fails intermittently starting 2022-05-03

[rhysh]

The failures I've seen so far are on android/386 and openbsd/amd64. Both show a sample starting in runtime.mcall (which I think is important to the bug) and leading to how a preemption is reported in the execution trace (which I think is less important). I'll take a look at what mcall means for getg(), and getg().m.p.ptr().

CC @bcmills (you'll see these when you do the next dashboard triage).

$ greplogs -e TestTraceCPUProfile -dashboard -l -since 2022-05-02 -md

2022-05-03T21:11:24-23f1325/android-386-emu
2022-05-03T21:11:24-23f1325/openbsd-amd64-70

--- FAIL: TestTraceCPUProfile (0.31s)
    trace_test.go:689: CPU profile included 1 samples at stack "runtime.step:1122 runtime.pcvalue:918 runtime.funcspdelta:1041 runtime.gentraceback:191 runtime.gcallers:920 runtime.traceStackID:791 runtime.traceEventLocked:667 runtime.traceEvent:601 runtime.traceGoPreempt:1285 runtime.gopreempt_m:3396 runtime.mcall:325" not present in execution trace
    trace_test.go:693: execution trace CPU samples:
    trace_test.go:695: 8: "runtime/trace_test.cpuHog0:732 runtime/trace_test.cpuHog1:723 runtime/trace_test.cpuHogger:710 runtime/trace_test.TestTraceCPUProfile.func1.1:613 runtime/pprof.Do:40 runtime/trace_test.TestTraceCPUProfile.func1:612 runtime/trace_test.TestTraceCPUProfile:618 testing.tRunner:1449"
    trace_test.go:695: 10: "runtime/trace_test.cpuHog0:732 runtime/trace_test.cpuHog1:723 runtime/trace_test.cpuHogger:710 runtime/trace_test.TestTraceCPUProfile.func1:617 runtime/trace_test.TestTraceCPUProfile:618 testing.tRunner:1449"

--- FAIL: TestTraceCPUProfile (0.32s)
    trace_test.go:689: CPU profile included 1 samples at stack "runtime.gentraceback:154 runtime.gcallers:920 runtime.traceStackID:791 runtime.traceEventLocked:667 runtime.traceEvent:601 runtime.traceGoPreempt:1285 runtime.gopreempt_m:3396 runtime.mcall:448" not present in execution trace
    trace_test.go:693: execution trace CPU samples:
    trace_test.go:695: 9: "runtime/trace_test.cpuHog0:732 runtime/trace_test.cpuHog1:723 runtime/trace_test.cpuHogger:710 runtime/trace_test.TestTraceCPUProfile.func1.1:613 runtime/pprof.Do:40 runtime/trace_test.TestTraceCPUProfile.func1:612 runtime/trace_test.TestTraceCPUProfile:618 testing.tRunner:1449"
    trace_test.go:695: 10: "runtime/trace_test.cpuHog0:732 runtime/trace_test.cpuHog1:723 runtime/trace_test.cpuHogger:710 runtime/trace_test.TestTraceCPUProfile.func1:617 runtime/trace_test.TestTraceCPUProfile:618 testing.tRunner:1449"

[bcmills]

Since there is relatively little overlap between android/386 and openbsd/amd64, I'm assuming that this is likely a platform-independent bug, which makes it a release-blocker for Go 1.19.

(CC @golang/runtime)

[bcmills]

Indeed, it also affects linux/386, which is a first class port.

greplogs -l -e 'FAIL: TestTraceCPUProfile' --since=2022-05-02
2022-05-03T21:11:24-23f1325/android-386-emu
2022-05-03T21:11:24-23f1325/linux-386-longtest
2022-05-03T21:11:24-23f1325/openbsd-amd64-70

In addition to those explicit failures, there was also an index out of range crash while executing the test that may or may not be related (filed as #52704).

[gopherbot]

Change https://go.dev/cl/404055 mentions this issue: runtime: prefer curg for execution trace profile

[bcmills]

greplogs -l -e 'FAIL: TestTraceCPUProfile' --since=2022-05-04
2022-05-05T04:53:27-0e90ba9/linux-arm64-packet
2022-05-05T04:05:43-d544591/openbsd-386-68
2022-05-05T01:33:01-ed462a6/linux-386-clang
2022-05-05T01:33:01-ed462a6/linux-arm64-packet
2022-05-04T21:35:22-aeb933d/android-amd64-emu
2022-05-04T21:35:22-aeb933d/linux-ppc64le-power9osu
2022-05-04T21:35:22-aeb933d/openbsd-386-68
2022-05-04T21:03:31-2f23364/linux-amd64-buster
2022-05-04T21:03:31-2f23364/windows-386-2008
2022-05-04T20:30:17-e1e056f/solaris-amd64-oraclerel
2022-05-04T20:20:28-fbb47e8/linux-386-longtest
2022-05-04T20:20:28-fbb47e8/solaris-amd64-oraclerel
2022-05-04T20:20:28-fbb47e8/windows-amd64-2008
2022-05-04T20:20:27-ab0bb52/linux-amd64-nocgo
2022-05-04T20:20:27-ab0bb52/linux-mips64le-mengzhuo
2022-05-04T18:51:19-1b0f9fb/freebsd-amd64-race
2022-05-04T18:51:19-1b0f9fb/openbsd-386-70
2022-05-04T18:49:50-c570f0e/linux-ppc64-buildlet
2022-05-04T16:41:22-265b5fd/openbsd-386-70
2022-05-04T16:41:22-265b5fd/windows-386-2012
2022-05-04T14:17:20-87cf92e/windows-amd64-race
2022-05-04T13:38:32-93218ea/windows-amd64-longtest

[bcmills]

@rhysh, this test has a very high failure rate — please aim to have it resolved today.

(If there isn't a quick solution to the underlying problem, either roll back the changes that introduced or exposed it, or add call to testenv.SkipFlaky to the test until it can be fixed.)

[rhysh]

Of the results for greplogs -dashboard -l -e 'TestTraceCPUProfile' --since=2022-05-05 -md, four are recent enough to include the attempted fix at 7b1f8b6.

All four of those claim that the CPU profile included a stack with a doubled frame, and in all four of those the doubling is runtime.pcvalue:932 runtime.pcvalue:932. In all four, the execution trace's view has that same stack but with only one layer of runtime.pcvalue:932. That makes me wonder about a failure mode similar to #50996 -- meaning the execution tracer's new profiling stacks are correct, and the view from the existing runtime/pprof profiler is what's broken.

---

2022-05-06T04:25:34-f87e28d/openbsd-arm-jsing

trace_test.go:715: CPU profile included 1 samples at stack "runtime.fastrand:148 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:265" not present in execution trace

2022-05-05T23:41:16-f99511d/linux-mips64le-rtrk

trace_test.go:715: CPU profile included 1 samples at stack "runtime.fastrand:135 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:142" not present in execution trace

2022-05-05T22:53:14-86536b9/linux-mips64le-rtrk

trace_test.go:715: CPU profile included 1 samples at stack "runtime.fastrand:136 runtime.fastrandn:157 runtime.pcvalue:932 runtime.pcvalue:932 runtime.pcdatavalue:1076 runtime.gentraceback:364 runtime.gcallers:920 runtime.traceStackID:792 runtime.traceEventLocked:667 runtime.traceEvent:601 runtime.traceGoSched:1280 runtime.gosched_m:3376 runtime.mcall:142" not present in execution trace

2022-05-05T18:48:17-e94fe09/linux-386-longtest

trace_test.go:715: CPU profile included 1 samples at stack "runtime.fastrand:148 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:325" not present in execution trace

---

The following all predate the attempted fix at 7b1f8b6, so don't indicate an existing problem.
2022-05-05T15:43:29-fdb640b/openbsd-arm64-jsing
2022-05-05T15:43:29-fdb640b/windows-amd64-race
2022-05-05T04:53:27-0e90ba9/darwin-amd64-race
2022-05-05T04:53:27-0e90ba9/linux-arm64-packet
2022-05-05T04:53:27-0e90ba9/linux-mips64-rtrk
2022-05-05T04:05:43-d544591/openbsd-386-68
2022-05-05T04:05:43-d544591/windows-amd64-longtest
2022-05-05T01:33:11-0bd7408/android-arm-corellium
2022-05-05T01:33:01-ed462a6/linux-386-clang
2022-05-05T01:33:01-ed462a6/linux-arm64-packet

[gopherbot]

Change https://go.dev/cl/404698 mentions this issue: runtime/trace: mark new CPU profile test as flaky