Thanks @felixge . What part of the behavior you see is inconsistent with #52674?

Are you able to reproduce the problem with a smaller output file?

Is the pattern consistent across different runs?

Have you looked at the delta between the CPU profile and the execution trace's CPUSample events to see which kinds of samples are missing from the trace? I don't think this one will be fruitful; between 700 and 800 ms, the benchmark is running BenchmarkCodeEncoder so I'd expect the content of the samples to be the same, which is evidence against the samples' content somehow causing them to be dropped.

I see no CPUSample events between 0.878 seconds and 7.773 seconds, so it's even a bit worse than your screenshot shows. The additional-row spans on Proc 0 near 5.5 seconds are MARK ASSIST, SWEEP, and STW.

The execution trace includes 2094 CPUSample events leading up to the gap at 0.878–7.773 seconds. Spot-checking several of those, they seem to have very deep call stacks, often at or near the 64-frame limit. It seems likely that this is filling the profBuf that we use for the execution tracer's CPU profile samples, as described in #52674 (a bit more than 1900 samples).

$ go tool trace -d ~/Downloads/json.trace | grep CPUSample > /tmp/cpuse

$ cat /tmp/cpuse | awk '{print int($1/100e6),$1/1e6}' | grep -C 4 '^8 ' | tail
7 717.821
7 717.823
7 717.824
7 721.825
8 877.786
77 7773.8
77 7773.8
77 7773.8
77 7773.81

$ cat /tmp/cpuse | awk '{if ($1<1e9) {print $0}}' | wc -l 
    2094

Thanks @felixge . What part of the behavior you see is inconsistent with #52674?

My understanding of #52674 is that samples could be dropped if trace buffers are not being flushed often enough. I could imagine this to happen here, but I wouldn't expect the problem to last for so many seconds given that the workload is causing non-stop trace activity. But maybe I'm overestimating the amount of trace buffers that would be flushed from that.

Other than that I have no strong reason to believe this is not caused by #52674 . If that's the root cause, then this issue could be seen as a "real world" example of the problem.

Are you able to reproduce the problem with a smaller output file?

No, but I haven't tried very hard.

Is the pattern consistent across different runs?

Yeah, it seems pretty consistent between runs for me.

Have you looked at the delta between the CPU profile and the execution trace's CPUSample events to see which kinds of samples are missing from the trace?

I haven't. Is there a way to extract a CPU pprof from a trace?

I don't think this one will be fruitful; between 700 and 800 ms, the benchmark is running BenchmarkCodeEncoder so I'd expect the content of the samples to be the same, which is evidence against the samples' content somehow causing them to be dropped.

Makes sense.

I see no CPUSample events between 0.878 seconds and 7.773 seconds, so it's even a bit worse than your screenshot shows. The additional-row spans on Proc 0 near 5.5 seconds are MARK ASSIST, SWEEP, and STW.

Ack.

The execution trace includes 2094 CPUSample events leading up to the gap at 0.878–7.773 seconds. Spot-checking several of those, they seem to have very deep call stacks, often at or near the 64-frame limit.

Yeah, some benchmarks are definitely creating very deep stacks. But we'd expect those to be truncated, not dropped, if they exceed the 64 frame limit, right?

It seems likely that this is filling the profBuf that we use for the execution tracer's CPU profile samples, as described in #52674 (a bit more than 1900 samples).

Ok, maybe that's what's happening after all.

$ go tool trace -d ~/Downloads/json.trace | grep CPUSample > /tmp/cpuse

TIL about -d 🙈 - thanks 🙇.

$ cat /tmp/cpuse | awk '{print int($1/100e6),$1/1e6}' | grep -C 4 '^8 ' | tail
7 717.821
7 717.823
7 717.824
7 721.825
8 877.786
77 7773.8
77 7773.8
77 7773.8
77 7773.81

$ cat /tmp/cpuse | awk '{if ($1<1e9) {print $0}}' | wc -l 
    2094

Nice analysis. So based on this, you think this is probably caused by #52674 - right?

Out of curiosity I added a println("empty") here:

And seem to get one or more consistently during BenchmarkMarshalBytes. Examples:

BenchmarkMarshalBytes/32
empty
BenchmarkMarshalBytes/32-8       	13310040	        91.08 ns/op

BenchmarkMarshalBytes/32
empty
BenchmarkMarshalBytes/32-8       	13002902	        88.95 ns/op

BenchmarkMarshalBytes/32
empty
empty
empty
BenchmarkMarshalBytes/32-8       	13341460	        86.97 ns/op

That's pretty early on in the run for me. I tried running the whole set of benchmarks once or twice but didn't see it pop up for any others.

In my last full-set run I got two empties:

BenchmarkMarshalBytes/32
empty
empty
BenchmarkMarshalBytes/32-8       	13634491	        86.77 ns/op

And looking at the flamescope I see:

With an empty run a few seconds in. This is confirmed with some trace to sqlite bits I'm playing with (here, which also has the query I used to generate the flamescope data inspired by you, @felixge, thanks!):

sqlite> select round(ts/1e9, 1), count(*) from events where type='CPUSample' and ts/1e9 between 3 and 5 group by 1 order by 1;
┌──────────────────┬──────────┐
│ round(ts/1e9, 1) │ count(*) │
├──────────────────┼──────────┤
│ 3.0              │ 31       │
│ 3.1              │ 61       │
│ 3.2              │ 59       │
│ 3.3              │ 62       │
│ 3.4              │ 61       │
│ 3.5              │ 57       │
│ 3.6              │ 53       │
│ 3.7              │ 1        │
│ 4.8              │ 5        │
│ 4.9              │ 9        │
│ 5.0              │ 5        │
└──────────────────┴──────────┘

cc @golang/runtime @mknyszek @prattmic @dvyukov

Should this be deduplicated with #52674?

Should this be deduplicated with #52674?

Yes. Based on the discussion above, I think we can close this one as a dupe and maybe update the description of #52674 to link to this issue for a concrete example?

SGTM! Closing as duplicate of #52674.