]> Cypherpunks repositories - gostls13.git/commitdiff
cmd/trace: extend trace view (/trace) for task-oriented view
authorHana Kim <hakim@google.com>
Wed, 24 Jan 2018 22:48:28 +0000 (17:48 -0500)
committerHyang-Ah Hana Kim <hyangah@gmail.com>
Tue, 20 Feb 2018 19:28:38 +0000 (19:28 +0000)
R=go1.11

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

index 680f39aa1ab9a61825603de691762a29d92072f7..c69f62cae562318fd203a2aba98e25c7630c989f 100644 (file)
@@ -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
index 7d1ed9426760a8dc960d4601471b96a9d183ae22..c9536c1246c9c1bb3d013a5160565e6dd7a2db43 100644 (file)
@@ -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
        }