// Copyright 2023 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" "cmp" "fmt" "html/template" "internal/trace" "internal/trace/traceviewer" "log" "net/http" "slices" "strings" "time" ) // UserTasksHandlerFunc returns a HandlerFunc that reports all tasks found in the trace. func UserTasksHandlerFunc(t *parsedTrace) http.HandlerFunc { return func(w http.ResponseWriter, r *http.Request) { tasks := t.summary.Tasks // Summarize groups of tasks with the same name. 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) } slices.SortFunc(userTasks, func(a, b taskStats) int { return cmp.Compare(a.Type, b.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 } } } type taskStats struct { Type string Count int // Complete + incomplete tasks Histogram traceviewer.TimeHistogram // 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 *trace.UserTaskSummary) { s.Count++ if task.Complete() { s.Histogram.Add(task.End.Time().Sub(task.Start.Time())) } } var templUserTaskTypes = template.Must(template.New("").Parse(` Tasks Search log text:

{{range $}} {{end}}
Task type Count Duration distribution (complete tasks)
{{.Type}} {{.Count}} {{.Histogram.ToHTML (.UserTaskURL true)}}
`)) // UserTaskHandlerFunc returns a HandlerFunc that presents the details of the selected tasks. func UserTaskHandlerFunc(t *parsedTrace) http.HandlerFunc { return func(w http.ResponseWriter, r *http.Request) { filter, err := newTaskFilter(r) if err != nil { http.Error(w, err.Error(), http.StatusBadRequest) return } type event struct { WhenString string Elapsed time.Duration Goroutine trace.GoID What string // TODO: include stack trace of creation time } type task struct { WhenString string ID trace.TaskID Duration time.Duration Complete bool Events []event Start, End time.Duration // Time since the beginning of the trace GCTime time.Duration } var tasks []task for _, summary := range t.summary.Tasks { if !filter.match(t, summary) { continue } // Collect all the events for the task. var rawEvents []*trace.Event if summary.Start != nil { rawEvents = append(rawEvents, summary.Start) } if summary.End != nil { rawEvents = append(rawEvents, summary.End) } rawEvents = append(rawEvents, summary.Logs...) for _, r := range summary.Regions { if r.Start != nil { rawEvents = append(rawEvents, r.Start) } if r.End != nil { rawEvents = append(rawEvents, r.End) } } // Sort them. slices.SortStableFunc(rawEvents, func(a, b *trace.Event) int { return cmp.Compare(a.Time(), b.Time()) }) // Summarize them. var events []event last := t.startTime() for _, ev := range rawEvents { what := describeEvent(ev) if what == "" { continue } sinceStart := ev.Time().Sub(t.startTime()) events = append(events, event{ WhenString: fmt.Sprintf("%2.9f", sinceStart.Seconds()), Elapsed: ev.Time().Sub(last), What: what, Goroutine: primaryGoroutine(ev), }) last = ev.Time() } taskSpan := taskInterval(t, summary) taskStart := taskSpan.start.Sub(t.startTime()) // Produce the task summary. tasks = append(tasks, task{ WhenString: fmt.Sprintf("%2.9fs", taskStart.Seconds()), Duration: taskSpan.duration(), ID: summary.ID, Complete: summary.Complete(), Events: events, Start: taskStart, End: taskStart + taskSpan.duration(), }) } // Sort the tasks by duration. slices.SortFunc(tasks, func(a, b task) int { return cmp.Compare(a.Duration, b.Duration) }) // Emit table. err = templUserTaskType.Execute(w, struct { Name string Tasks []task }{ Name: filter.name, Tasks: tasks, }) 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 } } } var templUserTaskType = template.Must(template.New("userTask").Funcs(template.FuncMap{ "elapsed": elapsed, "asMillisecond": asMillisecond, "trimSpace": strings.TrimSpace, }).Parse(` Tasks: {{.Name}}

User Task: {{.Name}}

Search log text:

