From: Austin Clements Date: Fri, 7 Oct 2016 21:25:26 +0000 (-0400) Subject: runtime, cmd/trace: annotate different mark worker types X-Git-Tag: go1.8beta1~528 X-Git-Url: http://www.git.cypherpunks.su/?a=commitdiff_plain;h=68348394274ee83f5286022d97cfe58b6761321b;p=gostls13.git 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 ()" 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 TryBot-Result: Gobot Gobot Reviewed-by: Dmitry Vyukov --- diff --git a/src/cmd/trace/trace.go b/src/cmd/trace/trace.go index 7670d330e1..26548fa9de 100644 --- a/src/cmd/trace/trace.go +++ b/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++ diff --git a/src/internal/trace/goroutines.go b/src/internal/trace/goroutines.go index f8673e20bc..f02c7eb91b 100644 --- a/src/internal/trace/goroutines.go +++ b/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 diff --git a/src/internal/trace/order.go b/src/internal/trace/order.go index 8ca2da52aa..4b788147d1 100644 --- a/src/internal/trace/order.go +++ b/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} diff --git a/src/internal/trace/parser.go b/src/internal/trace/parser.go index fa62eccf72..3110d6341f 100644 --- a/src/internal/trace/parser.go +++ b/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"}}, } diff --git a/src/internal/trace/testdata/http_1_7_good b/src/internal/trace/testdata/http_1_7_good new file mode 100644 index 0000000000..b0e318e9a4 Binary files /dev/null and b/src/internal/trace/testdata/http_1_7_good differ diff --git a/src/internal/trace/testdata/stress_1_7_good b/src/internal/trace/testdata/stress_1_7_good new file mode 100644 index 0000000000..b4d927de34 Binary files /dev/null and b/src/internal/trace/testdata/stress_1_7_good differ diff --git a/src/internal/trace/testdata/stress_start_stop_1_7_good b/src/internal/trace/testdata/stress_start_stop_1_7_good new file mode 100644 index 0000000000..c23ed7dc08 Binary files /dev/null and b/src/internal/trace/testdata/stress_start_stop_1_7_good differ diff --git a/src/runtime/mgc.go b/src/runtime/mgc.go index 37a3554d0d..0e3a4e4f15 100644 --- a/src/runtime/mgc.go +++ b/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. diff --git a/src/runtime/trace.go b/src/runtime/trace.go index d75019dd62..0bb529ea9d 100644 --- a/src/runtime/trace.go +++ b/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_