cmd/trace: implement /trace?focustask=<taskid> mode

This mode is similar to the default traceview mode where the execution
trace is presented in P-oriented way. Each row represents a P, and each
slice represents the time interval of a goroutine's execution on the P.

The difference is that, in this mode, only the execution of goroutines
involved in the specified task is highlighted, and other goroutine
execution or events are greyed out. So, users can focus on how a task is
executed while considering other affecting conditions such as other
goroutines, network events, or process scheduling.

Example: https://user-images.githubusercontent.com/4999471/38116793-a6f995f0-337f-11e8-8de9-88eec2f2c497.png

Here, for a while the program remained idle after the first burst of
activity related to the task because all other goroutines were also
being blocked or waiting for events, or no incoming network traffic
(indicated by the lack of any network activity). This is a bit hard to
discover when the usual task-oriented view (/trace?taskid=<taskid>)
mode.

Also, it simplifies the traceview generation mode logic.
  /trace ---> 0
  /trace?goid ---> modeGoroutineOriented
  /trace?taskid ---> modeGoroutineOriented|modeTaskOriented
  /trace?focustask ---> modeTaskOriented

Change-Id: Idcc0ae31b708ddfd19766f4e26ee7efdafecd3a5
Reviewed-on: https://go-review.googlesource.com/103555
Run-TryBot: Hyang-Ah Hana Kim <hyangah@gmail.com>
Reviewed-by: Heschi Kreinick <heschi@google.com>

diff --git a/src/cmd/trace/trace.go b/src/cmd/trace/trace.go
index 46d67cd6870fa2c31064ed7860cabd91269a27e7..12d8dec7539245be52a703bb38790f1f2fd6ffa9 100644 (file)
--- a/src/cmd/trace/trace.go
+++ b/src/cmd/trace/trace.go
@@ -189,9 +189,13 @@ func httpJsonTrace(w http.ResponseWriter, r *http.Request) {
                }
                analyzeGoroutines(res.Events)
                g := gs[goid]
-               params.mode = goroutineTraceview
+               params.mode = modeGoroutineOriented
                params.startTime = g.StartTime
-               params.endTime = g.EndTime
+               if g.EndTime != 0 {
+                       params.endTime = g.EndTime
+               } else { // The goroutine didn't end.
+                       params.endTime = lastTimestamp()
+               }
                params.maing = goid
                params.gs = trace.RelatedGoroutines(res.Events, goid)
        } else if taskids := r.FormValue("taskid"); taskids != "" {
@@ -207,7 +211,7 @@ func httpJsonTrace(w http.ResponseWriter, r *http.Request) {
                        return
                }
                goid := task.events[0].G
-               params.mode = taskTraceview
+               params.mode = modeGoroutineOriented | modeTaskOriented
                params.startTime = task.firstTimestamp() - 1
                params.endTime = task.lastTimestamp() + 1
                params.maing = goid
@@ -220,6 +224,22 @@ func httpJsonTrace(w http.ResponseWriter, r *http.Request) {
                        }
                }
                params.gs = gs
+       } 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
+               }
+               annotRes, _ := analyzeAnnotations()
+               task, ok := annotRes.tasks[taskid]
+               if !ok || len(task.events) == 0 {
+                       log.Printf("failed to find task with id %d", taskid)
+                       return
+               }
+               params.mode = modeTaskOriented
+               params.startTime = task.firstTimestamp() - 1
+               params.endTime = task.lastTimestamp() + 1
+               params.tasks = task.decendents()
        }
 
        start := int64(0)
@@ -366,12 +386,11 @@ type traceParams struct {
        tasks     []*taskDesc     // Tasks to be displayed. tasks[0] is the top-most task
 }
 
