// Copyright 2018 The Go Authors. All rights reserved. // Use of this source code is governed by a BSD-style // license that can be found in the LICENSE file. package main import ( "bytes" "fmt" "html/template" "internal/trace" "log" "math" "net/http" "net/url" "reflect" "sort" "strconv" "strings" "time" ) func init() { http.HandleFunc("/usertasks", httpUserTasks) http.HandleFunc("/usertask", httpUserTask) http.HandleFunc("/userregions", httpUserRegions) http.HandleFunc("/userregion", httpUserRegion) } // httpUserTasks reports all tasks found in the trace. func httpUserTasks(w http.ResponseWriter, r *http.Request) { res, err := analyzeAnnotations() if err != nil { http.Error(w, err.Error(), http.StatusInternalServerError) return } tasks := res.tasks summary := make(map[string]taskStats) for _, task := range tasks { stats, ok := summary[task.name] if !ok { stats.Type = task.name } stats.add(task) summary[task.name] = stats } // Sort tasks by type. userTasks := make([]taskStats, 0, len(summary)) for _, stats := range summary { userTasks = append(userTasks, stats) } sort.Slice(userTasks, func(i, j int) bool { return userTasks[i].Type < userTasks[j].Type }) // Emit table. err = templUserTaskTypes.Execute(w, userTasks) if err != nil { http.Error(w, fmt.Sprintf("failed to execute template: %v", err), http.StatusInternalServerError) return } } func httpUserRegions(w http.ResponseWriter, r *http.Request) { res, err := analyzeAnnotations() if err != nil { http.Error(w, err.Error(), http.StatusInternalServerError) return } allRegions := res.regions summary := make(map[regionTypeID]regionStats) for id, regions := range allRegions { stats, ok := summary[id] if !ok { stats.regionTypeID = id } for _, s := range regions { stats.add(s) } summary[id] = stats } // Sort regions by pc and name userRegions := make([]regionStats, 0, len(summary)) for _, stats := range summary { userRegions = append(userRegions, stats) } sort.Slice(userRegions, func(i, j int) bool { if userRegions[i].Type != userRegions[j].Type { return userRegions[i].Type < userRegions[j].Type } return userRegions[i].Frame.PC < userRegions[j].Frame.PC }) // Emit table. err = templUserRegionTypes.Execute(w, userRegions) if err != nil { http.Error(w, fmt.Sprintf("failed to execute template: %v", err), http.StatusInternalServerError) return } } func httpUserRegion(w http.ResponseWriter, r *http.Request) { filter, err := newRegionFilter(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 } allRegions := res.regions var data []regionDesc var maxTotal int64 for id, regions := range allRegions { for _, s := range regions { if !filter.match(id, s) { continue } data = append(data, s) if maxTotal < s.TotalTime { maxTotal = s.TotalTime } } } sortby := r.FormValue("sortby") _, ok := reflect.TypeOf(regionDesc{}).FieldByNameFunc(func(s string) bool { return s == sortby }) if !ok { sortby = "TotalTime" } sort.Slice(data, func(i, j int) bool { ival := reflect.ValueOf(data[i]).FieldByName(sortby).Int() jval := reflect.ValueOf(data[j]).FieldByName(sortby).Int() return ival > jval }) err = templUserRegionType.Execute(w, struct { MaxTotal int64 Data []regionDesc Name string Filter *regionFilter }{ MaxTotal: maxTotal, Data: data, Name: filter.name, Filter: filter, }) 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) 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 } tasks := res.tasks type event struct { WhenString string Elapsed time.Duration Go uint64 What string // TODO: include stack trace of creation time } type entry struct { WhenString string ID uint64 Duration time.Duration Complete bool Events []event Start, End time.Duration // Time since the beginning of the trace GCTime time.Duration } base := time.Duration(firstTimestamp()) * time.Nanosecond // trace start var data []entry for _, task := range tasks { if !filter.match(task) { continue } // merge events in the task.events and task.regions.Start rawEvents := append([]*trace.Event{}, task.events...) for _, s := range task.regions { if s.Start != nil { rawEvents = append(rawEvents, s.Start) } } sort.SliceStable(rawEvents, func(i, j int) bool { return rawEvents[i].Ts < rawEvents[j].Ts }) var events []event var last time.Duration for i, ev := range rawEvents { when := time.Duration(ev.Ts)*time.Nanosecond - base elapsed := time.Duration(ev.Ts)*time.Nanosecond - last if i == 0 { elapsed = 0 } what := describeEvent(ev) if what != "" { events = append(events, event{ WhenString: fmt.Sprintf("%2.9f", when.Seconds()), Elapsed: elapsed, What: what, Go: ev.G, }) last = time.Duration(ev.Ts) * time.Nanosecond } } data = append(data, entry{ WhenString: fmt.Sprintf("%2.9fs", (time.Duration(task.firstTimestamp())*time.Nanosecond - base).Seconds()), Duration: task.duration(), ID: task.id, Complete: task.complete(), Events: events, Start: time.Duration(task.firstTimestamp()) * time.Nanosecond, End: time.Duration(task.endTimestamp()) * time.Nanosecond, GCTime: task.overlappingGCDuration(res.gcEvents), }) } sort.Slice(data, func(i, j int) bool { return data[i].Duration < data[j].Duration }) // Emit table. err = templUserTaskType.Execute(w, struct { Name string Entry []entry }{ Name: filter.name, Entry: data, }) if err != nil { log.Printf("failed to execute template: %v", err) http.Error(w, fmt.Sprintf("failed to execute template: %v", err), http.StatusInternalServerError) return } } type annotationAnalysisResult struct { tasks map[uint64]*taskDesc // tasks regions map[regionTypeID][]regionDesc // regions gcEvents []*trace.Event // GCStartevents, sorted } type regionTypeID struct { Frame trace.Frame // top frame Type string } // analyzeAnnotations analyzes user annotation events and // returns the task descriptors keyed by internal task id. func analyzeAnnotations() (annotationAnalysisResult, error) { res, err := parseTrace() if err != nil { return annotationAnalysisResult{}, fmt.Errorf("failed to parse trace: %v", err) } events := res.Events if len(events) == 0 { return annotationAnalysisResult{}, fmt.Errorf("empty trace") } tasks := allTasks{} regions := map[regionTypeID][]regionDesc{} var gcEvents []*trace.Event for _, ev := range events { switch typ := ev.Type; typ { case trace.EvUserTaskCreate, trace.EvUserTaskEnd, trace.EvUserLog: taskid := ev.Args[0] task := tasks.task(taskid) task.addEvent(ev) // retrieve parent task information if typ == trace.EvUserTaskCreate { if parentID := ev.Args[1]; parentID != 0 { parentTask := tasks.task(parentID) task.parent = parentTask if parentTask != nil { parentTask.children = append(parentTask.children, task) } } } case trace.EvGCStart: gcEvents = append(gcEvents, ev) } } // combine region info. analyzeGoroutines(events) for goid, stats := range gs { // gs is a global var defined in goroutines.go as a result // of analyzeGoroutines. TODO(hyangah): fix this not to depend // on a 'global' var. for _, s := range stats.Regions { if s.TaskID != 0 { task := tasks.task(s.TaskID) task.goroutines[goid] = struct{}{} task.regions = append(task.regions, regionDesc{UserRegionDesc: s, G: goid}) } var frame trace.Frame if s.Start != nil { frame = *s.Start.Stk[0] } id := regionTypeID{Frame: frame, Type: s.Name} regions[id] = append(regions[id], regionDesc{UserRegionDesc: s, G: goid}) } } // sort regions in tasks based on the timestamps. for _, task := range tasks { sort.SliceStable(task.regions, func(i, j int) bool { si, sj := task.regions[i].firstTimestamp(), task.regions[j].firstTimestamp() if si != sj { return si < sj } return task.regions[i].lastTimestamp() < task.regions[j].lastTimestamp() }) } return annotationAnalysisResult{tasks: tasks, regions: regions, gcEvents: gcEvents}, nil } // taskDesc represents a task. type taskDesc struct { name string // user-provided task name id uint64 // internal task id events []*trace.Event // sorted based on timestamp. regions []regionDesc // associated regions, sorted based on the start timestamp and then the last timestamp. goroutines map[uint64]struct{} // involved goroutines create *trace.Event // Task create event end *trace.Event // Task end event parent *taskDesc children []*taskDesc } func newTaskDesc(id uint64) *taskDesc { return &taskDesc{ id: id, goroutines: make(map[uint64]struct{}), } } func (task *taskDesc) String() string { if task == nil { return "task " } wb := new(strings.Builder) fmt.Fprintf(wb, "task %d:\t%s\n", task.id, task.name) fmt.Fprintf(wb, "\tstart: %v end: %v complete: %t\n", task.firstTimestamp(), task.endTimestamp(), task.complete()) fmt.Fprintf(wb, "\t%d goroutines\n", len(task.goroutines)) fmt.Fprintf(wb, "\t%d regions:\n", len(task.regions)) for _, s := range task.regions { 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) } fmt.Fprintf(wb, "\t%d children:\n", len(task.children)) for _, c := range task.children { fmt.Fprintf(wb, "\t\t%s\n", c.name) } return wb.String() } // regionDesc represents a region. type regionDesc struct { *trace.UserRegionDesc G uint64 // id of goroutine where the region was defined } type allTasks map[uint64]*taskDesc func (tasks allTasks) task(taskID uint64) *taskDesc { if taskID == 0 { return nil // notask } t, ok := tasks[taskID] if ok { return t } t = newTaskDesc(taskID) tasks[taskID] = t return t } func (task *taskDesc) addEvent(ev *trace.Event) { if task == nil { return } task.events = append(task.events, ev) task.goroutines[ev.G] = struct{}{} switch typ := ev.Type; typ { case trace.EvUserTaskCreate: task.name = ev.SArgs[0] task.create = ev case trace.EvUserTaskEnd: task.end = ev } } // complete is true only if both start and end events of this task // are present in the trace. func (task *taskDesc) complete() bool { if task == nil { return false } return task.create != nil && task.end != nil } // descendants returns all the task nodes in the subtree rooted from this task. func (task *taskDesc) descendants() []*taskDesc { if task == nil { return nil } res := []*taskDesc{task} for i := 0; len(res[i:]) > 0; i++ { t := res[i] res = append(res, t.children...) } return res } // firstTimestamp returns the first timestamp of this task found in // this trace. If the trace does not contain the task creation event, // the first timestamp of the trace will be returned. func (task *taskDesc) firstTimestamp() int64 { if task != nil && task.create != nil { return task.create.Ts } return firstTimestamp() } // lastTimestamp returns the last timestamp of this task in this // trace. If the trace does not contain the task end event, the last // timestamp of the trace will be returned. func (task *taskDesc) lastTimestamp() int64 { endTs := task.endTimestamp() if last := task.lastEvent(); last != nil && last.Ts > endTs { return last.Ts } return endTs } // endTimestamp returns the timestamp of this task's end event. // If the trace does not contain the task end event, the last // timestamp of the trace will be returned. func (task *taskDesc) endTimestamp() int64 { if task != nil && task.end != nil { return task.end.Ts } return lastTimestamp() } func (task *taskDesc) duration() time.Duration { return time.Duration(task.endTimestamp()-task.firstTimestamp()) * time.Nanosecond } func (region *regionDesc) duration() time.Duration { return time.Duration(region.lastTimestamp()-region.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 { // make sure we only consider the global GC events. if typ := ev.Type; typ != trace.EvGCStart && typ != trace.EvGCSTWStart { continue } if o, overlapped := task.overlappingDuration(ev); overlapped { overlapping += o } } return overlapping } // overlappingInstant reports whether the instantaneous event, ev, occurred during // any of the task's region if ev is a goroutine-local event, or overlaps with the // task's lifetime if ev is a global event. func (task *taskDesc) overlappingInstant(ev *trace.Event) bool { if _, ok := isUserAnnotationEvent(ev); ok && task.id != ev.Args[0] { return false // not this task's user event. } ts := ev.Ts taskStart := task.firstTimestamp() taskEnd := task.endTimestamp() if ts < taskStart || taskEnd < ts { return false } if ev.P == trace.GCP { return true } // Goroutine local event. Check whether there are regions overlapping with the event. goid := ev.G for _, region := range task.regions { if region.G != goid { continue } if region.firstTimestamp() <= ts && ts <= region.lastTimestamp() { return true } } return false } // overlappingDuration reports whether the durational event, ev, overlaps with // any of the task's region if ev is a goroutine-local event, or overlaps with // the task's lifetime if ev is a global event. It returns the overlapping time // as well. func (task *taskDesc) overlappingDuration(ev *trace.Event) (time.Duration, bool) { start := ev.Ts end := lastTimestamp() if ev.Link != nil { end = ev.Link.Ts } if start > end { return 0, false } goid := ev.G goid2 := ev.G if ev.Link != nil { goid2 = ev.Link.G } // This event is a global GC event if ev.P == trace.GCP { taskStart := task.firstTimestamp() taskEnd := task.endTimestamp() o := overlappingDuration(taskStart, taskEnd, start, end) return o, o > 0 } // Goroutine local event. Check whether there are regions overlapping with the event. var overlapping time.Duration var lastRegionEnd int64 // the end of previous overlapping region for _, region := range task.regions { if region.G != goid && region.G != goid2 { continue } regionStart, regionEnd := region.firstTimestamp(), region.lastTimestamp() if regionStart < lastRegionEnd { // skip nested regions continue } if o := overlappingDuration(regionStart, regionEnd, start, end); o > 0 { // overlapping. lastRegionEnd = regionEnd overlapping += o } } return overlapping, overlapping > 0 } // overlappingDuration returns the overlapping time duration between // two time intervals [start1, end1] and [start2, end2] where // start, end parameters are all int64 representing nanoseconds. func overlappingDuration(start1, end1, start2, end2 int64) time.Duration { // assume start1 <= end1 and start2 <= end2 if end1 < start2 || end2 < start1 { return 0 } if start1 < start2 { // choose the later one start1 = start2 } if end1 > end2 { // choose the earlier one end1 = end2 } return time.Duration(end1 - start1) } func (task *taskDesc) lastEvent() *trace.Event { if task == nil { return nil } if n := len(task.events); n > 0 { return task.events[n-1] } return nil } // firstTimestamp returns the timestamp of region start event. // If the region's start event is not present in the trace, // the first timestamp of the trace will be returned. func (region *regionDesc) firstTimestamp() int64 { if region.Start != nil { return region.Start.Ts } return firstTimestamp() } // lastTimestamp returns the timestamp of region end event. // If the region's end event is not present in the trace, // the last timestamp of the trace will be returned. func (region *regionDesc) lastTimestamp() int64 { if region.End != nil { return region.End.Ts } return 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.endTimestamp() 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 } func (f *taskFilter) match(t *taskDesc) bool { if t == nil { return false } for _, c := range f.cond { if !c(t) { return false } } return true } func newTaskFilter(r *http.Request) (*taskFilter, error) { if err := r.ParseForm(); err != nil { return nil, err } var name []string var conditions []func(*taskDesc) bool param := r.Form if typ, ok := param["type"]; ok && len(typ) > 0 { name = append(name, "type="+typ[0]) conditions = append(conditions, func(t *taskDesc) bool { return t.name == typ[0] }) } if complete := r.FormValue("complete"); complete == "1" { name = append(name, "complete") conditions = append(conditions, func(t *taskDesc) bool { return t.complete() }) } else if complete == "0" { name = append(name, "incomplete") conditions = append(conditions, func(t *taskDesc) bool { return !t.complete() }) } if lat, err := time.ParseDuration(r.FormValue("latmin")); err == nil { name = append(name, fmt.Sprintf("latency >= %s", lat)) conditions = append(conditions, func(t *taskDesc) bool { return t.complete() && t.duration() >= lat }) } if lat, err := time.ParseDuration(r.FormValue("latmax")); err == nil { name = append(name, fmt.Sprintf("latency <= %s", lat)) conditions = append(conditions, func(t *taskDesc) bool { return t.complete() && t.duration() <= lat }) } if text := r.FormValue("logtext"); text != "" { name = append(name, fmt.Sprintf("log contains %q", text)) conditions = append(conditions, func(t *taskDesc) bool { return taskMatches(t, text) }) } return &taskFilter{name: strings.Join(name, ","), cond: conditions}, nil } func taskMatches(t *taskDesc, text string) bool { for _, ev := range t.events { switch ev.Type { case trace.EvUserTaskCreate, trace.EvUserRegion, trace.EvUserLog: for _, s := range ev.SArgs { if strings.Contains(s, text) { return true } } } } return false } type regionFilter struct { name string params url.Values cond []func(regionTypeID, regionDesc) bool } func (f *regionFilter) match(id regionTypeID, s regionDesc) bool { for _, c := range f.cond { if !c(id, s) { return false } } return true } func newRegionFilter(r *http.Request) (*regionFilter, error) { if err := r.ParseForm(); err != nil { return nil, err } var name []string var conditions []func(regionTypeID, regionDesc) bool filterParams := make(url.Values) param := r.Form if typ, ok := param["type"]; ok && len(typ) > 0 { name = append(name, "type="+typ[0]) conditions = append(conditions, func(id regionTypeID, s regionDesc) bool { return id.Type == typ[0] }) filterParams.Add("type", typ[0]) } if pc, err := strconv.ParseUint(r.FormValue("pc"), 16, 64); err == nil { encPC := fmt.Sprintf("%x", pc) name = append(name, "pc="+encPC) conditions = append(conditions, func(id regionTypeID, s regionDesc) bool { return id.Frame.PC == pc }) filterParams.Add("pc", encPC) } if lat, err := time.ParseDuration(r.FormValue("latmin")); err == nil { name = append(name, fmt.Sprintf("latency >= %s", lat)) conditions = append(conditions, func(_ regionTypeID, s regionDesc) bool { return s.duration() >= lat }) filterParams.Add("latmin", lat.String()) } if lat, err := time.ParseDuration(r.FormValue("latmax")); err == nil { name = append(name, fmt.Sprintf("latency <= %s", lat)) conditions = append(conditions, func(_ regionTypeID, s regionDesc) bool { return s.duration() <= lat }) filterParams.Add("latmax", lat.String()) } return ®ionFilter{ name: strings.Join(name, ","), cond: conditions, params: filterParams, }, nil } type durationHistogram struct { Count int Buckets []int MinBucket, MaxBucket int } // Five buckets for every power of 10. var logDiv = math.Log(math.Pow(10, 1.0/5)) func (h *durationHistogram) add(d time.Duration) { var bucket int if d > 0 { bucket = int(math.Log(float64(d)) / logDiv) } if len(h.Buckets) <= bucket { h.Buckets = append(h.Buckets, make([]int, bucket-len(h.Buckets)+1)...) h.Buckets = h.Buckets[:cap(h.Buckets)] } h.Buckets[bucket]++ if bucket < h.MinBucket || h.MaxBucket == 0 { h.MinBucket = bucket } if bucket > h.MaxBucket { h.MaxBucket = bucket } h.Count++ } func (h *durationHistogram) BucketMin(bucket int) time.Duration { return time.Duration(math.Exp(float64(bucket) * logDiv)) } func niceDuration(d time.Duration) string { var rnd time.Duration var unit string switch { case d < 10*time.Microsecond: rnd, unit = time.Nanosecond, "ns" case d < 10*time.Millisecond: rnd, unit = time.Microsecond, "µs" case d < 10*time.Second: rnd, unit = time.Millisecond, "ms" default: rnd, unit = time.Second, "s " } return fmt.Sprintf("%d%s", d/rnd, unit) } func (h *durationHistogram) ToHTML(urlmaker func(min, max time.Duration) string) template.HTML { if h == nil || h.Count == 0 { return template.HTML("") } const barWidth = 400 maxCount := 0 for _, count := range h.Buckets { if count > maxCount { maxCount = count } } w := new(strings.Builder) fmt.Fprintf(w, ``) for i := h.MinBucket; i <= h.MaxBucket; i++ { // Tick label. if h.Buckets[i] > 0 { fmt.Fprintf(w, ``, urlmaker(h.BucketMin(i), h.BucketMin(i+1)), niceDuration(h.BucketMin(i))) } else { fmt.Fprintf(w, ``, niceDuration(h.BucketMin(i))) } // Bucket bar. width := h.Buckets[i] * barWidth / maxCount fmt.Fprintf(w, ``, width) // Bucket count. fmt.Fprintf(w, ``, h.Buckets[i]) fmt.Fprintf(w, "\n") } // Final tick label. fmt.Fprintf(w, ``, niceDuration(h.BucketMin(h.MaxBucket+1))) fmt.Fprintf(w, `
%s
%s
 
