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>

diff --git a/src/cmd/trace/pprof.go b/src/cmd/trace/pprof.go
index 636d23dc06fae5036119c6eb4235b5818110cfb5..3bae15c60869e61456b8c2137328ff3b8c8599d2 100644 (file)
--- a/src/cmd/trace/pprof.go
+++ b/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
                }

diff --git a/src/cmd/trace/trace.go b/src/cmd/trace/trace.go
index 37c14a286f82868976e5274d2ade94ab359a36a9..f92852f2a0e5a403646bd85f518fb42c9d788bb7 100644 (file)
--- a/src/cmd/trace/trace.go
+++ b/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 {

diff --git a/src/internal/trace/goroutines.go b/src/internal/trace/goroutines.go
index f02c7eb91b360a992e5dfd49a88ece9811a85d37..923a157416f1f452fef8bcbcdcd55c0d25e7ca2b 100644 (file)
--- a/src/internal/trace/goroutines.go
+++ b/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 {

diff --git a/src/internal/trace/order.go b/src/internal/trace/order.go
index 4b788147d149dc78bf50e7dc3e80bc776dcebcf9..36ed58d675aa7aa104079543a2314f403df5f9dd 100644 (file)
--- a/src/internal/trace/order.go
+++ b/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}

diff --git a/src/internal/trace/parser.go b/src/internal/trace/parser.go
index 3110d6341fbae70c6aa5b94b5d3cd9eab1590f65..40176237495b0c17bca8860ab78a8d9153df9bad 100644 (file)
--- a/src/internal/trace/parser.go
+++ b/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{}},
 }

diff --git a/src/runtime/mgcmark.go b/src/runtime/mgcmark.go
index 954bbef40ca0b023e39d990e995a23951a360a5f..286aeb74a9eade6eb932a82a8545e3368279c127 100644 (file)
--- a/src/runtime/mgcmark.go
+++ b/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
 }
 

diff --git a/src/runtime/trace.go b/src/runtime/trace.go
index 0bb529ea9dae2665d32498f3fdcd0f34851c1937..a8f4ab60d301fd9b8f9bd0fe5244052c530cfa7e 100644 (file)
--- a/src/runtime/trace.go
+++ b/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 (