cmd/trace/v2: add support for a task-oriented procs-based view

This change implements support for the trace?focustask=<taskid> endpoint
in the trace tool for v2 traces.

Note: the one missing feature in v2 vs. v1 is that the "irrelevant" (but
still rendered) events are not grayed out. This basically includes
events that overlapped with events that overlapped with other events
that were in the task time period, but aren't themselves directly
associated. This is probably fine -- the UI already puts a very obvious
focus on the period of time the selected task was running.

For #60773.
For #63960.

Change-Id: I5c78a220ae816e331b74cb67c01c5cd98be40dd4
Reviewed-on: https://go-review.googlesource.com/c/go/+/543596
Auto-Submit: Michael Knyszek <[email protected]>
LUCI-TryBot-Result: Go LUCI <[email protected]>
Reviewed-by: Michael Pratt <[email protected]>

Author: mknyszek

src/cmd/trace/trace.go

@@ -210,7 +210,6 @@ type SortIndexArg struct {
 func generateTrace(params *traceParams, consumer traceviewer.TraceConsumer) error {
 	emitter := traceviewer.NewEmitter(
 		consumer,
-		params.mode,
 		time.Duration(params.startTime),
 		time.Duration(params.endTime),
 	)
@@ -565,8 +564,7 @@ func (ctx *traceContext) emitTask(task *taskDesc, sortIndex int) {
 	taskName := task.name
 	durationUsec := float64(task.lastTimestamp()-task.firstTimestamp()) / 1e3
 
-	ctx.emitFooter(&format.Event{Name: "thread_name", Phase: "M", PID: format.TasksSection, TID: taskRow, Arg: &NameArg{fmt.Sprintf("T%d %s", task.id, taskName)}})
-	ctx.emit(&format.Event{Name: "thread_sort_index", Phase: "M", PID: format.TasksSection, TID: taskRow, Arg: &SortIndexArg{sortIndex}})
+	ctx.emitter.Task(taskRow, taskName, sortIndex)
 	ts := float64(task.firstTimestamp()) / 1e3
 	sl := &format.Event{
 		Name:  taskName,

src/cmd/trace/v2/gen.go

@@ -5,6 +5,7 @@
 package trace
 
 import (
+	"fmt"
 	"internal/trace"
 	"internal/trace/traceviewer"
 	tracev2 "internal/trace/v2"
@@ -31,11 +32,11 @@ type generator interface {
 	ProcTransition(ctx *traceContext, ev *tracev2.Event)
 
 	// Finish indicates the end of the trace and finalizes generation.
-	Finish(ctx *traceContext, endTime tracev2.Time)
+	Finish(ctx *traceContext)
 }
 
 // runGenerator produces a trace into ctx by running the generator over the parsed trace.
-func runGenerator(ctx *traceContext, g generator, parsed *parsedTrace) {
+func runGenerator(ctx *traceContext, g generator, parsed *parsedTrace, opts *genOpts) {
 	for i := range parsed.events {
 		ev := &parsed.events[i]
 
@@ -70,7 +71,63 @@ func runGenerator(ctx *traceContext, g generator, parsed *parsedTrace) {
 			}
 		}
 	}
-	g.Finish(ctx, parsed.events[len(parsed.events)-1].Time())
+	for i, task := range opts.tasks {
+		emitTask(ctx, task, i)
+	}
+	g.Finish(ctx)
+}
+
+// emitTask emits information about a task into the trace viewer's event stream.
+//
+// sortIndex sets the order in which this task will appear related to other tasks,
+// lowest first.
+func emitTask(ctx *traceContext, task *trace.UserTaskSummary, sortIndex int) {
+	// Collect information about the task.
+	var startStack, endStack tracev2.Stack
+	var startG, endG tracev2.GoID
+	startTime, endTime := ctx.startTime, ctx.endTime
+	if task.Start != nil {
+		startStack = task.Start.Stack()
+		startG = task.Start.Goroutine()
+		startTime = task.Start.Time()
+	}
+	if task.End != nil {
+		endStack = task.End.Stack()
+		endG = task.End.Goroutine()
+		endTime = task.End.Time()
+	}
+	arg := struct {
+		ID     uint64 `json:"id"`
+		StartG uint64 `json:"start_g,omitempty"`
+		EndG   uint64 `json:"end_g,omitempty"`
+	}{
+		ID:     uint64(task.ID),
+		StartG: uint64(startG),
+		EndG:   uint64(endG),
+	}
+
+	// Emit the task slice and notify the emitter of the task.
+	ctx.Task(uint64(task.ID), fmt.Sprintf("T%d %s", task.ID, task.Name), sortIndex)
+	ctx.TaskSlice(traceviewer.SliceEvent{
+		Name:     task.Name,
+		Ts:       ctx.elapsed(startTime),
+		Dur:      endTime.Sub(startTime),
+		Resource: uint64(task.ID),
+		Stack:    ctx.Stack(viewerFrames(startStack)),
+		EndStack: ctx.Stack(viewerFrames(endStack)),
+		Arg:      arg,
+	})
+	// Emit an arrow from the parent to the child.
+	if task.Parent != nil && task.Start != nil && task.Start.Kind() == tracev2.EventTaskBegin {
+		ctx.TaskArrow(traceviewer.ArrowEvent{
+			Name:         "newTask",
+			Start:        ctx.elapsed(task.Start.Time()),
+			End:          ctx.elapsed(task.Start.Time()),
+			FromResource: uint64(task.Parent.ID),
+			ToResource:   uint64(task.ID),
+			FromStack:    ctx.Stack(viewerFrames(task.Start.Stack())),
+		})
+	}
 }
 
 // Building blocks for generators.
@@ -144,15 +201,15 @@ func (g *globalRangeGenerator) GlobalRange(ctx *traceContext, ev *tracev2.Event)
 }
 
 // Finish flushes any outstanding ranges at the end of the trace.
-func (g *globalRangeGenerator) Finish(ctx *traceContext, endTime tracev2.Time) {
+func (g *globalRangeGenerator) Finish(ctx *traceContext) {
 	for name, ar := range g.ranges {
 		if !strings.Contains(name, "GC") {
 			continue
 		}
 		ctx.Slice(traceviewer.SliceEvent{
 			Name:     name,
 			Ts:       ctx.elapsed(ar.time),
-			Dur:      endTime.Sub(ar.time),
+			Dur:      ctx.endTime.Sub(ar.time),
 			Resource: trace.GCP,
 			Stack:    ctx.Stack(viewerFrames(ar.stack)),
 		})
@@ -220,12 +277,12 @@ func (g *procRangeGenerator) ProcRange(ctx *traceContext, ev *tracev2.Event) {
 }
 
 // Finish flushes any outstanding ranges at the end of the trace.
-func (g *procRangeGenerator) Finish(ctx *traceContext, endTime tracev2.Time) {
+func (g *procRangeGenerator) Finish(ctx *traceContext) {
 	for r, ar := range g.ranges {
 		ctx.Slice(traceviewer.SliceEvent{
 			Name:     r.Name,
 			Ts:       ctx.elapsed(ar.time),
-			Dur:      endTime.Sub(ar.time),
+			Dur:      ctx.endTime.Sub(ar.time),
 			Resource: uint64(r.Scope.Proc()),
 			Stack:    ctx.Stack(viewerFrames(ar.stack)),
 		})

src/cmd/trace/v2/goroutinegen.go

@@ -143,15 +143,15 @@ 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) {
+func (g *goroutineGenerator) Finish(ctx *traceContext) {
 	ctx.SetResourceType("G")
 
 	// Finish off global ranges.
-	g.globalRangeGenerator.Finish(ctx, endTime)
+	g.globalRangeGenerator.Finish(ctx)
 
 	// Finish off all the goroutine slices.
 	for id, gs := range g.gStates {
-		gs.finish(endTime, ctx)
+		gs.finish(ctx)
 
 		// Tell the emitter about the goroutines we want to render.
 		ctx.Resource(uint64(id), gs.name())

src/cmd/trace/v2/gstate.go

@@ -305,10 +305,10 @@ func (gs *gState[R]) stop(ts tracev2.Time, stack tracev2.Stack, ctx *traceContex
 // This must only be used once the trace has been fully processed and no
 // further events will be processed. This method may leave the gState in
 // an inconsistent state.
-func (gs *gState[R]) finish(ts tracev2.Time, ctx *traceContext) {
+func (gs *gState[R]) finish(ctx *traceContext) {
 	if gs.executing != R(noResource) {
-		gs.syscallEnd(ts, false, ctx)
-		gs.stop(ts, tracev2.NoStack, ctx)
+		gs.syscallEnd(ctx.endTime, false, ctx)
+		gs.stop(ctx.endTime, tracev2.NoStack, ctx)
 	}
 }
 

src/cmd/trace/v2/jsontrace.go

@@ -5,9 +5,11 @@
 package trace
 
 import (
+	"cmp"
 	"log"
 	"math"
 	"net/http"
+	"slices"
 	"strconv"
 	"time"
 
@@ -47,6 +49,50 @@ func JSONTraceHandler(parsed *parsedTrace) http.Handler {
 			}
 			opts.focusGoroutine = goid
 			opts.goroutines = trace.RelatedGoroutinesV2(parsed.events, goid)
+		} else if taskids := r.FormValue("focustask"); taskids != "" {
+			taskid, err := strconv.ParseUint(taskids, 10, 64)
+			if err != nil {
+				log.Printf("failed to parse focustask parameter %q: %v", taskids, err)
+				return
+			}
+			task, ok := parsed.summary.Tasks[tracev2.TaskID(taskid)]
+			if !ok || (task.Start == nil && task.End == nil) {
+				log.Printf("failed to find task with id %d", taskid)
+				return
+			}
+			opts.mode = traceviewer.ModeTaskOriented
+			if task.Start != nil {
+				opts.startTime = task.Start.Time().Sub(parsed.startTime())
+			} else { // The task started before the trace did.
+				opts.startTime = 0
+			}
+			if task.End != nil {
+				opts.endTime = task.End.Time().Sub(parsed.startTime())
+			} else { // The task didn't end.
+				opts.endTime = parsed.endTime().Sub(parsed.startTime())
+			}
+			opts.tasks = task.Descendents()
+			slices.SortStableFunc(opts.tasks, func(a, b *trace.UserTaskSummary) int {
+				aStart, bStart := parsed.startTime(), parsed.startTime()
+				if a.Start != nil {
+					aStart = a.Start.Time()
+				}
+				if b.Start != nil {
+					bStart = b.Start.Time()
+				}
+				if a.Start != b.Start {
+					return cmp.Compare(aStart, bStart)
+				}
+				// Break ties with the end time.
+				aEnd, bEnd := parsed.endTime(), parsed.endTime()
+				if a.End != nil {
+					aEnd = a.End.Time()
+				}
+				if b.End != nil {
+					bEnd = b.End.Time()
+				}
+				return cmp.Compare(aEnd, bEnd)
+			})
 		}
 
 		// Parse start and end options. Both or none must be present.
@@ -79,6 +125,7 @@ func JSONTraceHandler(parsed *parsedTrace) http.Handler {
 type traceContext struct {
 	*traceviewer.Emitter
 	startTime tracev2.Time
+	endTime   tracev2.Time
 }
 
 // elapsed returns the elapsed time between the trace time and the start time
@@ -95,6 +142,7 @@ type genOpts struct {
 	// 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.
+	tasks          []*trace.UserTaskSummary
 }
 
 func defaultGenOpts() *genOpts {
@@ -106,8 +154,9 @@ func defaultGenOpts() *genOpts {
 
 func generateTrace(parsed *parsedTrace, opts *genOpts, c traceviewer.TraceConsumer) error {
 	ctx := &traceContext{
-		Emitter:   traceviewer.NewEmitter(c, 0, opts.startTime, opts.endTime),
+		Emitter:   traceviewer.NewEmitter(c, opts.startTime, opts.endTime),
 		startTime: parsed.events[0].Time(),
+		endTime:   parsed.events[len(parsed.events)-1].Time(),
 	}
 	defer ctx.Flush()
 
@@ -117,6 +166,6 @@ func generateTrace(parsed *parsedTrace, opts *genOpts, c traceviewer.TraceConsum
 	} else {
 		g = newProcGenerator()
 	}
-	runGenerator(ctx, g, parsed)
+	runGenerator(ctx, g, parsed, opts)
 	return nil
 }

src/cmd/trace/v2/procgen.go

@@ -188,18 +188,18 @@ func (g *procGenerator) ProcTransition(ctx *traceContext, ev *tracev2.Event) {
 	}
 }
 
-func (g *procGenerator) Finish(ctx *traceContext, endTime tracev2.Time) {
+func (g *procGenerator) Finish(ctx *traceContext) {
 	ctx.SetResourceType("PROCS")
 
 	// Finish off ranges first. It doesn't really matter for the global ranges,
 	// but the proc ranges need to either be a subset of a goroutine slice or
 	// their own slice entirely. If the former, it needs to end first.
-	g.procRangeGenerator.Finish(ctx, endTime)
-	g.globalRangeGenerator.Finish(ctx, endTime)
+	g.procRangeGenerator.Finish(ctx)
+	g.globalRangeGenerator.Finish(ctx)
 
 	// Finish off all the goroutine slices.
 	for _, gs := range g.gStates {
-		gs.finish(endTime, ctx)
+		gs.finish(ctx)
 	}
 
 	// Name all the procs to the emitter.

src/internal/trace/summary.go

@@ -50,7 +50,7 @@ type UserTaskSummary struct {
 	// Task begin event. An EventTaskBegin event or nil.
 	Start *tracev2.Event
 
-	// End end event. Normally EventTaskEnd event or nil,
+	// End end event. Normally EventTaskEnd event or nil.
 	End *tracev2.Event
 
 	// Logs is a list of tracev2.EventLog events associated with the task.
@@ -69,6 +69,16 @@ func (s *UserTaskSummary) Complete() bool {
 	return s.Start != nil && s.End != nil
 }
 
+// Descendents returns a slice consisting of itself (always the first task returned),
+// and the transitive closure of all of its children.
+func (s *UserTaskSummary) Descendents() []*UserTaskSummary {
+	descendents := []*UserTaskSummary{s}
+	for _, child := range s.Children {
+		descendents = append(descendents, child.Descendents()...)
+	}
+	return descendents
+}
+
 // UserRegionSummary represents a region and goroutine execution stats
 // while the region was active. (For v2 traces.)
 type UserRegionSummary struct {