%d
%s
`) return template.HTML(w.String()) } func (h *durationHistogram) String() string { const barWidth = 40 labels := []string{} maxLabel := 0 maxCount := 0 for i := h.MinBucket; i <= h.MaxBucket; i++ { // TODO: This formatting is pretty awful. label := fmt.Sprintf("[%-12s%-11s)", h.BucketMin(i).String()+",", h.BucketMin(i+1)) labels = append(labels, label) if len(label) > maxLabel { maxLabel = len(label) } count := h.Buckets[i] if count > maxCount { maxCount = count } } w := new(strings.Builder) for i := h.MinBucket; i <= h.MaxBucket; i++ { count := h.Buckets[i] bar := count * barWidth / maxCount fmt.Fprintf(w, "%*s %-*s %d\n", maxLabel, labels[i-h.MinBucket], barWidth, strings.Repeat("█", bar), count) } return w.String() } type regionStats struct { regionTypeID Histogram durationHistogram } func (s *regionStats) UserRegionURL() func(min, max time.Duration) string { return func(min, max time.Duration) string { return fmt.Sprintf("/userregion?type=%s&pc=%x&latmin=%v&latmax=%v", template.URLQueryEscaper(s.Type), s.Frame.PC, template.URLQueryEscaper(min), template.URLQueryEscaper(max)) } } func (s *regionStats) add(region regionDesc) { s.Histogram.add(region.duration()) } var templUserRegionTypes = template.Must(template.New("").Parse(` {{range $}} {{end}}
Region type Count Duration distribution (complete tasks)
{{.Type}}
{{.Frame.Fn}}
{{.Frame.File}}:{{.Frame.Line}}
{{.Histogram.Count}} {{.Histogram.ToHTML (.UserRegionURL)}}
`)) type taskStats struct { Type string Count int // Complete + incomplete tasks Histogram durationHistogram // Complete tasks only } func (s *taskStats) UserTaskURL(complete bool) func(min, max time.Duration) string { return func(min, max time.Duration) string { return fmt.Sprintf("/usertask?type=%s&complete=%v&latmin=%v&latmax=%v", template.URLQueryEscaper(s.Type), template.URLQueryEscaper(complete), template.URLQueryEscaper(min), template.URLQueryEscaper(max)) } } func (s *taskStats) add(task *taskDesc) { s.Count++ if task.complete() { s.Histogram.add(task.duration()) } } var templUserTaskTypes = template.Must(template.New("").Parse(` Search log text:

