Skip to content

Commit

Permalink
cmd/trace/v2: add support for goroutine filtering
Browse files Browse the repository at this point in the history
This change adds support for the trace?goid=<goid> endpoint to the trace
tool for v2 traces.

In effect, this change actually implements a per-goroutine view. I tried
to add a link to the main page to enable a "view by goroutines" view
without filtering, but the web trace viewer broke the browser tab when
there were a few hundred goroutines. The risk of a browser hang probably
isn't worth the cases where this is nice, especially since filtering by
goroutine already works. Unfortunate, but c'est l'vie. Might be worth
revisiting if we change out the web viewer in the future.

For #60773.
For #63960.

Change-Id: I8e29f4ab8346af6708fd8824505c30f2c43db796
Reviewed-on: https://go-review.googlesource.com/c/go/+/543595
TryBot-Bypass: Michael Knyszek <mknyszek@google.com>
Reviewed-by: Michael Pratt <mpratt@google.com>
Auto-Submit: Michael Knyszek <mknyszek@google.com>
  • Loading branch information
mknyszek committed Nov 21, 2023
1 parent 7105216 commit 64c12ba
Show file tree
Hide file tree
Showing 5 changed files with 249 additions and 24 deletions.
164 changes: 164 additions & 0 deletions src/cmd/trace/v2/goroutinegen.go
Original file line number Diff line number Diff line change
@@ -0,0 +1,164 @@
// Copyright 2023 The Go Authors. All rights reserved.
// Use of this source code is governed by a BSD-style
// license that can be found in the LICENSE file.

package trace

import (
tracev2 "internal/trace/v2"
)

var _ generator = &goroutineGenerator{}

type goroutineGenerator struct {
globalRangeGenerator
globalMetricGenerator
stackSampleGenerator[tracev2.GoID]

gStates map[tracev2.GoID]*gState[tracev2.GoID]
focus tracev2.GoID
filter map[tracev2.GoID]struct{}
}

func newGoroutineGenerator(ctx *traceContext, focus tracev2.GoID, filter map[tracev2.GoID]struct{}) *goroutineGenerator {
gg := new(goroutineGenerator)
gg.stackSampleGenerator.getResource = func(ev *tracev2.Event) tracev2.GoID {
return ev.Goroutine()
}
gg.gStates = make(map[tracev2.GoID]*gState[tracev2.GoID])
gg.focus = focus
gg.filter = filter

// Enable a filter on the emitter.
if filter != nil {
ctx.SetResourceFilter(func(resource uint64) bool {
_, ok := filter[tracev2.GoID(resource)]
return ok
})
}
return gg
}

func (g *goroutineGenerator) Sync() {
g.globalRangeGenerator.Sync()
}

func (g *goroutineGenerator) GoroutineLabel(ctx *traceContext, ev *tracev2.Event) {
l := ev.Label()
g.gStates[l.Resource.Goroutine()].setLabel(l.Label)
}

func (g *goroutineGenerator) GoroutineRange(ctx *traceContext, ev *tracev2.Event) {
r := ev.Range()
switch ev.Kind() {
case tracev2.EventRangeBegin:
g.gStates[r.Scope.Goroutine()].rangeBegin(ev.Time(), r.Name, ev.Stack())
case tracev2.EventRangeActive:
g.gStates[r.Scope.Goroutine()].rangeActive(r.Name)
case tracev2.EventRangeEnd:
gs := g.gStates[r.Scope.Goroutine()]
gs.rangeEnd(ev.Time(), r.Name, ev.Stack(), ctx)
}
}

func (g *goroutineGenerator) GoroutineTransition(ctx *traceContext, ev *tracev2.Event) {
st := ev.StateTransition()
goID := st.Resource.Goroutine()

// If we haven't seen this goroutine before, create a new
// gState for it.
gs, ok := g.gStates[goID]
if !ok {
gs = newGState[tracev2.GoID](goID)
g.gStates[goID] = gs
}

// Try to augment the name of the goroutine.
gs.augmentName(st.Stack)

// Handle the goroutine state transition.
from, to := st.Goroutine()
if from == to {
// Filter out no-op events.
return
}
if from.Executing() && !to.Executing() {
if to == tracev2.GoWaiting {
// Goroutine started blocking.
gs.block(ev.Time(), ev.Stack(), st.Reason, ctx)
} else {
gs.stop(ev.Time(), ev.Stack(), ctx)
}
}
if !from.Executing() && to.Executing() {
start := ev.Time()
if from == tracev2.GoUndetermined {
// Back-date the event to the start of the trace.
start = ctx.startTime
}
gs.start(start, goID, ctx)
}

if from == tracev2.GoWaiting {
// Goroutine unblocked.
gs.unblock(ev.Time(), ev.Stack(), ev.Goroutine(), ctx)
}
if from == tracev2.GoNotExist && to == tracev2.GoRunnable {
// Goroutine was created.
gs.created(ev.Time(), ev.Goroutine(), ev.Stack())
}
if from == tracev2.GoSyscall && to != tracev2.GoRunning {
// Exiting blocked syscall.
gs.syscallEnd(ev.Time(), true, ctx)
gs.blockedSyscallEnd(ev.Time(), ev.Stack(), ctx)
} else if from == tracev2.GoSyscall {
// Check if we're exiting a syscall in a non-blocking way.
gs.syscallEnd(ev.Time(), false, ctx)
}

// Handle syscalls.
if to == tracev2.GoSyscall {
start := ev.Time()
if from == tracev2.GoUndetermined {
// Back-date the event to the start of the trace.
start = ctx.startTime
}
// Write down that we've entered a syscall. Note: we might have no G or P here
// if we're in a cgo callback or this is a transition from GoUndetermined
// (i.e. the G has been blocked in a syscall).
gs.syscallBegin(start, goID, ev.Stack())
}

// Note down the goroutine transition.
_, inMarkAssist := gs.activeRanges["GC mark assist"]
ctx.GoroutineTransition(ctx.elapsed(ev.Time()), viewerGState(from, inMarkAssist), viewerGState(to, inMarkAssist))
}

