runtime/trace: TestTraceCPUProfile failures with `runtime._System` sample not present in execution trace

[bcmills]

--- FAIL: TestTraceCPUProfile (1.57s)
    trace_test.go:715: CPU profile included 1 samples at stack ":0 runtime._System:4491" not present in execution trace

greplogs -l -e 'runtime\._System:\d+" not present in execution trace'
2022-06-06T19:55:16-7271a0a/android-amd64-emu
2022-05-05T15:43:29-fdb640b/windows-amd64-race

TestTraceCPUProfile was previously believed to have been fixed in #52693 (attn @rhysh @cherrymui @prattmic; CC @golang/runtime).

[bcmills]

Marking as release-blocker for Go 1.19 because this failure mode affects windows/amd64 (a first-class port).

[prattmic]

The missing samples are both runtime._System stacks, so my first thought was that we simply don't include samples missing a P in the trace. However, it looks like we do.

Perhaps this is more mundane: the test disables tracing before CPU profiling, so there is a race between disabling tracing and disabling profiling during which a sample could end up in the pprof profile but not the trace.

@rhysh perhaps we should only complain about mismatched cpuHogger samples, which should be strictly bound inside tracing and profiling being enabled?

[rhysh]

In the android/amd64 failure: The top-level error message is trace_test.go:715: CPU profile included 1 samples at stack ":0 runtime._System:4491" not present in execution trace. A few lines down in the list of samples that do appear in the execution trace, the log shows trace_test.go:724: 1: "runtime._System:4491". The sample in the raw CPU profile dump is 1 10000000: 25 26 / tracing:[on]. The PC is within the mapping of /system/lib64/libc.so.

In the windows/amd64-race failure: The top-level error message is trace_test.go:689: CPU profile included 1 samples at stack "_ZN6__tsan11ThreadClock7releaseEPNS_19DenseSlabAllocCacheEPNS_9SyncClockE:0 runtime._System:4480" not present in execution trace. There's no mention of runtime._System in the list of CPU samples that the execution trace includes. The sample in the raw CPU profile dump is 1 10000000: 9 10 / tracing:[on]. The function looks like part of the race detector runtime (the CPU profile does not list the mappings).

Calls from runtime._System are inserted by runtime.sigprof when "Normal traceback is impossible or has failed", which then adds the same stk[:n] to both the CPU profile and the execution trace.

The execution tracer and the CPU profiler do their symbolization in rather different ways: a single call to runtime.CallersFrames (the allFrames function in src/runtime/trace.go), or a more involved approach that eventually leads to a separate runtime.CallersFrames call for each single address (the allFrames function in src/runtime/pprof/proto.go). Maybe that explains the difference? These two-frame call stacks are faked by runtime.sigprof, and built in a way that is known to render correctly with the CPU profiler's approach of splitting addresses and symbolizing each separately, and might (I don't know the details of CallersFrames' operation) not deal well with being symbolized as a pair as the new code does.

Should we try to change the execution tracer's profile stacks to include more info on reported callees of runtime._System? Or should it continue to report that as runtime._System calling a non-symbolized function :0 (or, as with the windows/amd64-race failure, to drop the sample), with the test changing to ignore samples that show a root of runtime._System or the other functions runtime.sigprof uses (runtime._GC, runtime._ExternalCode, and runtime._VDSO)? I'm currently in favor of adding code to the test that special-cases those generated stacks.

I don't think it's the mundane race, @prattmic : the test filters the CPU profile samples down to the ones that include the "tracing:[on]" label, which has a fairly well-controlled start and end time. That should make the order of the Start/Stop function calls not matter.

[prattmic]

I'm currently in favor of adding code to the test that special-cases those generated stacks.

By "special-case" in the test, you mean ignore, right? I think that is fine. It would be nice to get the execution trace symbolization to match up with pprof a bit better in the these cases, but I certainly don't think it is high priority or something that needs to be in 1.19.

the test filters the CPU profile samples down to the ones that include the "tracing:[on]" label, which has a fairly well-controlled start and end time.

Apologies, I did not pay close enough attention and missed that.

[gopherbot]

Change https://go.dev/cl/413457 mentions this issue: runtime/trace: ignore fallback stacks in test