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
5package main
6
7import (
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.
22func 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
55type taskStats struct {
56	Type      string
57	Count     int                       // Complete + incomplete tasks
58	Histogram traceviewer.TimeHistogram // Complete tasks only
59}
60
61func (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
67func (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
74var 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}
82th {
83  background-color: #050505;
84  color: #fff;
85}
86table {
87  border-collapse: collapse;
88}
89td,
90th {
91  padding-left: 8px;
92  padding-right: 8px;
93  padding-top: 4px;
94  padding-bottom: 4px;
95}
96</style>
97<body>
98Search 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.
118func 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
222var 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 + `
230body {
231  font-family: sans-serif;
232}
233table#req-status td.family {
234  padding-right: 2em;
235}
236table#req-status td.active {
237  padding-right: 1em;
238}
239table#req-status td.empty {
240  color: #aaa;
241}
242table#reqs {
243  margin-top: 1em;
244  border-collapse: collapse;
245}
246table#reqs tr.first {
247  font-weight: bold;
248}
249table#reqs td {
250  font-family: monospace;
251}
252table#reqs td.when {
253  text-align: right;
254  white-space: nowrap;
255}
256table#reqs td.elapsed {
257  padding: 0 0.5em;
258  text-align: right;
259  white-space: pre;
260  width: 10em;
261}
262address {
263  font-size: smaller;
264  margin-top: 5em;
265}
266</style>
267<body>
268
269<h2>User Task: {{.Name}}</h2>
270
271Search 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.
307type 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.
314func (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.
327func 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
375func 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
390func 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
414func 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
442func 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
453func 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
474func asMillisecond(d time.Duration) float64 {
475	return float64(d.Nanoseconds()) / float64(time.Millisecond)
476}
477