func (g *goroutineGenerator) ProcRange(ctx *traceContext, ev *tracev2.Event) {
// TODO(mknyszek): Extend procRangeGenerator to support rendering proc ranges
// that overlap with a goroutine's execution.
}

func (g *goroutineGenerator) ProcTransition(ctx *traceContext, ev *tracev2.Event) {
// Not needed. All relevant information for goroutines can be derived from goroutine transitions.
}

func (g *goroutineGenerator) Finish(ctx *traceContext, endTime tracev2.Time) {
ctx.SetResourceType("G")

// Finish off global ranges.
g.globalRangeGenerator.Finish(ctx, endTime)

// Finish off all the goroutine slices.
for id, gs := range g.gStates {
gs.finish(endTime, ctx)

// Tell the emitter about the goroutines we want to render.
ctx.Resource(uint64(id), gs.name())
}

// Set the goroutine to focus on.
if g.focus != tracev2.NoGoroutine {
ctx.Focus(uint64(g.focus))
}
}
63 changes: 59 additions & 4 deletions src/cmd/trace/v2/jsontrace.go
Original file line number Diff line number Diff line change
Expand Up @@ -11,12 +11,44 @@ import (
"strconv"
"time"

"internal/trace"
"internal/trace/traceviewer"
tracev2 "internal/trace/v2"
)

func JSONTraceHandler(parsed *parsedTrace) http.Handler {
return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
opts := defaultGenOpts()

if goids := r.FormValue("goid"); goids != "" {
// Render trace focused on a particular goroutine.

id, err := strconv.ParseUint(goids, 10, 64)
if err != nil {
log.Printf("failed to parse goid parameter %q: %v", goids, err)
return
}
goid := tracev2.GoID(id)
g, ok := parsed.summary.Goroutines[goid]
if !ok {
log.Printf("failed to find goroutine %d", goid)
return
}
opts.mode = traceviewer.ModeGoroutineOriented
if g.StartTime != 0 {
opts.startTime = g.StartTime.Sub(parsed.startTime())
} else {
opts.startTime = 0
}
if g.EndTime != 0 {
opts.endTime = g.EndTime.Sub(parsed.startTime())
} else { // The goroutine didn't end.
opts.endTime = parsed.endTime().Sub(parsed.startTime())
}
opts.focusGoroutine = goid
opts.goroutines = trace.RelatedGoroutinesV2(parsed.events, goid)
}

// Parse start and end options. Both or none must be present.
start := int64(0)
end := int64(math.MaxInt64)
Expand All @@ -36,7 +68,7 @@ func JSONTraceHandler(parsed *parsedTrace) http.Handler {
}

c := traceviewer.ViewerDataTraceConsumer(w, start, end)
if err := generateTrace(parsed, c); err != nil {
if err := generateTrace(parsed, opts, c); err != nil {
log.Printf("failed to generate trace: %v", err)
}
})
Expand All @@ -55,13 +87,36 @@ func (ctx *traceContext) elapsed(now tracev2.Time) time.Duration {
return now.Sub(ctx.startTime)
}

