runtime, cmd/trace: track goroutines blocked on GC assists

Currently when a goroutine blocks on a GC assist, it emits a generic
EvGoBlock event. Since assist blocking events and, in particular, the
length of the blocked assist queue, are important for diagnosing GC
behavior, this commit adds a new EvGoBlockGC event for blocking on a
GC assist. The trace viewer uses this event to report a "waiting on
GC" count in the "Goroutines" row. This makes sense because, unlike
other blocked goroutines, these goroutines do have work to do, so
being blocked on a GC assist is quite similar to being in the
"runnable" state, which we also report in the trace viewer.

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

src/cmd/trace/pprof.go

@@ -62,7 +62,7 @@ func pprofBlock(w io.Writer) error {
 	for _, ev := range events {
 		switch ev.Type {
 		case trace.EvGoBlockSend, trace.EvGoBlockRecv, trace.EvGoBlockSelect,
-			trace.EvGoBlockSync, trace.EvGoBlockCond:
+			trace.EvGoBlockSync, trace.EvGoBlockCond, trace.EvGoBlockGC:
 		default:
 			continue
 		}

src/cmd/trace/trace.go

@@ -274,6 +274,7 @@ const (
 	gRunnable
 	gRunning
 	gWaiting
+	gWaitingGC
 
 	gStateCount
 )
@@ -333,6 +334,10 @@ func generateTrace(params *traceParams) (ViewerData, error) {
 	// error in setGStateErr and check it after every event.
 	var setGStateErr error
 	setGState := func(ev *trace.Event, g uint64, oldState, newState gState) {
+		if oldState == gWaiting && gstates[g] == gWaitingGC {
+			// For checking, gWaiting counts as any gWaiting*.
+			oldState = gstates[g]
+		}
 		if gstates[g] != oldState && setGStateErr == nil {
 			setGStateErr = fmt.Errorf("expected G %d to be in state %d, but got state %d", g, oldState, newState)
 		}
@@ -428,6 +433,8 @@ func generateTrace(params *traceParams) (ViewerData, error) {
 			trace.EvGoSleep, trace.EvGoBlock, trace.EvGoBlockSend, trace.EvGoBlockRecv,
 			trace.EvGoBlockSelect, trace.EvGoBlockSync, trace.EvGoBlockCond, trace.EvGoBlockNet:
 			setGState(ev, ev.G, gRunning, gWaiting)
+		case trace.EvGoBlockGC:
+			setGState(ev, ev.G, gRunning, gWaitingGC)
 		case trace.EvGoWaiting:
 			setGState(ev, ev.G, gRunnable, gWaiting)
 		case trace.EvGoInSyscall:
@@ -536,15 +543,16 @@ func (ctx *traceContext) emitHeapCounters(ev *trace.Event) {
 }
 
 type goroutineCountersArg struct {
-	Running  uint64
-	Runnable uint64
+	Running   uint64
+	Runnable  uint64
+	GCWaiting uint64
 }
 
 func (ctx *traceContext) emitGoroutineCounters(ev *trace.Event) {
 	if ctx.gtrace {
 		return
 	}
-	ctx.emit(&ViewerEvent{Name: "Goroutines", Phase: "C", Time: ctx.time(ev), Pid: 1, Arg: &goroutineCountersArg{ctx.gstates[gRunning], ctx.gstates[gRunnable]}})
+	ctx.emit(&ViewerEvent{Name: "Goroutines", Phase: "C", Time: ctx.time(ev), Pid: 1, Arg: &goroutineCountersArg{ctx.gstates[gRunning], ctx.gstates[gRunnable], ctx.gstates[gWaitingGC]}})
 }
 
 type threadCountersArg struct {

src/internal/trace/goroutines.go

@@ -83,6 +83,10 @@ func GoroutineStats(events []*Event) map[uint64]*GDesc {
 			g := gs[ev.G]
 			g.ExecTime += ev.Ts - g.lastStartTime
 			g.blockNetTime = ev.Ts
+		case EvGoBlockGC:
+			g := gs[ev.G]
+			g.ExecTime += ev.Ts - g.lastStartTime
+			g.blockGCTime = ev.Ts
 		case EvGoUnblock:
 			g := gs[ev.Args[0]]
 			if g.blockNetTime != 0 {

src/internal/trace/order.go

@@ -165,7 +165,8 @@ func stateTransition(ev *Event) (g uint64, init, next gState) {
 		init = gState{noseq, gRunnable}
 		next = gState{seqinc, gRunning}
 	case EvGoBlock, EvGoBlockSend, EvGoBlockRecv, EvGoBlockSelect,
-		EvGoBlockSync, EvGoBlockCond, EvGoBlockNet, EvGoSleep, EvGoSysBlock:
+		EvGoBlockSync, EvGoBlockCond, EvGoBlockNet, EvGoSleep,
+		EvGoSysBlock, EvGoBlockGC:
 		g = ev.G
 		init = gState{noseq, gRunning}
 		next = gState{noseq, gWaiting}

src/internal/trace/parser.go

@@ -375,7 +375,7 @@ func parseEvents(ver int, rawEvents []rawEvent, strings map[uint64]string) (even
 			case EvGoEnd, EvGoStop, EvGoSched, EvGoPreempt,
 				EvGoSleep, EvGoBlock, EvGoBlockSend, EvGoBlockRecv,
 				EvGoBlockSelect, EvGoBlockSync, EvGoBlockCond, EvGoBlockNet,
-				EvGoSysBlock:
+				EvGoSysBlock, EvGoBlockGC:
 				lastG = 0
 			case EvGoSysExit, EvGoWaiting, EvGoInSyscall:
 				e.G = e.Args[0]
@@ -687,7 +687,7 @@ func postProcessTrace(ver int, events []*Event) error {
 			g.state = gRunnable
 			g.ev = ev
 		case EvGoSleep, EvGoBlock, EvGoBlockSend, EvGoBlockRecv,
-			EvGoBlockSelect, EvGoBlockSync, EvGoBlockCond, EvGoBlockNet:
+			EvGoBlockSelect, EvGoBlockSync, EvGoBlockCond, EvGoBlockNet, EvGoBlockGC:
 			if err := checkRunning(p, g, ev, false); err != nil {
 				return err
 			}
@@ -895,7 +895,8 @@ const (
 	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]
 	EvGoStartLabel   = 41 // goroutine starts running with label [timestamp, goroutine id, seq, label string id]
-	EvCount          = 42
+	EvGoBlockGC      = 42 // goroutine blocks on GC assist [timestamp, stack]
+	EvCount          = 43
 )
 
 var EventDescriptions = [EvCount]struct {
@@ -946,4 +947,5 @@ var EventDescriptions = [EvCount]struct {
 	EvGoUnblockLocal: {"GoUnblockLocal", 1007, true, []string{"g"}},
 	EvGoSysExitLocal: {"GoSysExitLocal", 1007, false, []string{"g", "ts"}},
 	EvGoStartLabel:   {"GoStartLabel", 1008, false, []string{"g", "seq", "label"}},
+	EvGoBlockGC:      {"GoBlockGC", 1008, true, []string{}},
 }

src/runtime/mgcmark.go

@@ -589,7 +589,7 @@ func gcParkAssist() bool {
 		return false
 	}
 	// Park.
-	goparkunlock(&work.assistQueue.lock, "GC assist wait", traceEvGoBlock, 2)
+	goparkunlock(&work.assistQueue.lock, "GC assist wait", traceEvGoBlockGC, 2)
 	return true
 }
 

src/runtime/trace.go

@@ -61,7 +61,8 @@ const (
 	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]
 	traceEvGoStartLabel   = 41 // goroutine starts running with label [timestamp, goroutine id, seq, label string id]
-	traceEvCount          = 42
+	traceEvGoBlockGC      = 42 // goroutine blocks on GC assist [timestamp, stack]
+	traceEvCount          = 43
 )
 
 const (