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
(<mode>)" 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 <austin@google.com>
TryBot-Result: Gobot Gobot <gobot@golang.org>
Reviewed-by: Dmitry Vyukov <dvyukov@google.com>

diff --git a/src/cmd/trace/trace.go b/src/cmd/trace/trace.go
index 7670d330e1d1aeb503b56d509da70298b526d530..26548fa9de2c2e5a1e048d977aeb7bc8fae9b87d 100644 (file)
--- 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 f8673e20bc2301cc5f1cea21df068fe3145fb302..f02c7eb91b360a992e5dfd49a88ece9811a85d37 100644 (file)
--- 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 8ca2da52aa6874d64701a128677d57f43d7d5cc4..4b788147d149dc78bf50e7dc3e80bc776dcebcf9 100644 (file)
--- 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 fa62eccf72f93103f7a5be09147f9a1b8e82028d..3110d6341fbae70c6aa5b94b5d3cd9eab1590f65 100644 (file)
--- 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 (file)
index 0000000..b0e318e
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 (file)
index 0000000..b4d927d
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 (file)
index 0000000..c23ed7d
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 37a3554d0d47e333dcc74afb3b1ad6ea386b996e..0e3a4e4f1531450d22b313044806463fd79fa59d 100644 (file)
--- 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 d75019dd624ee3b3512864928cb9fa5d14748326..0bb529ea9dae2665d32498f3fdcd0f34851c1937 100644 (file)
--- 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_