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 <[email protected]>
Run-TryBot: Rhys Hiltner <[email protected]>
Reviewed-by: David Chase <[email protected]>
TryBot-Result: Gopher Robot <[email protected]>

Author: rhysh

src/cmd/trace/trace.go

@@ -30,7 +30,6 @@ func init() {
 	http.Handle("/static/", http.FileServer(http.FS(staticContent)))
 }
 
-
 // httpTrace serves either whole trace (goid==0) or trace for goid goroutine.
 func httpTrace(w http.ResponseWriter, r *http.Request) {
 	_, err := parseTrace()
@@ -719,6 +718,11 @@ func generateTrace(params *traceParams, consumer traceConsumer) error {
 			ctx.emitInstant(ev, "task start", "user event")
 		case trace.EvUserTaskEnd:
 			ctx.emitInstant(ev, "task end", "user event")
+		case trace.EvCPUSample:
+			if ev.P >= 0 {
+				// only show in this UI when there's an associated P
+				ctx.emitInstant(ev, "CPU profile sample", "")
+			}
 		}
 		// Emit any counter updates.
 		ctx.emitThreadCounters(ev)

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)

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

src/runtime/cpuprof.go

@@ -19,7 +19,21 @@ import (
 	"unsafe"
 )
 
-const maxCPUProfStack = 64
+const (
+	maxCPUProfStack = 64
+
+	// profBufWordCount is the size of the CPU profile buffer's storage for the
+	// header and stack of each sample, measured in 64-bit words. Every sample
+	// has a required header of two words. With a small additional header (a
+	// word or two) and stacks at the profiler's maximum length of 64 frames,
+	// that capacity can support 1900 samples or 19 thread-seconds at a 100 Hz
+	// sample rate, at a cost of 1 MiB.
+	profBufWordCount = 1 << 17
+	// profBufTagCount is the size of the CPU profile buffer's storage for the
+	// goroutine tags associated with each sample. A capacity of 1<<14 means
+	// room for 16k samples, or 160 thread-seconds at a 100 Hz sample rate.
+	profBufTagCount = 1 << 14
+)
 
 type cpuProfile struct {
 	lock mutex
@@ -70,7 +84,7 @@ func SetCPUProfileRate(hz int) {
 		}
 
 		cpuprof.on = true
-		cpuprof.log = newProfBuf(1, 1<<17, 1<<14)
+		cpuprof.log = newProfBuf(1, profBufWordCount, profBufTagCount)
 		hdr := [1]uint64{uint64(hz)}
 		cpuprof.log.write(nil, nanotime(), hdr[:], nil)
 		setcpuprofilerate(int32(hz))
@@ -93,6 +107,7 @@ func SetCPUProfileRate(hz int) {
 func (p *cpuProfile) add(tagPtr *unsafe.Pointer, stk []uintptr) {
 	// Simple cas-lock to coordinate with setcpuprofilerate.
 	for !atomic.Cas(&prof.signalLock, 0, 1) {
+		// TODO: Is it safe to osyield here? https://go.dev/issue/52672
 		osyield()
 	}
 
@@ -125,8 +140,11 @@ func (p *cpuProfile) addNonGo(stk []uintptr) {
 	// Simple cas-lock to coordinate with SetCPUProfileRate.
 	// (Other calls to add or addNonGo should be blocked out
 	// by the fact that only one SIGPROF can be handled by the
-	// process at a time. If not, this lock will serialize those too.)
+	// process at a time. If not, this lock will serialize those too.
+	// The use of timer_create(2) on Linux to request process-targeted
+	// signals may have changed this.)
 	for !atomic.Cas(&prof.signalLock, 0, 1) {
+		// TODO: Is it safe to osyield here? https://go.dev/issue/52672
 		osyield()
 	}
 

src/runtime/proc.go

@@ -4595,6 +4595,12 @@ func sigprof(pc, sp, lr uintptr, gp *g, mp *m) {
 			tagPtr = &gp.m.curg.labels
 		}
 		cpuprof.add(tagPtr, stk[:n])
+
+		var pp *p
+		if gp != nil && gp.m != nil {
+			pp = gp.m.p.ptr()
+		}
+		traceCPUSample(gp, pp, stk[:n])
 	}
 	getg().m.mallocing--
 }