From 2c0a9884e0dc930c1a3596bc1decf183c8fdcf77 Mon Sep 17 00:00:00 2001 From: Rhys Hiltner Date: Mon, 18 Apr 2022 12:32:37 -0700 Subject: runtime: add CPU samples to execution trace When the CPU profiler and execution tracer are both active, report the CPU profile samples in the execution trace data stream. Include only samples that arrive on the threads known to the runtime, but include them even when running g0 (such as near the scheduler) or if there's no P (such as near syscalls). Render them in "go tool trace" as instantaneous events. For #16895 Change-Id: I0aa501a7b450c971e510961c0290838729033f7f Reviewed-on: https://go-review.googlesource.com/c/go/+/400795 Reviewed-by: Michael Knyszek Run-TryBot: Rhys Hiltner Reviewed-by: David Chase TryBot-Result: Gopher Robot --- src/internal/trace/order.go | 6 ++++++ src/internal/trace/parser.go | 28 +++++++++++++++++++++++++--- 2 files changed, 31 insertions(+), 3 deletions(-) (limited to 'src/internal/trace') diff --git a/src/internal/trace/order.go b/src/internal/trace/order.go index 36ed58d675..07a6e13ffe 100644 --- a/src/internal/trace/order.go +++ b/src/internal/trace/order.go @@ -52,6 +52,12 @@ const ( // incorrect (condition observed on some machines). func order1007(m map[int][]*Event) (events []*Event, err error) { pending := 0 + // The ordering of CPU profile sample events in the data stream is based on + // when each run of the signal handler was able to acquire the spinlock, + // with original timestamps corresponding to when ReadTrace pulled the data + // off of the profBuf queue. Re-sort them by the timestamp we captured + // inside the signal handler. + sort.Stable(eventList(m[ProfileP])) var batches []*eventBatch for _, v := range m { pending += len(v) diff --git a/src/internal/trace/parser.go b/src/internal/trace/parser.go index 254f20137b..8c74196ddf 100644 --- a/src/internal/trace/parser.go +++ b/src/internal/trace/parser.go @@ -75,6 +75,7 @@ const ( NetpollP // depicts network unblocks SyscallP // depicts returns from syscalls GCP // depicts GC state + ProfileP // depicts recording of CPU profile samples ) // ParseResult is the result of Parse. @@ -150,7 +151,7 @@ func readTrace(r io.Reader) (ver int, events []rawEvent, strings map[uint64]stri return } switch ver { - case 1005, 1007, 1008, 1009, 1010, 1011: + case 1005, 1007, 1008, 1009, 1010, 1011, 1019: // Note: When adding a new version, add canned traces // from the old version to the test suite using mkcanned.bash. break @@ -448,8 +449,27 @@ func parseEvents(ver int, rawEvents []rawEvent, strings map[uint64]string) (even case EvUserLog: // e.Args 0: taskID, 1:keyID, 2: stackID e.SArgs = []string{strings[e.Args[1]], raw.sargs[0]} + case EvCPUSample: + e.Ts = int64(e.Args[0]) + e.P = int(e.Args[1]) + e.G = e.Args[2] + e.Args[0] = 0 + } + switch raw.typ { + default: + batches[lastP] = append(batches[lastP], e) + case EvCPUSample: + // Most events are written out by the active P at the exact + // moment they describe. CPU profile samples are different + // because they're written to the tracing log after some delay, + // by a separate worker goroutine, into a separate buffer. + // + // We keep these in their own batch until all of the batches are + // merged in timestamp order. We also (right before the merge) + // re-sort these events by the timestamp captured in the + // profiling signal handler. + batches[ProfileP] = append(batches[ProfileP], e) } - batches[lastP] = append(batches[lastP], e) } } if len(batches) == 0 { @@ -1058,7 +1078,8 @@ const ( EvUserTaskEnd = 46 // end of task [timestamp, internal task id, stack] EvUserRegion = 47 // trace.WithRegion [timestamp, internal task id, mode(0:start, 1:end), stack, name string] EvUserLog = 48 // trace.Log [timestamp, internal id, key string id, stack, value string] - EvCount = 49 + EvCPUSample = 49 // CPU profiling sample [timestamp, stack, real timestamp, real P id (-1 when absent), goroutine id] + EvCount = 50 ) var EventDescriptions = [EvCount]struct { @@ -1117,4 +1138,5 @@ var EventDescriptions = [EvCount]struct { EvUserTaskEnd: {"UserTaskEnd", 1011, true, []string{"taskid"}, nil}, EvUserRegion: {"UserRegion", 1011, true, []string{"taskid", "mode", "typeid"}, []string{"name"}}, EvUserLog: {"UserLog", 1011, true, []string{"id", "keyid"}, []string{"category", "message"}}, + EvCPUSample: {"CPUSample", 1019, true, []string{"ts", "p", "g"}, nil}, } -- cgit v1.3