From: Hana Kim Date: Thu, 15 Mar 2018 15:28:07 +0000 (-0400) Subject: cmd/trace: add /userspans, /userspan pages X-Git-Tag: go1.11beta1~1097 X-Git-Url: http://www.git.cypherpunks.su/?a=commitdiff_plain;h=f0eca373beb94763b71dadcf6504a95a3797dcbb;p=gostls13.git cmd/trace: add /userspans, /userspan pages Change-Id: Ifbefb659a8df3b079d69679871af444b179deaeb Reviewed-on: https://go-review.googlesource.com/102599 Run-TryBot: Hyang-Ah Hana Kim TryBot-Result: Gobot Gobot Reviewed-by: Heschi Kreinick --- diff --git a/src/cmd/trace/annotations.go b/src/cmd/trace/annotations.go index 0cfef8e3b9..35f0ee39d2 100644 --- a/src/cmd/trace/annotations.go +++ b/src/cmd/trace/annotations.go @@ -9,6 +9,7 @@ import ( "math" "net/http" "sort" + "strconv" "strings" "time" ) @@ -16,6 +17,8 @@ import ( func init() { http.HandleFunc("/usertasks", httpUserTasks) http.HandleFunc("/usertask", httpUserTask) + http.HandleFunc("/userspans", httpUserSpans) + http.HandleFunc("/userspan", httpUserSpan) } // httpUserTasks reports all tasks found in the trace. @@ -55,6 +58,80 @@ func httpUserTasks(w http.ResponseWriter, r *http.Request) { } } +func httpUserSpans(w http.ResponseWriter, r *http.Request) { + res, err := analyzeAnnotations() + if err != nil { + http.Error(w, err.Error(), http.StatusInternalServerError) + return + } + allSpans := res.spans + + summary := make(map[spanTypeID]spanStats) + for id, spans := range allSpans { + stats, ok := summary[id] + if !ok { + stats.spanTypeID = id + } + for _, s := range spans { + stats.add(s) + } + summary[id] = stats + } + // Sort spans by pc and name + userSpans := make([]spanStats, 0, len(summary)) + for _, stats := range summary { + userSpans = append(userSpans, stats) + } + sort.Slice(userSpans, func(i, j int) bool { + if userSpans[i].Type != userSpans[j].Type { + return userSpans[i].Type < userSpans[j].Type + } + return userSpans[i].Frame.PC < userSpans[j].Frame.PC + }) + // Emit table. + err = templUserSpanTypes.Execute(w, userSpans) + if err != nil { + http.Error(w, fmt.Sprintf("failed to execute template: %v", err), http.StatusInternalServerError) + return + } +} + +func httpUserSpan(w http.ResponseWriter, r *http.Request) { + filter, err := newSpanFilter(r) + if err != nil { + http.Error(w, err.Error(), http.StatusBadRequest) + return + } + res, err := analyzeAnnotations() + if err != nil { + http.Error(w, err.Error(), http.StatusInternalServerError) + return + } + allSpans := res.spans + + var data []spanDesc + + for id, spans := range allSpans { + for _, s := range spans { + if !filter.match(id, s) { + continue + } + data = append(data, s) + } + } + + err = templUserSpanType.Execute(w, struct { + Data []spanDesc + Title string + }{ + Data: data, + Title: filter.name}) + if err != nil { + http.Error(w, fmt.Sprintf("failed to execute template: %v", err), http.StatusInternalServerError) + return + } +} + // httpUserTask presents the details of the selected tasks. func httpUserTask(w http.ResponseWriter, r *http.Request) { filter, err := newTaskFilter(r) @@ -156,8 +233,14 @@ func httpUserTask(w http.ResponseWriter, r *http.Request) { } type annotationAnalysisResult struct { - tasks map[uint64]*taskDesc // tasks - gcEvents []*trace.Event // GCStartevents, sorted + tasks map[uint64]*taskDesc // tasks + spans map[spanTypeID][]spanDesc // spans + gcEvents []*trace.Event // GCStartevents, sorted +} + +type spanTypeID struct { + Frame trace.Frame // top frame + Type string } // analyzeAnnotations analyzes user annotation events and @@ -174,6 +257,7 @@ func analyzeAnnotations() (annotationAnalysisResult, error) { } tasks := allTasks{} + spans := map[spanTypeID][]spanDesc{} var gcEvents []*trace.Event for _, ev := range events { @@ -207,7 +291,13 @@ func analyzeAnnotations() (annotationAnalysisResult, error) { } task := tasks.task(s.TaskID) task.goroutines[goid] = struct{}{} - task.spans = append(task.spans, spanDesc{UserSpanDesc: s, goid: goid}) + task.spans = append(task.spans, spanDesc{UserSpanDesc: s, G: goid}) + var frame trace.Frame + if s.Start != nil { + frame = *s.Start.Stk[0] + } + id := spanTypeID{Frame: frame, Type: s.Name} + spans[id] = append(spans[id], spanDesc{UserSpanDesc: s, G: goid}) } } @@ -221,7 +311,7 @@ func analyzeAnnotations() (annotationAnalysisResult, error) { return task.spans[i].lastTimestamp() < task.spans[i].lastTimestamp() }) } - return annotationAnalysisResult{tasks: tasks, gcEvents: gcEvents}, nil + return annotationAnalysisResult{tasks: tasks, spans: spans, gcEvents: gcEvents}, nil } // taskDesc represents a task. @@ -256,7 +346,7 @@ func (task *taskDesc) String() string { fmt.Fprintf(wb, "\t%d goroutines\n", len(task.goroutines)) fmt.Fprintf(wb, "\t%d spans:\n", len(task.spans)) for _, s := range task.spans { - fmt.Fprintf(wb, "\t\t%s(goid=%d)\n", s.Name, s.goid) + fmt.Fprintf(wb, "\t\t%s(goid=%d)\n", s.Name, s.G) } if task.parent != nil { fmt.Fprintf(wb, "\tparent: %s\n", task.parent.name) @@ -272,7 +362,7 @@ func (task *taskDesc) String() string { // spanDesc represents a span. type spanDesc struct { *trace.UserSpanDesc - goid uint64 // id of goroutine where the span was defined + G uint64 // id of goroutine where the span was defined } type allTasks map[uint64]*taskDesc @@ -361,6 +451,10 @@ func (task *taskDesc) duration() time.Duration { return time.Duration(task.lastTimestamp()-task.firstTimestamp()) * time.Nanosecond } +func (span *spanDesc) duration() time.Duration { + return time.Duration(span.lastTimestamp()-span.firstTimestamp()) * time.Nanosecond +} + // overlappingGCDuration returns the sum of GC period overlapping with the task's lifetime. func (task *taskDesc) overlappingGCDuration(evs []*trace.Event) (overlapping time.Duration) { for _, ev := range evs { @@ -397,7 +491,7 @@ func (task *taskDesc) overlappingInstant(ev *trace.Event) bool { // Goroutine local event. Check whether there are spans overlapping with the event. goid := ev.G for _, span := range task.spans { - if span.goid != goid { + if span.G != goid { continue } if span.firstTimestamp() <= ts && ts <= span.lastTimestamp() { @@ -440,7 +534,7 @@ func (task *taskDesc) overlappingDuration(ev *trace.Event) (time.Duration, bool) var overlapping time.Duration var lastSpanEnd int64 // the end of previous overlapping span for _, span := range task.spans { - if span.goid != goid && span.goid != goid2 { + if span.G != goid && span.G != goid2 { continue } spanStart, spanEnd := span.firstTimestamp(), span.lastTimestamp() @@ -616,6 +710,58 @@ func taskMatches(t *taskDesc, text string) bool { return false } +type spanFilter struct { + name string + cond []func(spanTypeID, spanDesc) bool +} + +func (f *spanFilter) match(id spanTypeID, s spanDesc) bool { + for _, c := range f.cond { + if !c(id, s) { + return false + } + } + return true +} + +func newSpanFilter(r *http.Request) (*spanFilter, error) { + if err := r.ParseForm(); err != nil { + return nil, err + } + + var name []string + var conditions []func(spanTypeID, spanDesc) bool + + param := r.Form + if typ, ok := param["type"]; ok && len(typ) > 0 { + name = append(name, "type="+typ[0]) + conditions = append(conditions, func(id spanTypeID, s spanDesc) bool { + return id.Type == typ[0] + }) + } + if pc, err := strconv.ParseUint(r.FormValue("pc"), 16, 64); err == nil { + name = append(name, fmt.Sprintf("pc=%x", pc)) + conditions = append(conditions, func(id spanTypeID, s spanDesc) bool { + return id.Frame.PC == pc + }) + } + + if lat, err := time.ParseDuration(r.FormValue("latmin")); err == nil { + name = append(name, fmt.Sprintf("latency >= %s", lat)) + conditions = append(conditions, func(_ spanTypeID, s spanDesc) bool { + return s.duration() >= lat + }) + } + if lat, err := time.ParseDuration(r.FormValue("latmax")); err == nil { + name = append(name, fmt.Sprintf("latency <= %s", lat)) + conditions = append(conditions, func(_ spanTypeID, s spanDesc) bool { + return s.duration() <= lat + }) + } + + return &spanFilter{name: strings.Join(name, ","), cond: conditions}, nil +} + type durationHistogram struct { Count int Buckets []int @@ -725,6 +871,49 @@ func (h *durationHistogram) String() string { return w.String() } +type spanStats struct { + spanTypeID + Histogram durationHistogram +} + +func (s *spanStats) UserSpanURL() func(min, max time.Duration) string { + return func(min, max time.Duration) string { + return fmt.Sprintf("/userspan?type=%s&pc=%x&latmin=%v&latmax=%v", template.URLQueryEscaper(s.Type), s.Frame.PC, template.URLQueryEscaper(min), template.URLQueryEscaper(max)) + } +} + +func (s *spanStats) add(span spanDesc) { + s.Histogram.add(span.duration()) +} + +var templUserSpanTypes = template.Must(template.New("").Parse(` + + + + + + + + + +{{range $}} + + + + + +{{end}} +
Span typeCountDuration distribution (complete tasks)
{{.Type}}
{{.Frame.Fn}}
{{.Frame.File}}:{{.Frame.Line}}		{{.Histogram.Count}}{{.Histogram.ToHTML (.UserSpanURL)}}
+ + +`)) + type taskStats struct { Type string Count int // Complete + incomplete tasks @@ -923,3 +1112,41 @@ func isUserAnnotationEvent(ev *trace.Event) bool { } return false } + +var templUserSpanType = template.Must(template.New("").Parse(` + + +