{{range $el := $.Tasks}} {{range $el.Events}} {{end}} {{end}} `)) // taskFilter represents a task filter specified by a user of cmd/trace. type taskFilter struct { name string cond []func(*parsedTrace, *trace.UserTaskSummary) bool } // match returns true if a task, described by its ID and summary, matches // the filter. func (f *taskFilter) match(t *parsedTrace, task *trace.UserTaskSummary) bool { if t == nil { return false } for _, c := range f.cond { if !c(t, task) { return false } } return true } // newTaskFilter creates a new task filter from URL query variables. func newTaskFilter(r *http.Request) (*taskFilter, error) { if err := r.ParseForm(); err != nil { return nil, err } var name []string var conditions []func(*parsedTrace, *trace.UserTaskSummary) bool param := r.Form if typ, ok := param["type"]; ok && len(typ) > 0 { name = append(name, fmt.Sprintf("%q", typ[0])) conditions = append(conditions, func(_ *parsedTrace, task *trace.UserTaskSummary) bool { return task.Name == typ[0] }) } if complete := r.FormValue("complete"); complete == "1" { name = append(name, "complete") conditions = append(conditions, func(_ *parsedTrace, task *trace.UserTaskSummary) bool { return task.Complete() }) } else if complete == "0" { name = append(name, "incomplete") conditions = append(conditions, func(_ *parsedTrace, task *trace.UserTaskSummary) bool { return !task.Complete() }) } if lat, err := time.ParseDuration(r.FormValue("latmin")); err == nil { name = append(name, fmt.Sprintf("latency >= %s", lat)) conditions = append(conditions, func(t *parsedTrace, task *trace.UserTaskSummary) bool { return task.Complete() && taskInterval(t, task).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 *parsedTrace, task *trace.UserTaskSummary) bool { return task.Complete() && taskInterval(t, task).duration() <= lat }) } if text := r.FormValue("logtext"); text != "" { name = append(name, fmt.Sprintf("log contains %q", text)) conditions = append(conditions, func(_ *parsedTrace, task *trace.UserTaskSummary) bool { return taskMatches(task, text) }) } return &taskFilter{name: strings.Join(name, ","), cond: conditions}, nil } func taskInterval(t *parsedTrace, s *trace.UserTaskSummary) interval { var i interval if s.Start != nil { i.start = s.Start.Time() } else { i.start = t.startTime() } if s.End != nil { i.end = s.End.Time() } else { i.end = t.endTime() } return i } func taskMatches(t *trace.UserTaskSummary, text string) bool { matches := func(s string) bool { return strings.Contains(s, text) } if matches(t.Name) { return true } for _, r := range t.Regions { if matches(r.Name) { return true } } for _, ev := range t.Logs { log := ev.Log() if matches(log.Category) { return true } if matches(log.Message) { return true } } return false } func describeEvent(ev *trace.Event) string { switch ev.Kind() { case trace.EventStateTransition: st := ev.StateTransition() if st.Resource.Kind != trace.ResourceGoroutine { return "" } old, new := st.Goroutine() return fmt.Sprintf("%s -> %s", old, new) case trace.EventRegionBegin: return fmt.Sprintf("region %q begin", ev.Region().Type) case trace.EventRegionEnd: return fmt.Sprintf("region %q end", ev.Region().Type) case trace.EventTaskBegin: t := ev.Task() return fmt.Sprintf("task %q (D %d, parent %d) begin", t.Type, t.ID, t.Parent) case trace.EventTaskEnd: return "task end" case trace.EventLog: log := ev.Log() if log.Category != "" { return fmt.Sprintf("log %q", log.Message) } return fmt.Sprintf("log (category: %s): %q", log.Category, log.Message) } return "" } func primaryGoroutine(ev *trace.Event) trace.GoID { if ev.Kind() != trace.EventStateTransition { return ev.Goroutine() } st := ev.StateTransition() if st.Resource.Kind != trace.ResourceGoroutine { return trace.NoGoroutine } return st.Resource.Goroutine() } 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()) / float64(time.Millisecond) }
When Elapsed Goroutine Events
{{$el.WhenString}} {{$el.Duration}} Task {{$el.ID}} (goroutine view) ({{if .Complete}}complete{{else}}incomplete{{end}})
{{.WhenString}} {{elapsed .Elapsed}} {{.Goroutine}} {{.What}}