tasks.go

Documentation: cmd/trace

     1  // Copyright 2023 The Go Authors. All rights reserved.
     2  // Use of this source code is governed by a BSD-style
     3  // license that can be found in the LICENSE file.
     4  
     5  package main
     6  
     7  import (
     8  	"bytes"
     9  	"cmp"
    10  	"fmt"
    11  	"html/template"
    12  	"internal/trace"
    13  	"internal/trace/traceviewer"
    14  	"log"
    15  	"net/http"
    16  	"slices"
    17  	"strings"
    18  	"time"
    19  )
    20  
    21  // UserTasksHandlerFunc returns a HandlerFunc that reports all tasks found in the trace.
    22  func UserTasksHandlerFunc(t *parsedTrace) http.HandlerFunc {
    23  	return func(w http.ResponseWriter, r *http.Request) {
    24  		tasks := t.summary.Tasks
    25  
    26  		// Summarize groups of tasks with the same name.
    27  		summary := make(map[string]taskStats)
    28  		for _, task := range tasks {
    29  			stats, ok := summary[task.Name]
    30  			if !ok {
    31  				stats.Type = task.Name
    32  			}
    33  			stats.add(task)
    34  			summary[task.Name] = stats
    35  		}
    36  
    37  		// Sort tasks by type.
    38  		userTasks := make([]taskStats, 0, len(summary))
    39  		for _, stats := range summary {
    40  			userTasks = append(userTasks, stats)
    41  		}
    42  		slices.SortFunc(userTasks, func(a, b taskStats) int {
    43  			return cmp.Compare(a.Type, b.Type)
    44  		})
    45  
    46  		// Emit table.
    47  		err := templUserTaskTypes.Execute(w, userTasks)
    48  		if err != nil {
    49  			http.Error(w, fmt.Sprintf("failed to execute template: %v", err), http.StatusInternalServerError)
    50  			return
    51  		}
    52  	}
    53  }
    54  
    55  type taskStats struct {
    56  	Type      string
    57  	Count     int                       // Complete + incomplete tasks
    58  	Histogram traceviewer.TimeHistogram // Complete tasks only
    59  }
    60  
    61  func (s *taskStats) UserTaskURL(complete bool) func(min, max time.Duration) string {
    62  	return func(min, max time.Duration) string {
    63  		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))
    64  	}
    65  }
    66  
    67  func (s *taskStats) add(task *trace.UserTaskSummary) {
    68  	s.Count++
    69  	if task.Complete() {
    70  		s.Histogram.Add(task.End.Time().Sub(task.Start.Time()))
    71  	}
    72  }
    73  
    74  var templUserTaskTypes = template.Must(template.New("").Parse(`
    75  <!DOCTYPE html>
    76  <title>Tasks</title>
    77  <style>` + traceviewer.CommonStyle + `
    78  .histoTime {
    79    width: 20%;
    80    white-space:nowrap;
    81  }
    82  th {
    83    background-color: #050505;
    84    color: #fff;
    85  }
    86  table {
    87    border-collapse: collapse;
    88  }
    89  td,
    90  th {
    91    padding-left: 8px;
    92    padding-right: 8px;
    93    padding-top: 4px;
    94    padding-bottom: 4px;
    95  }
    96  </style>
    97  <body>
    98  Search log text: <form action="/usertask"><input name="logtext" type="text"><input type="submit"></form><br>
    99  <table border="1" sortable="1">
   100  <tr>
   101  <th>Task type</th>
   102  <th>Count</th>
   103  <th>Duration distribution (complete tasks)</th>
   104  </tr>
   105  {{range $}}
   106    <tr>
   107      <td>{{.Type}}</td>
   108      <td><a href="/usertask?type={{.Type}}">{{.Count}}</a></td>
   109      <td>{{.Histogram.ToHTML (.UserTaskURL true)}}</td>
   110    </tr>
   111  {{end}}
   112  </table>
   113  </body>
   114  </html>
   115  `))
   116  
   117  // UserTaskHandlerFunc returns a HandlerFunc that presents the details of the selected tasks.
   118  func UserTaskHandlerFunc(t *parsedTrace) http.HandlerFunc {
   119  	return func(w http.ResponseWriter, r *http.Request) {
   120  		filter, err := newTaskFilter(r)
   121  		if err != nil {
   122  			http.Error(w, err.Error(), http.StatusBadRequest)
   123  			return
   124  		}
   125  		type event struct {
   126  			WhenString string
   127  			Elapsed    time.Duration
   128  			Goroutine  trace.GoID
   129  			What       string
   130  			// TODO: include stack trace of creation time
   131  		}
   132  		type task struct {
   133  			WhenString string
   134  			ID         trace.TaskID
   135  			Duration   time.Duration
   136  			Complete   bool
   137  			Events     []event
   138  			Start, End time.Duration // Time since the beginning of the trace
   139  			GCTime     time.Duration
   140  		}
   141  		var tasks []task
   142  		for _, summary := range t.summary.Tasks {
   143  			if !filter.match(t, summary) {
   144  				continue
   145  			}
   146  
   147  			// Collect all the events for the task.
   148  			var rawEvents []*trace.Event
   149  			if summary.Start != nil {
   150  				rawEvents = append(rawEvents, summary.Start)
   151  			}
   152  			if summary.End != nil {
   153  				rawEvents = append(rawEvents, summary.End)
   154  			}
   155  			rawEvents = append(rawEvents, summary.Logs...)
   156  			for _, r := range summary.Regions {
   157  				if r.Start != nil {
   158  					rawEvents = append(rawEvents, r.Start)
   159  				}
   160  				if r.End != nil {
   161  					rawEvents = append(rawEvents, r.End)
   162  				}
   163  			}
   164  
   165  			// Sort them.
   166  			slices.SortStableFunc(rawEvents, func(a, b *trace.Event) int {
   167  				return cmp.Compare(a.Time(), b.Time())
   168  			})
   169  
   170  			// Summarize them.
   171  			var events []event
   172  			last := t.startTime()
   173  			for _, ev := range rawEvents {
   174  				what := describeEvent(ev)
   175  				if what == "" {
   176  					continue
   177  				}
   178  				sinceStart := ev.Time().Sub(t.startTime())
   179  				events = append(events, event{
   180  					WhenString: fmt.Sprintf("%2.9f", sinceStart.Seconds()),
   181  					Elapsed:    ev.Time().Sub(last),
   182  					What:       what,
   183  					Goroutine:  primaryGoroutine(ev),
   184  				})
   185  				last = ev.Time()
   186  			}
   187  			taskSpan := taskInterval(t, summary)
   188  			taskStart := taskSpan.start.Sub(t.startTime())
   189  
   190  			// Produce the task summary.
   191  			tasks = append(tasks, task{
   192  				WhenString: fmt.Sprintf("%2.9fs", taskStart.Seconds()),
   193  				Duration:   taskSpan.duration(),
   194  				ID:         summary.ID,
   195  				Complete:   summary.Complete(),
   196  				Events:     events,
   197  				Start:      taskStart,
   198  				End:        taskStart + taskSpan.duration(),
   199  			})
   200  		}
   201  		// Sort the tasks by duration.
   202  		slices.SortFunc(tasks, func(a, b task) int {
   203  			return cmp.Compare(a.Duration, b.Duration)
   204  		})
   205  
   206  		// Emit table.
   207  		err = templUserTaskType.Execute(w, struct {
   208  			Name  string
   209  			Tasks []task
   210  		}{
   211  			Name:  filter.name,
   212  			Tasks: tasks,
   213  		})
   214  		if err != nil {
   215  			log.Printf("failed to execute template: %v", err)
   216  			http.Error(w, fmt.Sprintf("failed to execute template: %v", err), http.StatusInternalServerError)
   217  			return
   218  		}
   219  	}
   220  }
   221  
   222  var templUserTaskType = template.Must(template.New("userTask").Funcs(template.FuncMap{
   223  	"elapsed":       elapsed,
   224  	"asMillisecond": asMillisecond,
   225  	"trimSpace":     strings.TrimSpace,
   226  }).Parse(`
   227  <!DOCTYPE html>
   228  <title>Tasks: {{.Name}}</title>
   229  <style>` + traceviewer.CommonStyle + `
   230  body {
   231    font-family: sans-serif;
   232  }
   233  table#req-status td.family {
   234    padding-right: 2em;
   235  }
   236  table#req-status td.active {
   237    padding-right: 1em;
   238  }
   239  table#req-status td.empty {
   240    color: #aaa;
   241  }
   242  table#reqs {
   243    margin-top: 1em;
   244    border-collapse: collapse;
   245  }
   246  table#reqs tr.first {
   247    font-weight: bold;
   248  }
   249  table#reqs td {
   250    font-family: monospace;
   251  }
   252  table#reqs td.when {
   253    text-align: right;
   254    white-space: nowrap;
   255  }
   256  table#reqs td.elapsed {
   257    padding: 0 0.5em;
   258    text-align: right;
   259    white-space: pre;
   260    width: 10em;
   261  }
   262  address {
   263    font-size: smaller;
   264    margin-top: 5em;
   265  }
   266  </style>
   267  <body>
   268  
   269  <h2>User Task: {{.Name}}</h2>
   270  
   271  Search log text: <form onsubmit="window.location.search+='&logtext='+window.logtextinput.value; return false">
   272  <input name="logtext" id="logtextinput" type="text"><input type="submit">
   273  </form><br>
   274  
   275  <table id="reqs">
   276  	<tr>
   277  		<th>When</th>
   278  		<th>Elapsed</th>
   279  		<th>Goroutine</th>
   280  		<th>Events</th>
   281  	</tr>
   282  	{{range $el := $.Tasks}}
   283  	<tr class="first">
   284  		<td class="when">{{$el.WhenString}}</td>
   285  		<td class="elapsed">{{$el.Duration}}</td>
   286  		<td></td>
   287  		<td>
   288  			<a href="/trace?focustask={{$el.ID}}#{{asMillisecond $el.Start}}:{{asMillisecond $el.End}}">Task {{$el.ID}}</a>
   289  			<a href="/trace?taskid={{$el.ID}}#{{asMillisecond $el.Start}}:{{asMillisecond $el.End}}">(goroutine view)</a>
   290  			({{if .Complete}}complete{{else}}incomplete{{end}})
   291  		</td>
   292  	</tr>
   293  	{{range $el.Events}}
   294  	<tr>
   295  		<td class="when">{{.WhenString}}</td>
   296  		<td class="elapsed">{{elapsed .Elapsed}}</td>
   297  		<td class="goid">{{.Goroutine}}</td>
   298  		<td>{{.What}}</td>
   299  	</tr>
   300  	{{end}}
   301      {{end}}
   302  </body>
   303  </html>
   304  `))
   305  
   306  // taskFilter represents a task filter specified by a user of cmd/trace.
   307  type taskFilter struct {
   308  	name string
   309  	cond []func(*parsedTrace, *trace.UserTaskSummary) bool
   310  }
   311  
   312  // match returns true if a task, described by its ID and summary, matches
   313  // the filter.
   314  func (f *taskFilter) match(t *parsedTrace, task *trace.UserTaskSummary) bool {
   315  	if t == nil {
   316  		return false
   317  	}
   318  	for _, c := range f.cond {
   319  		if !c(t, task) {
   320  			return false
   321  		}
   322  	}
   323  	return true
   324  }
   325  
   326  // newTaskFilter creates a new task filter from URL query variables.
   327  func newTaskFilter(r *http.Request) (*taskFilter, error) {
   328  	if err := r.ParseForm(); err != nil {
   329  		return nil, err
   330  	}
   331  
   332  	var name []string
   333  	var conditions []func(*parsedTrace, *trace.UserTaskSummary) bool
   334  
   335  	param := r.Form
   336  	if typ, ok := param["type"]; ok && len(typ) > 0 {
   337  		name = append(name, fmt.Sprintf("%q", typ[0]))
   338  		conditions = append(conditions, func(_ *parsedTrace, task *trace.UserTaskSummary) bool {
   339  			return task.Name == typ[0]
   340  		})
   341  	}
   342  	if complete := r.FormValue("complete"); complete == "1" {
   343  		name = append(name, "complete")
   344  		conditions = append(conditions, func(_ *parsedTrace, task *trace.UserTaskSummary) bool {
   345  			return task.Complete()
   346  		})
   347  	} else if complete == "0" {
   348  		name = append(name, "incomplete")
   349  		conditions = append(conditions, func(_ *parsedTrace, task *trace.UserTaskSummary) bool {
   350  			return !task.Complete()
   351  		})
   352  	}
   353  	if lat, err := time.ParseDuration(r.FormValue("latmin")); err == nil {
   354  		name = append(name, fmt.Sprintf("latency >= %s", lat))
   355  		conditions = append(conditions, func(t *parsedTrace, task *trace.UserTaskSummary) bool {
   356  			return task.Complete() && taskInterval(t, task).duration() >= lat
   357  		})
   358  	}
   359  	if lat, err := time.ParseDuration(r.FormValue("latmax")); err == nil {
   360  		name = append(name, fmt.Sprintf("latency <= %s", lat))
   361  		conditions = append(conditions, func(t *parsedTrace, task *trace.UserTaskSummary) bool {
   362  			return task.Complete() && taskInterval(t, task).duration() <= lat
   363  		})
   364  	}
   365  	if text := r.FormValue("logtext"); text != "" {
   366  		name = append(name, fmt.Sprintf("log contains %q", text))
   367  		conditions = append(conditions, func(_ *parsedTrace, task *trace.UserTaskSummary) bool {
   368  			return taskMatches(task, text)
   369  		})
   370  	}
   371  
   372  	return &taskFilter{name: strings.Join(name, ","), cond: conditions}, nil
   373  }
   374  
   375  func taskInterval(t *parsedTrace, s *trace.UserTaskSummary) interval {
   376  	var i interval
   377  	if s.Start != nil {
   378  		i.start = s.Start.Time()
   379  	} else {
   380  		i.start = t.startTime()
   381  	}
   382  	if s.End != nil {
   383  		i.end = s.End.Time()
   384  	} else {
   385  		i.end = t.endTime()
   386  	}
   387  	return i
   388  }
   389  
   390  func taskMatches(t *trace.UserTaskSummary, text string) bool {
   391  	matches := func(s string) bool {
   392  		return strings.Contains(s, text)
   393  	}
   394  	if matches(t.Name) {
   395  		return true
   396  	}
   397  	for _, r := range t.Regions {
   398  		if matches(r.Name) {
   399  			return true
   400  		}
   401  	}
   402  	for _, ev := range t.Logs {
   403  		log := ev.Log()
   404  		if matches(log.Category) {
   405  			return true
   406  		}
   407  		if matches(log.Message) {
   408  			return true
   409  		}
   410  	}
   411  	return false
   412  }
   413  
   414  func describeEvent(ev *trace.Event) string {
   415  	switch ev.Kind() {
   416  	case trace.EventStateTransition:
   417  		st := ev.StateTransition()
   418  		if st.Resource.Kind != trace.ResourceGoroutine {
   419  			return ""
   420  		}
   421  		old, new := st.Goroutine()
   422  		return fmt.Sprintf("%s -> %s", old, new)
   423  	case trace.EventRegionBegin:
   424  		return fmt.Sprintf("region %q begin", ev.Region().Type)
   425  	case trace.EventRegionEnd:
   426  		return fmt.Sprintf("region %q end", ev.Region().Type)
   427  	case trace.EventTaskBegin:
   428  		t := ev.Task()
   429  		return fmt.Sprintf("task %q (D %d, parent %d) begin", t.Type, t.ID, t.Parent)
   430  	case trace.EventTaskEnd:
   431  		return "task end"
   432  	case trace.EventLog:
   433  		log := ev.Log()
   434  		if log.Category != "" {
   435  			return fmt.Sprintf("log %q", log.Message)
   436  		}
   437  		return fmt.Sprintf("log (category: %s): %q", log.Category, log.Message)
   438  	}
   439  	return ""
   440  }
   441  
   442  func primaryGoroutine(ev *trace.Event) trace.GoID {
   443  	if ev.Kind() != trace.EventStateTransition {
   444  		return ev.Goroutine()
   445  	}
   446  	st := ev.StateTransition()
   447  	if st.Resource.Kind != trace.ResourceGoroutine {
   448  		return trace.NoGoroutine
   449  	}
   450  	return st.Resource.Goroutine()
   451  }
   452  
   453  func elapsed(d time.Duration) string {
   454  	b := fmt.Appendf(nil, "%.9f", d.Seconds())
   455  
   456  	// For subsecond durations, blank all zeros before decimal point,
   457  	// and all zeros between the decimal point and the first non-zero digit.
   458  	if d < time.Second {
   459  		dot := bytes.IndexByte(b, '.')
   460  		for i := 0; i < dot; i++ {
   461  			b[i] = ' '
   462  		}
   463  		for i := dot + 1; i < len(b); i++ {
   464  			if b[i] == '0' {
   465  				b[i] = ' '
   466  			} else {
   467  				break
   468  			}
   469  		}
   470  	}
   471  	return string(b)
   472  }
   473  
   474  func asMillisecond(d time.Duration) float64 {
   475  	return float64(d.Nanoseconds()) / float64(time.Millisecond)
   476  }
   477
View as plain text