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 636d23d..3bae15c 100644
--- a/src/cmd/trace/pprof.go
+++ b/src/cmd/trace/pprof.go
@@ -62,7 +62,7 @@
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 37c14a2..f92852f 100644
--- a/src/cmd/trace/trace.go
+++ b/src/cmd/trace/trace.go
@@ -274,6 +274,7 @@
gRunnable
gRunning
gWaiting
+ gWaitingGC
gStateCount
)
@@ -333,6 +334,10 @@
// 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 @@
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 @@
}
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 f02c7eb..923a157 100644
--- a/src/internal/trace/goroutines.go
+++ b/src/internal/trace/goroutines.go
@@ -83,6 +83,10 @@
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 4b78814..36ed58d 100644
--- a/src/internal/trace/order.go
+++ b/src/internal/trace/order.go
@@ -165,7 +165,8 @@
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 3110d63..4017623 100644
--- a/src/internal/trace/parser.go
+++ b/src/internal/trace/parser.go
@@ -375,7 +375,7 @@
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 @@
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 @@
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 @@
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 954bbef..286aeb7 100644
--- a/src/runtime/mgcmark.go
+++ b/src/runtime/mgcmark.go
@@ -589,7 +589,7 @@
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 0bb529e..a8f4ab6 100644
--- a/src/runtime/trace.go
+++ b/src/runtime/trace.go
@@ -61,7 +61,8 @@
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 (
