From 6da83c6fc006019f6fe0503099d165e19f465b1b Mon Sep 17 00:00:00 2001 From: Austin Clements Date: Sat, 8 Oct 2016 18:38:35 -0400 Subject: [PATCH] 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 TryBot-Result: Gobot Gobot Reviewed-by: Dmitry Vyukov --- src/cmd/trace/pprof.go | 2 +- src/cmd/trace/trace.go | 14 +++++++++++--- src/internal/trace/goroutines.go | 4 ++++ src/internal/trace/order.go | 3 ++- src/internal/trace/parser.go | 8 +++++--- src/runtime/mgcmark.go | 2 +- src/runtime/trace.go | 3 ++- 7 files changed, 26 insertions(+), 10 deletions(-) diff --git a/src/cmd/trace/pprof.go b/src/cmd/trace/pprof.go index 636d23dc06..3bae15c608 100644 --- 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 37c14a286f..f92852f2a0 100644 --- 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 f02c7eb91b..923a157416 100644 --- 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 4b788147d1..36ed58d675 100644 --- 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 3110d6341f..4017623749 100644 --- 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 954bbef40c..286aeb74a9 100644 --- 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 0bb529ea9d..a8f4ab60d3 100644 --- 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 ( -- 2.48.1