From 7b1f8b62be5f4901404071ddc7160217a60c9810 Mon Sep 17 00:00:00 2001 From: Rhys Hiltner Date: Wed, 4 May 2022 07:44:50 -0700 Subject: [PATCH] runtime: prefer curg for execution trace profile The CPU profiler adds goroutine labels to its samples based on getg().m.curg. That allows the profile to correctly attribute work that the runtime does on behalf of that goroutine on the M's g0 stack via systemstack calls, such as using runtime.Callers to record the call stack. Those labels also cover work on the g0 stack via mcall. When the active goroutine calls runtime.Gosched, it will receive attribution of its share of the scheduler work necessary to find the next runnable goroutine. The execution tracer's attribution of CPU samples to specific goroutines should match. When curg is set, attribute the CPU samples to that goroutine's ID. Fixes #52693 Change-Id: Ic9af92e153abd8477559e48bc8ebaf3739527b94 Reviewed-on: https://go-review.googlesource.com/c/go/+/404055 Reviewed-by: Michael Knyszek Reviewed-by: Bryan Mills Run-TryBot: Rhys Hiltner TryBot-Result: Gopher Robot --- src/runtime/proc.go | 6 +++- src/runtime/trace/trace_test.go | 63 +++++++++++++++++++++++++-------- 2 files changed, 53 insertions(+), 16 deletions(-) diff --git a/src/runtime/proc.go b/src/runtime/proc.go index 427699e41d..06e5538964 100644 --- a/src/runtime/proc.go +++ b/src/runtime/proc.go @@ -4596,11 +4596,15 @@ func sigprof(pc, sp, lr uintptr, gp *g, mp *m) { } cpuprof.add(tagPtr, stk[:n]) + gprof := gp var pp *p if gp != nil && gp.m != nil { + if gp.m.curg != nil { + gprof = gp.m.curg + } pp = gp.m.p.ptr() } - traceCPUSample(gp, pp, stk[:n]) + traceCPUSample(gprof, pp, stk[:n]) } getg().m.mallocing-- } diff --git a/src/runtime/trace/trace_test.go b/src/runtime/trace/trace_test.go index 52a43929b7..b1afd2b8bb 100644 --- a/src/runtime/trace/trace_test.go +++ b/src/runtime/trace/trace_test.go @@ -612,8 +612,9 @@ func TestTraceCPUProfile(t *testing.T) { pprof.Do(ctx, pprof.Labels("tracing", "on"), func(ctx context.Context) { cpuHogger(cpuHog1, &salt1, dur) }) - // Be sure the execution trace's view, when filtered to this goroutine, - // gets many more samples than the CPU profiler when filtered by label. + // Be sure the execution trace's view, when filtered to this goroutine + // via the explicit goroutine ID in each event, gets many more samples + // than the CPU profiler when filtered to this goroutine via labels. cpuHogger(cpuHog1, &salt1, dur) }() @@ -625,8 +626,12 @@ func TestTraceCPUProfile(t *testing.T) { if err != nil { t.Fatalf("failed to parse CPU profile: %v", err) } + // Examine the CPU profiler's view. Filter it to only include samples from + // the single test goroutine. Use labels to execute that filter: they should + // apply to all work done while that goroutine is getg().m.curg, and they + // should apply to no other goroutines. pprofSamples := 0 - pprofStacks := make(map[string]int) // CPU profiler's view, filtered to include the label + pprofStacks := make(map[string]int) for _, s := range prof.Sample { if s.Label["tracing"] != nil { samples := int(s.Value[0]) @@ -645,8 +650,13 @@ func TestTraceCPUProfile(t *testing.T) { t.Skipf("CPU profile did not include any samples while tracing was active\n%s", prof) } + // Examine the execution tracer's view of the CPU profile samples. Filter it + // to only include samples from the single test goroutine. Use the goroutine + // ID that was recorded in the events: that should reflect getg().m.curg, + // same as the profiler's labels (even when the M is using its g0 stack). + totalTraceSamples := 0 traceSamples := 0 - traceStacks := make(map[string]int) // Execution tracer's view, filtered to this goroutine + traceStacks := make(map[string]int) events, _ := parseTrace(t, buf) var hogRegion *trace.Event for _, ev := range events { @@ -661,32 +671,51 @@ func TestTraceCPUProfile(t *testing.T) { t.Fatalf("execution trace did not close cpuHogger region") } for _, ev := range events { - if ev.Type == trace.EvCPUSample && ev.G == hogRegion.G { - traceSamples++ - var fns []string - for _, frame := range ev.Stk { - if frame.Fn != "runtime.goexit" { - fns = append(fns, fmt.Sprintf("%s:%d", frame.Fn, frame.Line)) + if ev.Type == trace.EvCPUSample { + totalTraceSamples++ + if ev.G == hogRegion.G { + traceSamples++ + var fns []string + for _, frame := range ev.Stk { + if frame.Fn != "runtime.goexit" { + fns = append(fns, fmt.Sprintf("%s:%d", frame.Fn, frame.Line)) + } } + stack := strings.Join(fns, " ") + traceStacks[stack]++ } - stack := strings.Join(fns, " ") - traceStacks[stack]++ } } + + // The execution trace may drop CPU profile samples if the profiling buffer + // overflows. Based on the size of profBufWordCount, that takes a bit over + // 1900 CPU samples or 19 thread-seconds at a 100 Hz sample rate. If we've + // hit that case, then we definitely have at least one full buffer's worth + // of CPU samples, so we'll call that success. + overflowed := totalTraceSamples >= 1900 if traceSamples < pprofSamples { - t.Errorf("exectution trace did not include all CPU profile samples; %d in profile, %d in trace", pprofSamples, traceSamples) + t.Logf("exectution trace did not include all CPU profile samples; %d in profile, %d in trace", pprofSamples, traceSamples) + if !overflowed { + t.Fail() + } } for stack, traceSamples := range traceStacks { pprofSamples := pprofStacks[stack] delete(pprofStacks, stack) if traceSamples < pprofSamples { - t.Errorf("execution trace did not include all CPU profile samples for stack %q; %d in profile, %d in trace", + t.Logf("execution trace did not include all CPU profile samples for stack %q; %d in profile, %d in trace", stack, pprofSamples, traceSamples) + if !overflowed { + t.Fail() + } } } for stack, pprofSamples := range pprofStacks { - t.Errorf("CPU profile included %d samples at stack %q not present in execution trace", pprofSamples, stack) + t.Logf("CPU profile included %d samples at stack %q not present in execution trace", pprofSamples, stack) + if !overflowed { + t.Fail() + } } if t.Failed() { @@ -726,6 +755,10 @@ func cpuHog1(x int) int { func cpuHog0(x, n int) int { foo := x for i := 0; i < n; i++ { + if i%1000 == 0 { + // Spend time in mcall, stored as gp.m.curg, with g0 running + runtime.Gosched() + } if foo > 0 { foo *= foo } else { -- 2.50.0