-type traceviewMode int
+type traceviewMode uint
 
 const (
-       defaultTraceview traceviewMode = iota
-       goroutineTraceview
-       taskTraceview
+       modeGoroutineOriented traceviewMode = 1 << iota
+       modeTaskOriented
 )
 
 type traceContext struct {
@@ -600,7 +619,7 @@ func generateTrace(params *traceParams, consumer traceConsumer) error {
                if ctx.gs != nil && ev.P < trace.FakeP && !ctx.gs[ev.G] {
                        continue
                }
-               if !withinTimerange(ev, ctx.startTime, ctx.endTime) {
+               if !withinTimeRange(ev, ctx.startTime, ctx.endTime) {
                        continue
                }
 
@@ -611,12 +630,12 @@ func generateTrace(params *traceParams, consumer traceConsumer) error {
                // Emit trace objects.
                switch ev.Type {
                case trace.EvProcStart:
-                       if ctx.mode != defaultTraceview {
+                       if ctx.mode&modeGoroutineOriented != 0 {
                                continue
                        }
                        ctx.emitInstant(ev, "proc start", "")
                case trace.EvProcStop:
-                       if ctx.mode != defaultTraceview {
+                       if ctx.mode&modeGoroutineOriented != 0 {
                                continue
                        }
                        ctx.emitInstant(ev, "proc stop", "")
@@ -624,7 +643,7 @@ func generateTrace(params *traceParams, consumer traceConsumer) error {
                        ctx.emitSlice(ev, "GC")
                case trace.EvGCDone:
                case trace.EvGCSTWStart:
-                       if ctx.mode != defaultTraceview {
+                       if ctx.mode&modeGoroutineOriented != 0 {
                                continue
                        }
                        ctx.emitSlice(ev, fmt.Sprintf("STW (%s)", ev.SArgs[0]))
@@ -709,16 +728,16 @@ func generateTrace(params *traceParams, consumer traceConsumer) error {
        ctx.emitFooter(&ViewerEvent{Name: "thread_name", Phase: "M", Pid: 0, Tid: trace.SyscallP, Arg: &NameArg{"Syscalls"}})
        ctx.emitFooter(&ViewerEvent{Name: "thread_sort_index", Phase: "M", Pid: 0, Tid: trace.SyscallP, Arg: &SortIndexArg{-3}})
 
-       // Display rows for Ps if we are in the default trace view mode.
-       if ctx.mode == defaultTraceview {
+       // Display rows for Ps if we are in the default trace view mode (not goroutine-oriented presentation)
+       if ctx.mode&modeGoroutineOriented != 0 {
                for i := 0; i <= maxProc; i++ {
                        ctx.emitFooter(&ViewerEvent{Name: "thread_name", Phase: "M", Pid: 0, Tid: uint64(i), Arg: &NameArg{fmt.Sprintf("Proc %v", i)}})
                        ctx.emitFooter(&ViewerEvent{Name: "thread_sort_index", Phase: "M", Pid: 0, Tid: uint64(i), Arg: &SortIndexArg{i}})
                }
        }
 
-       // Display task and its spans if we are in the taskTrace view mode.
-       if ctx.mode == taskTraceview {
+       // Display task and its spans if we are in task-oriented presentation mode.
+       if ctx.mode&modeTaskOriented != 0 {
                taskRow := uint64(trace.GCP + 1)
                for _, task := range ctx.tasks {
                        taskName := fmt.Sprintf("Task %s(%d)", task.name, task.id)
@@ -736,15 +755,18 @@ func generateTrace(params *traceParams, consumer traceConsumer) error {
                        }
                        ctx.emit(tEnd)
 
-                       // Spans
-                       for i, s := range task.spans {
-                               ctx.emitSpan(s, i)
+                       // If we are in goroutine-oriented mode, we draw spans.
+                       // TODO(hyangah): add this for task/P-oriented mode (i.e., focustask view) too.
+                       if ctx.mode&modeGoroutineOriented != 0 {
+                               for i, s := range task.spans {
+                                       ctx.emitSpan(s, i)
+                               }
                        }
                }
        }
 
-       // Display goroutine rows if we are either in gtrace or taskTrace view mode.
-       if ctx.mode != defaultTraceview && ctx.gs != nil {
+       // Display goroutine rows if we are either in goroutine-oriented mode.
+       if ctx.mode&modeGoroutineOriented != 0 {
                for k, v := range ginfos {
                        if !ctx.gs[k] {
                                continue
@@ -773,15 +795,19 @@ func (ctx *traceContext) time(ev *trace.Event) float64 {
        return float64(ev.Ts) / 1000
 }
 
-func withinTimerange(ev *trace.Event, s, e int64) bool {
+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 tsWithinRange(ts, s, e int64) bool {
+       return s <= ts && ts <= e
+}
+
 func (ctx *traceContext) proc(ev *trace.Event) uint64 {
-       if ctx.mode != defaultTraceview && ev.P < trace.FakeP {
+       if ctx.mode&modeGoroutineOriented != 0 && ev.P < trace.FakeP {
                return ev.G
        } else {
                return uint64(ev.P)
@@ -800,7 +826,7 @@ func (ctx *traceContext) emitSlice(ev *trace.Event, name string) *ViewerEvent {
        }
 
        // grey out non-overlapping events if the event is not a global event (ev.G == 0)
-       if ctx.mode == taskTraceview && ev.G != 0 {
+       if ctx.mode&modeTaskOriented != 0 && ev.G != 0 {
                // include P information.
                if t := ev.Type; t == trace.EvGoStart || t == trace.EvGoStartLabel {
                        type Arg struct {
@@ -868,9 +894,6 @@ type heapCountersArg struct {
 }
 
 func (ctx *traceContext) emitHeapCounters(ev *trace.Event) {
-       if ctx.mode == goroutineTraceview {
-               return
-       }
        if ctx.prevHeapStats == ctx.heapStats {
                return
        }
@@ -878,7 +901,9 @@ func (ctx *traceContext) emitHeapCounters(ev *trace.Event) {
        if ctx.heapStats.nextGC > ctx.heapStats.heapAlloc {
                diff = ctx.heapStats.nextGC - ctx.heapStats.heapAlloc
        }
-       ctx.emit(&ViewerEvent{Name: "Heap", Phase: "C", Time: ctx.time(ev), Pid: 1, Arg: &heapCountersArg{ctx.heapStats.heapAlloc, diff}})
+       if tsWithinRange(ev.Ts, ctx.startTime, ctx.endTime) {
+               ctx.emit(&ViewerEvent{Name: "Heap", Phase: "C", Time: ctx.time(ev), Pid: 1, Arg: &heapCountersArg{ctx.heapStats.heapAlloc, diff}})
+       }
        ctx.prevHeapStats = ctx.heapStats
 }
 
@@ -889,13 +914,12 @@ type goroutineCountersArg struct {
 }
 
 func (ctx *traceContext) emitGoroutineCounters(ev *trace.Event) {
-       if ctx.mode == goroutineTraceview {
-               return
-       }
        if ctx.prevGstates == ctx.gstates {
                return
        }
-       ctx.emit(&ViewerEvent{Name: "Goroutines", Phase: "C", Time: ctx.time(ev), Pid: 1, Arg: &goroutineCountersArg{uint64(ctx.gstates[gRunning]), uint64(ctx.gstates[gRunnable]), uint64(ctx.gstates[gWaitingGC])}})
+       if tsWithinRange(ev.Ts, ctx.startTime, ctx.endTime) {
+               ctx.emit(&ViewerEvent{Name: "Goroutines", Phase: "C", Time: ctx.time(ev), Pid: 1, Arg: &goroutineCountersArg{uint64(ctx.gstates[gRunning]), uint64(ctx.gstates[gRunnable]), uint64(ctx.gstates[gWaitingGC])}})
+       }
        ctx.prevGstates = ctx.gstates
 }
 
@@ -905,21 +929,20 @@ type threadCountersArg struct {
 }
 
 func (ctx *traceContext) emitThreadCounters(ev *trace.Event) {
-       if ctx.mode == goroutineTraceview {
-               return
-       }
        if ctx.prevThreadStats == ctx.threadStats {
                return
        }
-       ctx.emit(&ViewerEvent{Name: "Threads", Phase: "C", Time: ctx.time(ev), Pid: 1, Arg: &threadCountersArg{
-               Running:   ctx.threadStats.prunning,
-               InSyscall: ctx.threadStats.insyscall}})
+       if tsWithinRange(ev.Ts, ctx.startTime, ctx.endTime) {
+               ctx.emit(&ViewerEvent{Name: "Threads", Phase: "C", Time: ctx.time(ev), Pid: 1, Arg: &threadCountersArg{
+                       Running:   ctx.threadStats.prunning,
+                       InSyscall: ctx.threadStats.insyscall}})
+       }
        ctx.prevThreadStats = ctx.threadStats
 }
 
 func (ctx *traceContext) emitInstant(ev *trace.Event, name, category string) {
        cname := ""
-       if ctx.mode == taskTraceview && ev.G != 0 {
+       if ctx.mode&modeTaskOriented != 0 {
                overlapping := false
                for _, task := range ctx.tasks {
                        if task.overlappingInstant(ev) {
@@ -960,7 +983,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.mode != defaultTraceview && (!ctx.gs[ev.Link.G] || ev.Link.Ts < ctx.startTime || ev.Link.Ts > ctx.endTime) {
+       if ctx.mode&modeGoroutineOriented != 0 && (!ctx.gs[ev.Link.G] || ev.Link.Ts < ctx.startTime || ev.Link.Ts > ctx.endTime) {
                return
        }
 
@@ -970,7 +993,8 @@ func (ctx *traceContext) emitArrow(ev *trace.Event, name string) {
                ctx.emitInstant(&trace.Event{P: ev.P, Ts: ev.Ts}, "unblock", "")
        }
 
-       if ctx.mode == taskTraceview {
+       color := ""
+       if ctx.mode&modeTaskOriented != 0 {
                overlapping := false
                // skip non-overlapping arrows.
                for _, task := range ctx.tasks {
@@ -985,8 +1009,8 @@ func (ctx *traceContext) emitArrow(ev *trace.Event, name string) {
        }
 
        ctx.arrowSeq++
-       ctx.emit(&ViewerEvent{Name: name, Phase: "s", Tid: ctx.proc(ev), ID: ctx.arrowSeq, Time: ctx.time(ev), Stack: ctx.stack(ev.Stk)})
-       ctx.emit(&ViewerEvent{Name: name, Phase: "t", Tid: ctx.proc(ev.Link), ID: ctx.arrowSeq, Time: ctx.time(ev.Link)})
+       ctx.emit(&ViewerEvent{Name: name, Phase: "s", Tid: ctx.proc(ev), ID: ctx.arrowSeq, Time: ctx.time(ev), Stack: ctx.stack(ev.Stk), Cname: color})
+       ctx.emit(&ViewerEvent{Name: name, Phase: "t", Tid: ctx.proc(ev.Link), ID: ctx.arrowSeq, Time: ctx.time(ev.Link), Cname: color})
 }
 
 func (ctx *traceContext) stack(stk []*trace.Frame) int {