github.com/go-asm/go@v1.21.1-0.20240213172139-40c5ead50c48/cmd/trace/v2/tasks.go (about)

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