Skip to content

Commit

Permalink
cmd/trace: Record mark assists in execution traces
Browse files Browse the repository at this point in the history 
During the mark phase of garbage collection, goroutines that allocate
may be recruited to assist. This change creates trace events for mark
assists and displays them similarly to sweep assists in the trace
viewer.

Mark assists are different than sweeps in that they can be preempted, so
displaying them in the trace viewer is a little tricky -- we may need to
synthesize multiple slices for one mark assist. This could have been
done in the parser instead, but I thought it might be preferable to keep
the parser as true to the event stream as possible.

Change-Id: I381dcb1027a187a354b1858537851fa68a620ea7
Reviewed-on: https://go-review.googlesource.com/36015
Run-TryBot: Heschi Kreinick <[email protected]>
TryBot-Result: Gobot Gobot <[email protected]>
Reviewed-by: Austin Clements <[email protected]>
Reviewed-by: Hyang-Ah Hana Kim <[email protected]>
  • Loading branch information
@heschi
heschi committed Feb 10, 2017
1 parent 249aca5 commit 2a74b9e
Show file tree
Hide file tree
Showing 9 changed files with 286 additions and 156 deletions.
85 changes: 68 additions & 17 deletions src/cmd/trace/trace.go
View file
Original file line number Diff line number Diff line change
Expand Up @@ -288,6 +288,13 @@ const (
gStateCount
)

type gInfo struct {
state gState // current state
name string // name chosen for this goroutine at first EvGoStart
start *trace.Event // most recent EvGoStart
markAssist *trace.Event // if non-nil, the mark assist currently running.
}

