cmd/trace: extend trace view (/trace) for task-oriented view

R=go1.11

Change-Id: I2d2db148fed96d0fcb228bee414b050fe4e46e2c
Reviewed-on: https://go-review.googlesource.com/90217
Reviewed-by: Heschi Kreinick <heschi@google.com>

2 files changed, 158 insertions, 17 deletions

diff --git a/src/cmd/trace/annotations.go b/src/cmd/trace/annotations.go
index 680f39aa1a..c69f62cae5 100644
--- a/src/cmd/trace/annotations.go
+++ b/src/cmd/trace/annotations.go
@@ -332,6 +332,57 @@ func (task *taskDesc) lastEvent() *trace.Event {
 	return nil
 }
 
+// firstTimestamp returns the timestamp of span start event.
+// If the span's start event is not present in the trace,
+// the first timestamp of the task will be returned.
+func (span *spanDesc) firstTimestamp() int64 {
+	if span.start != nil {
+		return span.start.Ts
+	}
+	return span.task.firstTimestamp()
+}
+
+// lastTimestamp returns the timestamp of span end event.
+// If the span's end event is not present in the trace,
+// the last timestamp of the task will be returned.
+func (span *spanDesc) lastTimestamp() int64 {
+	if span.end != nil {
+		return span.end.Ts
+	}
+	return span.task.lastTimestamp()
+}
+
+// RelatedGoroutines returns IDs of goroutines related to the task. A goroutine
+// is related to the task if user annotation activities for the task occurred.
+// If non-zero depth is provided, this searches all events with BFS and includes
+// goroutines unblocked any of related goroutines to the result.
+func (task *taskDesc) RelatedGoroutines(events []*trace.Event, depth int) map[uint64]bool {
+	start, end := task.firstTimestamp(), task.lastTimestamp()
+
+	gmap := map[uint64]bool{}
+	for k := range task.goroutines {
+		gmap[k] = true
+	}
+
+	for i := 0; i < depth; i++ {
+		gmap1 := make(map[uint64]bool)
+		for g := range gmap {
+			gmap1[g] = true
+		}
+		for _, ev := range events {
+			if ev.Ts < start || ev.Ts > end {
+				continue
+			}
+			if ev.Type == trace.EvGoUnblock && gmap[ev.Args[0]] {
+				gmap1[ev.G] = true
+			}
+			gmap = gmap1
+		}
+	}
+	gmap[0] = true // for GC events (goroutine id = 0)
+	return gmap
+}
+
 type taskFilter struct {
 	name string
 	cond []func(*taskDesc) bool
diff --git a/src/cmd/trace/trace.go b/src/cmd/trace/trace.go
index 7d1ed94267..c9536c1246 100644
--- a/src/cmd/trace/trace.go
+++ b/src/cmd/trace/trace.go
@@ -184,11 +184,30 @@ func httpJsonTrace(w http.ResponseWriter, r *http.Request) {
 		}
 		analyzeGoroutines(res.Events)
 		g := gs[goid]
-		params.gtrace = true
+		params.mode = goroutineTraceview
 		params.startTime = g.StartTime
 		params.endTime = g.EndTime
 		params.maing = goid
 		params.gs = trace.RelatedGoroutines(res.Events, goid)
+	} else if taskids := r.FormValue("taskid"); taskids != "" {
+		taskid, err := strconv.ParseUint(taskids, 10, 64)
+		if err != nil {
+			log.Printf("failed to parse taskid parameter %q: %v", taskids, err)
+			return
+		}
+		tasks, _ := analyzeAnnotations()
+		task, ok := tasks[taskid]
+		if !ok {
+			log.Printf("failed to find task with id %d", taskid)
+			return
+		}
+		goid := task.events[0].G
+		params.mode = taskTraceview
+		params.startTime = task.firstTimestamp() - 1
+		params.endTime = task.lastTimestamp() + 1
+		params.maing = goid
+		params.gs = task.RelatedGoroutines(res.Events, 0) // find only directly involved goroutines
+		params.showTask = task
 	}
 
 	data, err := generateTrace(params)
