runtime, cmd/trace: annotate different mark worker types

Currently mark workers are shown in the trace as regular goroutines
labeled "runtime.gcBgMarkWorker". That's somewhat unhelpful to an end
user because of the opaque label and particularly unhelpful to runtime
developers because it doesn't distinguish the different types of mark
workers.

Fix this by introducing a variant of the GoStart event called
GoStartLabel that lets the runtime indicate a label for a goroutine
execution span and using this to label mark worker executions as "GC
(<mode>)" in the trace viewer.

Since this bumps the trace version to 1.8, we also add test data for
1.7 traces.

Change-Id: Id7b9c0536508430c661ffb9e40e436f3901ca121
Reviewed-on: https://go-review.googlesource.com/30702
Run-TryBot: Austin Clements <austin@google.com>
TryBot-Result: Gobot Gobot <gobot@golang.org>
Reviewed-by: Dmitry Vyukov <dvyukov@google.com>

src/cmd/trace/trace.go

@@ -371,11 +371,15 @@ func generateTrace(params *traceParams) (ViewerData, error) {
 		case trace.EvGCSweepStart:
 			ctx.emitSlice(ev, "SWEEP")
 		case trace.EvGCSweepDone:
-		case trace.EvGoStart:
+		case trace.EvGoStart, trace.EvGoStartLabel:
 			ctx.grunnable--
 			ctx.grunning++
 			ctx.emitGoroutineCounters(ev)
-			ctx.emitSlice(ev, gnames[ev.G])
+			if ev.Type == trace.EvGoStartLabel {
+				ctx.emitSlice(ev, ev.SArgs[0])
+			} else {
+				ctx.emitSlice(ev, gnames[ev.G])
+			}
 		case trace.EvGoCreate:
 			ctx.gcount++
 			ctx.grunnable++

src/internal/trace/goroutines.go

@@ -48,7 +48,7 @@ func GoroutineStats(events []*Event) map[uint64]*GDesc {
 			g := &GDesc{ID: ev.Args[0], CreationTime: ev.Ts, gdesc: new(gdesc)}
 			g.blockSchedTime = ev.Ts
 			gs[g.ID] = g
-		case EvGoStart:
+		case EvGoStart, EvGoStartLabel:
 			g := gs[ev.G]
 			if g.PC == 0 {
 				g.PC = ev.Stk[0].PC

src/internal/trace/order.go

@@ -150,7 +150,7 @@ func stateTransition(ev *Event) (g uint64, init, next gState) {
 		g = ev.G
 		init = gState{1, gRunnable}
 		next = gState{2, gWaiting}
-	case EvGoStart:
+	case EvGoStart, EvGoStartLabel:
 		g = ev.G
 		init = gState{ev.Args[1], gRunnable}
 		next = gState{ev.Args[1] + 1, gRunning}

src/internal/trace/parser.go

@@ -28,12 +28,13 @@ type Event struct {
 	StkID uint64    // unique stack ID
 	Stk   []*Frame  // stack trace (can be empty)
 	Args  [3]uint64 // event-type-specific arguments
+	SArgs []string  // event-type-specific string args
 	// linked event (can be nil), depends on event type:
 	// for GCStart: the GCStop
 	// for GCScanStart: the GCScanDone
 	// for GCSweepStart: the GCSweepDone
 	// for GoCreate: first GoStart of the created goroutine
-	// for GoStart: the associated GoEnd, GoBlock or other blocking event
+	// for GoStart/GoStartLabel: the associated GoEnd, GoBlock or other blocking event
 	// for GoSched/GoPreempt: the next GoStart
 	// for GoBlock and other blocking events: the unblock event
 	// for GoUnblock: the associated GoStart
@@ -126,7 +127,7 @@ func readTrace(r io.Reader) (ver int, events []rawEvent, strings map[uint64]stri
 		return
 	}
 	switch ver {
-	case 1005, 1007:
+	case 1005, 1007, 1008:
 		break
 	default:
 		err = fmt.Errorf("unsupported trace file version %v.%v (update Go toolchain) %v", ver/1000, ver%1000, ver)
@@ -363,9 +364,12 @@ func parseEvents(ver int, rawEvents []rawEvent, strings map[uint64]string) (even
 				}
 			}
 			switch raw.typ {
-			case EvGoStart, EvGoStartLocal:
+			case EvGoStart, EvGoStartLocal, EvGoStartLabel:
 				lastG = e.Args[0]
 				e.G = lastG
+				if raw.typ == EvGoStartLabel {
+					e.SArgs = []string{strings[e.Args[2]]}
+				}
 			case EvGCStart, EvGCDone, EvGCScanStart, EvGCScanDone:
 				e.G = 0
 			case EvGoEnd, EvGoStop, EvGoSched, EvGoPreempt,
@@ -599,7 +603,7 @@ func postProcessTrace(ver int, events []*Event) error {
 				return fmt.Errorf("g %v already exists (offset %v, time %v)", ev.Args[0], ev.Off, ev.Ts)
 			}
 			gs[ev.Args[0]] = gdesc{state: gRunnable, ev: ev, evCreate: ev}
-		case EvGoStart:
+		case EvGoStart, EvGoStartLabel:
 			if g.state != gRunnable {
 				return fmt.Errorf("g %v is not runnable before start (offset %v, time %v)", ev.G, ev.Off, ev.Ts)
 			}
@@ -890,7 +894,8 @@ const (
 	EvGoStartLocal   = 38 // goroutine starts running on the same P as the last event [timestamp, goroutine id]
 	EvGoUnblockLocal = 39 // goroutine is unblocked on the same P as the last event [timestamp, goroutine id, stack]
 	EvGoSysExitLocal = 40 // syscall exit on the same P as the last event [timestamp, goroutine id, real timestamp]
-	EvCount          = 41
+	EvGoStartLabel   = 41 // goroutine starts running with label [timestamp, goroutine id, seq, label string id]
+	EvCount          = 42
 )
 
 var EventDescriptions = [EvCount]struct {
@@ -940,4 +945,5 @@ var EventDescriptions = [EvCount]struct {
 	EvGoStartLocal:   {"GoStartLocal", 1007, false, []string{"g"}},
 	EvGoUnblockLocal: {"GoUnblockLocal", 1007, true, []string{"g"}},
 	EvGoSysExitLocal: {"GoSysExitLocal", 1007, false, []string{"g", "ts"}},
+	EvGoStartLabel:   {"GoStartLabel", 1008, false, []string{"g", "seq", "label"}},
 }

src/runtime/mgc.go

@@ -311,6 +311,14 @@ const (
 	gcMarkWorkerIdleMode
 )
 
+// gcMarkWorkerModeStrings are the strings labels of gcMarkWorkerModes
+// to use in execution traces.
+var gcMarkWorkerModeStrings = [...]string{
+	"GC (dedicated)",
+	"GC (fractional)",
+	"GC (idle)",
+}
+
 // gcController implements the GC pacing controller that determines
 // when to trigger concurrent garbage collection and how much marking
 // work to do in mutator assists and background marking.

src/runtime/trace.go

@@ -60,7 +60,8 @@ const (
 	traceEvGoStartLocal   = 38 // goroutine starts running on the same P as the last event [timestamp, goroutine id]
 	traceEvGoUnblockLocal = 39 // goroutine is unblocked on the same P as the last event [timestamp, goroutine id, stack]
 	traceEvGoSysExitLocal = 40 // syscall exit on the same P as the last event [timestamp, goroutine id, real timestamp]
-	traceEvCount          = 41
+	traceEvGoStartLabel   = 41 // goroutine starts running with label [timestamp, goroutine id, seq, label string id]
+	traceEvCount          = 42
 )
 
 const (
@@ -116,11 +117,16 @@ var trace struct {
 	stackTab      traceStackTable // maps stack traces to unique ids
 
 	// Dictionary for traceEvString.
-	// Currently this is used only for func/file:line info after tracing session,
-	// so we assume single-threaded access.
+	//
+	// Currently this is used only at trace setup and for
+	// func/file:line info after tracing session, so we assume
+	// single-threaded access.
 	strings   map[string]uint64
 	stringSeq uint64
 
+	// markWorkerLabels maps gcMarkWorkerMode to string ID.
+	markWorkerLabels [len(gcMarkWorkerModeStrings)]uint64
+
 	bufLock mutex       // protects buf
 	buf     traceBufPtr // global trace buffer, used when running without a p
 }
@@ -232,6 +238,18 @@ func StartTrace() error {
 	_g_.m.startingtrace = false
 	trace.enabled = true
 
+	// Register runtime goroutine labels.
+	_, pid, bufp := traceAcquireBuffer()
+	buf := (*bufp).ptr()
+	if buf == nil {
+		buf = traceFlush(0).ptr()
+		(*bufp).set(buf)
+	}
+	for i, label := range gcMarkWorkerModeStrings[:] {
+		trace.markWorkerLabels[i], buf = traceString(buf, label)
+	}
+	traceReleaseBuffer(pid)
+
 	unlock(&trace.bufLock)
 
 	startTheWorld()
@@ -361,7 +379,7 @@ func ReadTrace() []byte {
 		trace.headerWritten = true
 		trace.lockOwner = nil
 		unlock(&trace.lock)
-		return []byte("go 1.7 trace\x00\x00\x00\x00")
+		return []byte("go 1.8 trace\x00\x00\x00\x00")
 	}
 	// Wait for new data.
 	if trace.fullHead == 0 && !trace.shutdown {
@@ -932,7 +950,9 @@ func traceGoStart() {
 	_g_ := getg().m.curg
 	_p_ := _g_.m.p
 	_g_.traceseq++
-	if _g_.tracelastp == _p_ {
+	if _g_ == _p_.ptr().gcBgMarkWorker.ptr() {
+		traceEvent(traceEvGoStartLabel, -1, uint64(_g_.goid), _g_.traceseq, trace.markWorkerLabels[_p_.ptr().gcMarkWorkerMode])
+	} else if _g_.tracelastp == _p_ {
 		traceEvent(traceEvGoStartLocal, -1, uint64(_g_.goid))
 	} else {
 		_g_.tracelastp = _p_