type ViewerData struct {
Events []*ViewerEvent `json:"traceEvents"`
Frames map[string]ViewerFrame `json:"stackFrames"`
Expand Down Expand Up @@ -337,35 +344,47 @@ func generateTrace(params *traceParams) (ViewerData, error) {
ctx.data.Frames = make(map[string]ViewerFrame)
ctx.data.TimeUnit = "ns"
maxProc := 0
gnames := make(map[uint64]string)
gstates := make(map[uint64]gState)
ginfos := make(map[uint64]*gInfo)

getGInfo := func(g uint64) *gInfo {
info, ok := ginfos[g]
if !ok {
info = &gInfo{}
ginfos[g] = info
}
return info
}

// Since we make many calls to setGState, we record a sticky
// 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 {
info := getGInfo(g)
if oldState == gWaiting && info.state == gWaitingGC {
// For checking, gWaiting counts as any gWaiting*.
oldState = gstates[g]
oldState = info.state
}
if gstates[g] != oldState && setGStateErr == nil {
if info.state != oldState && setGStateErr == nil {
setGStateErr = fmt.Errorf("expected G %d to be in state %d, but got state %d", g, oldState, newState)
}
ctx.gstates[gstates[g]]--
ctx.gstates[info.state]--
ctx.gstates[newState]++
gstates[g] = newState
info.state = newState
}
for _, ev := range ctx.events {
// Handle state transitions before we filter out events.
switch ev.Type {
case trace.EvGoStart, trace.EvGoStartLabel:
setGState(ev, ev.G, gRunnable, gRunning)
if _, ok := gnames[ev.G]; !ok {
info := getGInfo(ev.G)
if info.name == "" {
if len(ev.Stk) > 0 {
gnames[ev.G] = fmt.Sprintf("G%v %s", ev.G, ev.Stk[0].Fn)
info.name = fmt.Sprintf("G%v %s", ev.G, ev.Stk[0].Fn)
} else {
gnames[ev.G] = fmt.Sprintf("G%v", ev.G)
info.name = fmt.Sprintf("G%v", ev.G)
}
}
info.start = ev
case trace.EvProcStart:
ctx.threadStats.prunning++
case trace.EvProcStop:
Expand All @@ -392,6 +411,10 @@ func generateTrace(params *traceParams) (ViewerData, error) {
setGState(ev, ev.G, gRunning, gWaiting)
case trace.EvGoBlockGC:
setGState(ev, ev.G, gRunning, gWaitingGC)
case trace.EvGCMarkAssistStart:
getGInfo(ev.G).markAssist = ev
case trace.EvGCMarkAssistDone:
getGInfo(ev.G).markAssist = nil
case trace.EvGoWaiting:
setGState(ev, ev.G, gRunnable, gWaiting)
case trace.EvGoInSyscall:
Expand Down Expand Up @@ -444,13 +467,41 @@ func generateTrace(params *traceParams) (ViewerData, error) {
}
ctx.emitSlice(ev, "MARK TERMINATION")
case trace.EvGCScanDone:
case trace.EvGCMarkAssistStart:
// Mark assists can continue past preemptions, so truncate to the
// whichever comes first. We'll synthesize another slice if
// necessary in EvGoStart.
markFinish := ev.Link
goFinish := getGInfo(ev.G).start.Link
fakeMarkStart := *ev
text := "MARK ASSIST"
if markFinish.Ts > goFinish.Ts {
fakeMarkStart.Link = goFinish
text = "MARK ASSIST (unfinished)"
}
ctx.emitSlice(&fakeMarkStart, text)
case trace.EvGCSweepStart:
ctx.emitSlice(ev, "SWEEP")
case trace.EvGCSweepDone:
case trace.EvGoStart:
ctx.emitSlice(ev, gnames[ev.G])
case trace.EvGoStartLabel:
ctx.emitSlice(ev, ev.SArgs[0])
case trace.EvGoStart, trace.EvGoStartLabel:
info := getGInfo(ev.G)
if ev.Type == trace.EvGoStartLabel {
ctx.emitSlice(ev, ev.SArgs[0])
} else {
ctx.emitSlice(ev, info.name)
}
if info.markAssist != nil {
// If we're in a mark assist, synthesize a new slice, ending
// either when the mark assist ends or when we're descheduled.
markFinish := info.markAssist.Link
goFinish := ev.Link
fakeMarkStart := *ev
text := "MARK ASSIST (resumed, unfinished)"
if markFinish.Ts < goFinish.Ts {
fakeMarkStart.Link = markFinish
text = "MARK ASSIST (resumed)"
}
ctx.emitSlice(&fakeMarkStart, text)
}
case trace.EvGoCreate:
ctx.emitArrow(ev, "go")
case trace.EvGoUnblock:
Expand Down Expand Up @@ -493,11 +544,11 @@ func generateTrace(params *traceParams) (ViewerData, error) {
}

if ctx.gtrace && ctx.gs != nil {
for k, v := range gnames {
for k, v := range ginfos {
if !ctx.gs[k] {
continue
}
ctx.emit(&ViewerEvent{Name: "thread_name", Phase: "M", Pid: 0, Tid: k, Arg: &NameArg{v}})
ctx.emit(&ViewerEvent{Name: "thread_name", Phase: "M", Pid: 0, Tid: k, Arg: &NameArg{v.name}})
}
ctx.emit(&ViewerEvent{Name: "thread_sort_index", Phase: "M", Pid: 0, Tid: ctx.maing, Arg: &SortIndexArg{-2}})
ctx.emit(&ViewerEvent{Name: "thread_sort_index", Phase: "M", Pid: 0, Tid: 0, Arg: &SortIndexArg{-1}})
Expand Down
41 changes: 41 additions & 0 deletions src/cmd/trace/trace_test.go
View file
Original file line number Diff line number Diff line change
Expand Up @@ -2,6 +2,7 @@ package main

import (
"internal/trace"
"strings"
"testing"
)

Expand Down Expand Up @@ -99,3 +100,43 @@ func TestGoroutineFilter(t *testing.T) {
t.Fatalf("generateTrace failed: %v", err)
}
}

func TestPreemptedMarkAssist(t *testing.T) {
w := trace.NewWriter()
w.Emit(trace.EvBatch, 0, 0) // start of per-P batch event [pid, timestamp]
w.Emit(trace.EvFrequency, 1) // [ticks per second]

// goroutine 9999: running -> mark assisting -> preempted -> assisting -> running -> block
w.Emit(trace.EvGoCreate, 1, 9999, 1, 1) // [timestamp, new goroutine id, new stack id, stack id]
w.Emit(trace.EvGoStartLocal, 1, 9999) // [timestamp, goroutine id]
w.Emit(trace.EvGCMarkAssistStart, 1, 2) // [timestamp, stack]
w.Emit(trace.EvGoPreempt, 1, 3) // [timestamp, stack]
w.Emit(trace.EvGoStartLocal, 1, 9999) // [timestamp, goroutine id]
w.Emit(trace.EvGCMarkAssistDone, 1) // [timestamp]
w.Emit(trace.EvGoBlock, 1, 4) // [timestamp, stack]

events, err := trace.Parse(w, "")
if err != nil {
t.Fatalf("failed to parse test trace: %v", err)
}

params := &traceParams{
events: events,
endTime: int64(1<<63 - 1),
}

viewerData, err := generateTrace(params)
if err != nil {
t.Fatalf("generateTrace failed: %v", err)
}

marks := 0
for _, ev := range viewerData.Events {
if strings.Contains(ev.Name, "MARK ASSIST") {
marks++
}
}
if marks != 2 {
t.Errorf("Got %v MARK ASSIST events, want %v", marks, 2)
}
}
Loading

0 comments on commit 2a74b9e

Please sign in to comment.