{{range $}} {{end}}
Task type Count Duration distribution (complete tasks)
{{.Type}} {{.Count}} {{.Histogram.ToHTML (.UserTaskURL true)}}
`)) var templUserTaskType = template.Must(template.New("userTask").Funcs(template.FuncMap{ "elapsed": elapsed, "asMillisecond": asMillisecond, "trimSpace": strings.TrimSpace, }).Parse(` User Task: {{.Name}}

User Task: {{.Name}}

Search log text:

{{range $el := $.Entry}} {{range $el.Events}} {{end}} {{end}} `)) func elapsed(d time.Duration) string { b := fmt.Appendf(nil, "%.9f", d.Seconds()) // For subsecond durations, blank all zeros before decimal point, // and all zeros between the decimal point and the first non-zero digit. if d < time.Second { dot := bytes.IndexByte(b, '.') for i := 0; i < dot; i++ { b[i] = ' ' } for i := dot + 1; i < len(b); i++ { if b[i] == '0' { b[i] = ' ' } else { break } } } return string(b) } func asMillisecond(d time.Duration) float64 { return float64(d.Nanoseconds()) / 1e6 } func formatUserLog(ev *trace.Event) string { k, v := ev.SArgs[0], ev.SArgs[1] if k == "" { return v } if v == "" { return k } return fmt.Sprintf("%v=%v", k, v) } func describeEvent(ev *trace.Event) string { switch ev.Type { case trace.EvGoCreate: goid := ev.Args[0] return fmt.Sprintf("new goroutine %d: %s", goid, gs[goid].Name) case trace.EvGoEnd, trace.EvGoStop: return "goroutine stopped" case trace.EvUserLog: return formatUserLog(ev) case trace.EvUserRegion: if ev.Args[1] == 0 { duration := "unknown" if ev.Link != nil { duration = (time.Duration(ev.Link.Ts-ev.Ts) * time.Nanosecond).String() } return fmt.Sprintf("region %s started (duration: %v)", ev.SArgs[0], duration) } return fmt.Sprintf("region %s ended", ev.SArgs[0]) case trace.EvUserTaskCreate: return fmt.Sprintf("task %v (id %d, parent %d) created", ev.SArgs[0], ev.Args[0], ev.Args[1]) // TODO: add child task creation events into the parent task events case trace.EvUserTaskEnd: return "task end" } return "" } func isUserAnnotationEvent(ev *trace.Event) (taskID uint64, ok bool) { switch ev.Type { case trace.EvUserLog, trace.EvUserRegion, trace.EvUserTaskCreate, trace.EvUserTaskEnd: return ev.Args[0], true } return 0, false } var templUserRegionType = template.Must(template.New("").Funcs(template.FuncMap{ "prettyDuration": func(nsec int64) template.HTML { d := time.Duration(nsec) * time.Nanosecond return template.HTML(niceDuration(d)) }, "percent": func(dividend, divisor int64) template.HTML { if divisor == 0 { return "" } return template.HTML(fmt.Sprintf("(%.1f%%)", float64(dividend)/float64(divisor)*100)) }, "barLen": func(dividend, divisor int64) template.HTML { if divisor == 0 { return "0" } return template.HTML(fmt.Sprintf("%.2f%%", float64(dividend)/float64(divisor)*100)) }, "unknownTime": func(desc regionDesc) int64 { sum := desc.ExecTime + desc.IOTime + desc.BlockTime + desc.SyscallTime + desc.SchedWaitTime if sum < desc.TotalTime { return desc.TotalTime - sum } return 0 }, "filterParams": func(f *regionFilter) template.URL { return template.URL(f.params.Encode()) }, }).Parse(` User Region {{.Name}}

