From d6856036bf2887de51f6408c7e283b66b57f7fa7 Mon Sep 17 00:00:00 2001 From: Hana Kim Date: Wed, 24 Jan 2018 17:48:28 -0500 Subject: [PATCH] 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 --- src/cmd/trace/annotations.go | 51 ++++++++++++++ src/cmd/trace/trace.go | 124 ++++++++++++++++++++++++++++++----- 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 } -- 2.50.0