{{.Title}}

+ + + + + + + + + + + + + + +{{range .Data}} + + + + + + + + + + + + + +{{end}} +
Goroutine Task Total time, ns Execution time, ns Network wait time, ns Sync block time, ns Blocking syscall time, ns Scheduler wait time, ns GC sweeping time, ns GC pause time, ns Logs
{{.G}} {{.TaskID}} {{.TotalTime}} {{.ExecTime}} {{.IOTime}} {{.BlockTime}} {{.SyscallTime}} {{.SchedWaitTime}} {{.SweepTime}} {{.GCTime}} /* TODO */
+ + +`)) diff --git a/src/cmd/trace/main.go b/src/cmd/trace/main.go index 5a856972b8..9e8292df2a 100644 --- a/src/cmd/trace/main.go +++ b/src/cmd/trace/main.go @@ -200,6 +200,7 @@ var templMain = template.Must(template.New("").Parse(` Syscall blocking profile (⬇)
Scheduler latency profile (⬇)
User-defined tasks
+User-defined spans
`)) diff --git a/src/cmd/trace/trace.go b/src/cmd/trace/trace.go index de062eea01..105d10c8fb 100644 --- a/src/cmd/trace/trace.go +++ b/src/cmd/trace/trace.go @@ -836,8 +836,8 @@ func (ctx *traceContext) emitSpan(s spanDesc) { Name: s.Name, Phase: "b", Time: float64(s.firstTimestamp()) / 1e3, - Tid: s.goid, - ID: s.goid, + Tid: s.G, + ID: s.G, Scope: scopeID, Cname: colorDeepMagenta, } @@ -851,8 +851,8 @@ func (ctx *traceContext) emitSpan(s spanDesc) { Name: s.Name, Phase: "e", Time: float64(s.lastTimestamp()) / 1e3, - Tid: s.goid, - ID: s.goid, + Tid: s.G, + ID: s.G, Scope: scopeID, Cname: colorDeepMagenta, }