{{.Name}}

{{ with $p := filterParams .Filter}}
WhenElapsedGoroutine IDEvents
{{$el.WhenString}} {{$el.Duration}} Task {{$el.ID}} (goroutine view) ({{if .Complete}}complete{{else}}incomplete{{end}})
{{.WhenString}} {{elapsed .Elapsed}} {{.Go}} {{.What}}
GC:{{$el.GCTime}}
Network Wait Time: graph(download)
Sync Block Time: graph(download)
Blocking Syscall Time: graph(download)
Scheduler Wait Time: graph(download)
{{ end }}

{{range .Data}} {{end}}
Goroutine Task Total Execution Network wait Sync block Blocking syscall Scheduler wait GC sweeping GC pause
{{.G}} {{if .TaskID}}{{.TaskID}}{{end}} {{prettyDuration .TotalTime}}
{{if unknownTime .}} {{end}} {{if .ExecTime}} {{end}} {{if .IOTime}} {{end}} {{if .BlockTime}} {{end}} {{if .SyscallTime}} {{end}} {{if .SchedWaitTime}} {{end}}
{{prettyDuration .ExecTime}} {{prettyDuration .IOTime}} {{prettyDuration .BlockTime}} {{prettyDuration .SyscallTime}} {{prettyDuration .SchedWaitTime}} {{prettyDuration .SweepTime}} {{percent .SweepTime .TotalTime}} {{prettyDuration .GCTime}} {{percent .GCTime .TotalTime}}

`))