tasks.go

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