File: //opt/golang/1.22.0/src/cmd/trace/v2/tasks.go
// 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 trace
import (
"bytes"
"cmp"
"fmt"
"html/template"
"internal/trace"
"internal/trace/traceviewer"
tracev2 "internal/trace/v2"
"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(`
<!DOCTYPE html>
<title>Tasks</title>
<style>` + traceviewer.CommonStyle + `
.histoTime {
width: 20%;
white-space:nowrap;
}
th {
background-color: #050505;
color: #fff;
}
table {
border-collapse: collapse;
}
td,
th {
padding-left: 8px;
padding-right: 8px;
padding-top: 4px;
padding-bottom: 4px;
}
</style>
<body>
Search log text: <form action="/usertask"><input name="logtext" type="text"><input type="submit"></form><br>
<table border="1" sortable="1">
<tr>
<th>Task type</th>
<th>Count</th>
<th>Duration distribution (complete tasks)</th>
</tr>
{{range $}}
<tr>
<td>{{.Type}}</td>
<td><a href="/usertask?type={{.Type}}">{{.Count}}</a></td>
<td>{{.Histogram.ToHTML (.UserTaskURL true)}}</td>
</tr>
{{end}}
</table>
</body>
</html>
`))
// 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 tracev2.GoID
What string
// TODO: include stack trace of creation time
}
type task struct {
WhenString string
ID tracev2.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 []*tracev2.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 *tracev2.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(`
<!DOCTYPE html>
<title>Tasks: {{.Name}}</title>
<style>` + traceviewer.CommonStyle + `
body {
font-family: sans-serif;
}
table#req-status td.family {
padding-right: 2em;
}
table#req-status td.active {
padding-right: 1em;
}
table#req-status td.empty {
color: #aaa;
}
table#reqs {
margin-top: 1em;
border-collapse: collapse;
}
table#reqs tr.first {
font-weight: bold;
}
table#reqs td {
font-family: monospace;
}
table#reqs td.when {
text-align: right;
white-space: nowrap;
}
table#reqs td.elapsed {
padding: 0 0.5em;
text-align: right;
white-space: pre;
width: 10em;
}
address {
font-size: smaller;
margin-top: 5em;
}
</style>
<body>
<h2>User Task: {{.Name}}</h2>
Search log text: <form onsubmit="window.location.search+='&logtext='+window.logtextinput.value; return false">
<input name="logtext" id="logtextinput" type="text"><input type="submit">
</form><br>
<table id="reqs">
<tr>
<th>When</th>
<th>Elapsed</th>
<th>Goroutine</th>
<th>Events</th>
</tr>
{{range $el := $.Tasks}}
<tr class="first">
<td class="when">{{$el.WhenString}}</td>
<td class="elapsed">{{$el.Duration}}</td>
<td></td>
<td>
<a href="/trace?focustask={{$el.ID}}#{{asMillisecond $el.Start}}:{{asMillisecond $el.End}}">Task {{$el.ID}}</a>
<a href="/trace?taskid={{$el.ID}}#{{asMillisecond $el.Start}}:{{asMillisecond $el.End}}">(goroutine view)</a>
({{if .Complete}}complete{{else}}incomplete{{end}})
</td>
</tr>
{{range $el.Events}}
<tr>
<td class="when">{{.WhenString}}</td>
<td class="elapsed">{{elapsed .Elapsed}}</td>
<td class="goid">{{.Goroutine}}</td>
<td>{{.What}}</td>
</tr>
{{end}}
{{end}}
</body>
</html>
`))
// 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 *tracev2.Event) string {
switch ev.Kind() {
case tracev2.EventStateTransition:
st := ev.StateTransition()
if st.Resource.Kind != tracev2.ResourceGoroutine {
return ""
}
old, new := st.Goroutine()
return fmt.Sprintf("%s -> %s", old, new)
case tracev2.EventRegionBegin:
return fmt.Sprintf("region %q begin", ev.Region().Type)
case tracev2.EventRegionEnd:
return fmt.Sprintf("region %q end", ev.Region().Type)
case tracev2.EventTaskBegin:
t := ev.Task()
return fmt.Sprintf("task %q (D %d, parent %d) begin", t.Type, t.ID, t.Parent)
case tracev2.EventTaskEnd:
return "task end"
case tracev2.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 *tracev2.Event) tracev2.GoID {
if ev.Kind() != tracev2.EventStateTransition {
return ev.Goroutine()
}
st := ev.StateTransition()
if st.Resource.Kind != tracev2.ResourceGoroutine {
return tracev2.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)
}