@@ -272,13 +291,22 @@ func (cw *countingWriter) Write(data []byte) (int, error) {
 
 type traceParams struct {
 	parsed    trace.ParseResult
-	gtrace    bool
+	mode      traceviewMode
 	startTime int64
 	endTime   int64
-	maing     uint64
-	gs        map[uint64]bool
+	maing     uint64          // for goroutine-oriented view, place this goroutine on the top row
+	gs        map[uint64]bool // Goroutines to be displayed for goroutine-oriented or task-oriented view
+	showTask  *taskDesc       // Task to be displayed
 }
 
+type traceviewMode int
+
+const (
+	defaultTraceview traceviewMode = iota
+	goroutineTraceview
+	taskTraceview
+)
+
 type traceContext struct {
 	*traceParams
 	data      ViewerData
@@ -349,6 +377,8 @@ type ViewerEvent struct {
 	Stack    int         `json:"sf,omitempty"`
 	EndStack int         `json:"esf,omitempty"`
 	Arg      interface{} `json:"args,omitempty"`
+	Cname    string      `json:"cname,omitempty"`
+	Category string      `json:"cat,omitempty"`
 }
 
 type ViewerFrame struct {
@@ -368,7 +398,7 @@ type SortIndexArg struct {
 // https://github.com/google/trace-viewer
 // Trace format is described at:
 // https://docs.google.com/document/d/1CvAClvFfyA5R-PhYUmn5OOQtYMH4h6I0nSsKchNAySU/view
-// If gtrace=true, generate trace for goroutine goid, otherwise whole trace.
+// If mode==goroutineMode, generate trace for goroutine goid, otherwise whole trace.
 // startTime, endTime determine part of the trace that we are interested in.
 // gset restricts goroutines that are included in the resulting trace.
 func generateTrace(params *traceParams) (ViewerData, error) {
@@ -493,7 +523,7 @@ func generateTrace(params *traceParams) (ViewerData, error) {
 		if ctx.gs != nil && ev.P < trace.FakeP && !ctx.gs[ev.G] {
 			continue
 		}
-		if ev.Ts < ctx.startTime || ev.Ts > ctx.endTime {
+		if !withinTimerange(ev, ctx.startTime, ctx.endTime) {
 			continue
 		}
 
@@ -504,12 +534,12 @@ func generateTrace(params *traceParams) (ViewerData, error) {
 		// Emit trace objects.
 		switch ev.Type {
 		case trace.EvProcStart:
-			if ctx.gtrace {
+			if ctx.mode != defaultTraceview {
 				continue
 			}
 			ctx.emitInstant(ev, "proc start")
 		case trace.EvProcStop:
-			if ctx.gtrace {
+			if ctx.mode != defaultTraceview {
 				continue
 			}
 			ctx.emitInstant(ev, "proc stop")
@@ -517,7 +547,7 @@ func generateTrace(params *traceParams) (ViewerData, error) {
 			ctx.emitSlice(ev, "GC")
 		case trace.EvGCDone:
 		case trace.EvGCSTWStart:
-			if ctx.gtrace {
+			if ctx.mode != defaultTraceview {
 				continue
 			}
 			ctx.emitSlice(ev, fmt.Sprintf("STW (%s)", ev.SArgs[0]))
@@ -597,21 +627,38 @@ func generateTrace(params *traceParams) (ViewerData, error) {
 	ctx.emit(&ViewerEvent{Name: "thread_name", Phase: "M", Pid: 0, Tid: trace.SyscallP, Arg: &NameArg{"Syscalls"}})
 	ctx.emit(&ViewerEvent{Name: "thread_sort_index", Phase: "M", Pid: 0, Tid: trace.SyscallP, Arg: &SortIndexArg{-3}})
 
-	if !ctx.gtrace {
+	if ctx.mode == defaultTraceview {
 		for i := 0; i <= maxProc; i++ {
 			ctx.emit(&ViewerEvent{Name: "thread_name", Phase: "M", Pid: 0, Tid: uint64(i), Arg: &NameArg{fmt.Sprintf("Proc %v", i)}})
 			ctx.emit(&ViewerEvent{Name: "thread_sort_index", Phase: "M", Pid: 0, Tid: uint64(i), Arg: &SortIndexArg{i}})
 		}
 	}
 
-	if ctx.gtrace && ctx.gs != nil {
+	// Display task and its spans
+	taskRow := uint64(trace.GCP + 1)
+	if task := ctx.showTask; task != nil {
+		taskName := fmt.Sprintf("Task %s(%d)", task.name, task.id)
+		ctx.emit(&ViewerEvent{Name: "thread_name", Phase: "M", Pid: 0, Tid: taskRow, Arg: &NameArg{"Tasks"}})
+		ctx.emit(&ViewerEvent{Name: "thread_sort_index", Phase: "M", Pid: 0, Tid: taskRow, Arg: &SortIndexArg{-3}})
+		ctx.emit(&ViewerEvent{Category: "task", Name: taskName, Phase: "b", Time: float64(task.firstTimestamp()) / 1e3, Tid: taskRow, ID: task.id, Cname: "bad"})
+		ctx.emit(&ViewerEvent{Category: "task", Name: taskName, Phase: "e", Time: float64(task.lastTimestamp()) / 1e3, Tid: taskRow, ID: task.id, Cname: "bad"})
+		// Spans
+		for _, s := range task.spans {
+			ctx.emitSpan(s)
+		}
+	}
+
+	if ctx.mode != defaultTraceview && ctx.gs != nil {
 		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.name}})
 		}
+		// Row for the main goroutine (maing)
 		ctx.emit(&ViewerEvent{Name: "thread_sort_index", Phase: "M", Pid: 0, Tid: ctx.maing, Arg: &SortIndexArg{-2}})
+
+		// Row for GC or global state (specified with G=0)
 		ctx.emit(&ViewerEvent{Name: "thread_sort_index", Phase: "M", Pid: 0, Tid: 0, Arg: &SortIndexArg{-1}})
 	}
 
@@ -624,11 +671,18 @@ func (ctx *traceContext) emit(e *ViewerEvent) {
 
 func (ctx *traceContext) time(ev *trace.Event) float64 {
 	// Trace viewer wants timestamps in microseconds.
-	return float64(ev.Ts-ctx.startTime) / 1000
+	return float64(ev.Ts) / 1000
+}
+
+func withinTimerange(ev *trace.Event, s, e int64) bool {
+	if evEnd := ev.Link; evEnd != nil {
+		return ev.Ts <= e && evEnd.Ts >= s
+	}
+	return ev.Ts >= s && ev.Ts <= e
 }
 
 func (ctx *traceContext) proc(ev *trace.Event) uint64 {
-	if ctx.gtrace && ev.P < trace.FakeP {
+	if ctx.mode != defaultTraceview && ev.P < trace.FakeP {
 		return ev.G
 	} else {
 		return uint64(ev.P)
@@ -649,13 +703,49 @@ func (ctx *traceContext) emitSlice(ev *trace.Event, name string) *ViewerEvent {
 	return sl
 }
 
+func (ctx *traceContext) emitSpan(s *spanDesc) {
+	id := uint64(0)
+	if task := s.task; task != nil {
+		id = task.id
+	}
+	scopeID := fmt.Sprintf("%x", id)
+
+	sl0 := &ViewerEvent{
+		Category: "Span",
+		Name:     s.name,
+		Phase:    "b",
+		Time:     float64(s.firstTimestamp()) / 1e3,
+		Tid:      s.goid,
+		ID:       s.goid,
+		Scope:    scopeID,
+	}
+	if s.start != nil {
+		sl0.Stack = ctx.stack(s.start.Stk)
+	}
+	ctx.emit(sl0)
+
+	sl1 := &ViewerEvent{
+		Category: "Span",
+		Name:     s.name,
+		Phase:    "e",
+		Time:     float64(s.lastTimestamp()) / 1e3,
+		Tid:      s.goid,
+		ID:       s.goid,
+		Scope:    scopeID,
+	}
+	if s.end != nil {
+		sl1.Stack = ctx.stack(s.end.Stk)
+	}
+	ctx.emit(sl1)
+}
+
 type heapCountersArg struct {
 	Allocated uint64
 	NextGC    uint64
 }
 
 func (ctx *traceContext) emitHeapCounters(ev *trace.Event) {
-	if ctx.gtrace {
+	if ctx.mode == goroutineTraceview {
 		return
 	}
 	if ctx.prevHeapStats == ctx.heapStats {
@@ -676,7 +766,7 @@ type goroutineCountersArg struct {
 }
 
 func (ctx *traceContext) emitGoroutineCounters(ev *trace.Event) {
-	if ctx.gtrace {
+	if ctx.mode == goroutineTraceview {
 		return
 	}
 	if ctx.prevGstates == ctx.gstates {
@@ -692,7 +782,7 @@ type threadCountersArg struct {
 }
 
 func (ctx *traceContext) emitThreadCounters(ev *trace.Event) {
-	if ctx.gtrace {
+	if ctx.mode == goroutineTraceview {
 		return
 	}
 	if ctx.prevThreadStats == ctx.threadStats {
@@ -721,7 +811,7 @@ func (ctx *traceContext) emitArrow(ev *trace.Event, name string) {
 		// For example, a goroutine was unblocked but was not scheduled before trace stop.
 		return
 	}
-	if ctx.gtrace && (!ctx.gs[ev.Link.G] || ev.Link.Ts < ctx.startTime || ev.Link.Ts > ctx.endTime) {
+	if ctx.mode != defaultTraceview && (!ctx.gs[ev.Link.G] || ev.Link.Ts < ctx.startTime || ev.Link.Ts > ctx.endTime) {
 		return
 	}