func generateTrace(parsed *parsedTrace, c traceviewer.TraceConsumer) error {
type genOpts struct {
mode traceviewer.Mode
startTime time.Duration
endTime time.Duration

// Used if mode != 0.
focusGoroutine tracev2.GoID
goroutines map[tracev2.GoID]struct{} // Goroutines to be displayed for goroutine-oriented or task-oriented view. goroutines[0] is the main goroutine.
}

func defaultGenOpts() *genOpts {
return &genOpts{
startTime: time.Duration(0),
endTime: time.Duration(math.MaxInt64),
}
}

func generateTrace(parsed *parsedTrace, opts *genOpts, c traceviewer.TraceConsumer) error {
ctx := &traceContext{
Emitter: traceviewer.NewEmitter(c, 0, time.Duration(0), time.Duration(math.MaxInt64)),
Emitter: traceviewer.NewEmitter(c, 0, opts.startTime, opts.endTime),
startTime: parsed.events[0].Time(),
}
defer ctx.Flush()

runGenerator(ctx, newProcGenerator(), parsed)
var g generator
if opts.mode&traceviewer.ModeGoroutineOriented != 0 {
g = newGoroutineGenerator(ctx, opts.focusGoroutine, opts.goroutines)
} else {
g = newProcGenerator()
}
runGenerator(ctx, g, parsed)
return nil
}
2 changes: 1 addition & 1 deletion src/cmd/trace/v2/main.go
Original file line number Diff line number Diff line change
Expand Up @@ -145,7 +145,7 @@ func splitTrace(parsed *parsedTrace) ([]traceviewer.Range, error) {
// TODO(mknyszek): Split traces by generation by doing a quick first pass over the
// trace to identify all the generation boundaries.
s, c := traceviewer.SplittingTraceConsumer(100 << 20) // 100 MiB
if err := generateTrace(parsed, c); err != nil {
if err := generateTrace(parsed, defaultGenOpts(), c); err != nil {
return nil, err
}
return s.Ranges, nil
Expand Down
18 changes: 3 additions & 15 deletions src/internal/trace/summary.go
Original file line number Diff line number Diff line change
Expand Up @@ -6,7 +6,6 @@ package trace

import (
tracev2 "internal/trace/v2"
"io"
"sort"
"time"
)
Expand Down Expand Up @@ -601,11 +600,7 @@ func (s *Summarizer) Finalize() *Summary {
// RelatedGoroutinesV2 finds a set of goroutines related to goroutine goid for v2 traces.
// The association is based on whether they have synchronized with each other in the Go
// scheduler (one has unblocked another).
func RelatedGoroutinesV2(trace io.Reader, goid tracev2.GoID) (map[tracev2.GoID]struct{}, error) {
r, err := tracev2.NewReader(trace)
if err != nil {
return nil, err
}
func RelatedGoroutinesV2(events []tracev2.Event, goid tracev2.GoID) map[tracev2.GoID]struct{} {
// Process all the events, looking for transitions of goroutines
// out of GoWaiting. If there was an active goroutine when this
// happened, then we know that active goroutine unblocked another.
Expand All @@ -615,14 +610,7 @@ func RelatedGoroutinesV2(trace io.Reader, goid tracev2.GoID) (map[tracev2.GoID]s
operand tracev2.GoID
}
var unblockEdges []unblockEdge
for {
ev, err := r.ReadEvent()
if err == io.EOF {
break
}
if err != nil {
return nil, err
}
for _, ev := range events {
if ev.Goroutine() == tracev2.NoGoroutine {
continue
}
Expand Down Expand Up @@ -660,5 +648,5 @@ func RelatedGoroutinesV2(trace io.Reader, goid tracev2.GoID) (map[tracev2.GoID]s
}
gmap = gmap1
}
return gmap, nil
return gmap
}
26 changes: 22 additions & 4 deletions src/internal/trace/summary_test.go
Original file line number Diff line number Diff line change
Expand Up @@ -375,15 +375,33 @@ func basicGoroutineExecStatsChecks(t *testing.T, stats *GoroutineExecStats) {

func TestRelatedGoroutinesV2Trace(t *testing.T) {
testPath := "v2/testdata/tests/go122-gc-stress.test"
r, _, err := testtrace.ParseFile(testPath)
trace, _, err := testtrace.ParseFile(testPath)
if err != nil {
t.Fatalf("malformed test %s: bad trace file: %v", testPath, err)
}
targetg := tracev2.GoID(86)
got, err := RelatedGoroutinesV2(r, targetg)

// Create a reader.
r, err := tracev2.NewReader(trace)
if err != nil {
t.Fatalf("failed to find related goroutines for %s: %v", testPath, err)
t.Fatalf("failed to create trace reader for %s: %v", testPath, err)
}

// Collect all the events.
var events []tracev2.Event
for {
ev, err := r.ReadEvent()
if err == io.EOF {
break
}
if err != nil {
t.Fatalf("failed to process trace %s: %v", testPath, err)
}
events = append(events, ev)
}

// Test the function.
targetg := tracev2.GoID(86)
got := RelatedGoroutinesV2(events, targetg)
want := map[tracev2.GoID]struct{}{
tracev2.GoID(86): struct{}{}, // N.B. Result includes target.
tracev2.GoID(71): struct{}{},
Expand Down

0 comments on commit 64c12ba

Please sign in to comment.