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 <mknyszek@google.com>
Run-TryBot: Rhys Hiltner <rhys@justin.tv>
Reviewed-by: David Chase <drchase@google.com>
TryBot-Result: Gopher Robot <gobot@golang.org>

1 files changed, 25 insertions, 3 deletions

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},
 }