Source file src/cmd/trace/annotations.go

Documentation: cmd/trace

     1  // Copyright 2018 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  	"fmt"
    10  	"html/template"
    11  	"internal/trace"
    12  	"log"
    13  	"math"
    14  	"net/http"
    15  	"reflect"
    16  	"sort"
    17  	"strconv"
    18  	"strings"
    19  	"time"
    20  )
    21  
    22  func init() {
    23  	http.HandleFunc("/usertasks", httpUserTasks)
    24  	http.HandleFunc("/usertask", httpUserTask)
    25  	http.HandleFunc("/userregions", httpUserRegions)
    26  	http.HandleFunc("/userregion", httpUserRegion)
    27  }
    28  
    29  // httpUserTasks reports all tasks found in the trace.
    30  func httpUserTasks(w http.ResponseWriter, r *http.Request) {
    31  	res, err := analyzeAnnotations()
    32  	if err != nil {
    33  		http.Error(w, err.Error(), http.StatusInternalServerError)
    34  		return
    35  	}
    36  
    37  	tasks := res.tasks
    38  	summary := make(map[string]taskStats)
    39  	for _, task := range tasks {
    40  		stats, ok := summary[task.name]
    41  		if !ok {
    42  			stats.Type = task.name
    43  		}
    44  
    45  		stats.add(task)
    46  		summary[task.name] = stats
    47  	}
    48  
    49  	// Sort tasks by type.
    50  	userTasks := make([]taskStats, 0, len(summary))
    51  	for _, stats := range summary {
    52  		userTasks = append(userTasks, stats)
    53  	}
    54  	sort.Slice(userTasks, func(i, j int) bool {
    55  		return userTasks[i].Type < userTasks[j].Type
    56  	})
    57  
    58  	// Emit table.
    59  	err = templUserTaskTypes.Execute(w, userTasks)
    60  	if err != nil {
    61  		http.Error(w, fmt.Sprintf("failed to execute template: %v", err), http.StatusInternalServerError)
    62  		return
    63  	}
    64  }
    65  
    66  func httpUserRegions(w http.ResponseWriter, r *http.Request) {
    67  	res, err := analyzeAnnotations()
    68  	if err != nil {
    69  		http.Error(w, err.Error(), http.StatusInternalServerError)
    70  		return
    71  	}
    72  	allRegions := res.regions
    73  
    74  	summary := make(map[regionTypeID]regionStats)
    75  	for id, regions := range allRegions {
    76  		stats, ok := summary[id]
    77  		if !ok {
    78  			stats.regionTypeID = id
    79  		}
    80  		for _, s := range regions {
    81  			stats.add(s)
    82  		}
    83  		summary[id] = stats
    84  	}
    85  	// Sort regions by pc and name
    86  	userRegions := make([]regionStats, 0, len(summary))
    87  	for _, stats := range summary {
    88  		userRegions = append(userRegions, stats)
    89  	}
    90  	sort.Slice(userRegions, func(i, j int) bool {
    91  		if userRegions[i].Type != userRegions[j].Type {
    92  			return userRegions[i].Type < userRegions[j].Type
    93  		}
    94  		return userRegions[i].Frame.PC < userRegions[j].Frame.PC
    95  	})
    96  	// Emit table.
    97  	err = templUserRegionTypes.Execute(w, userRegions)
    98  	if err != nil {
    99  		http.Error(w, fmt.Sprintf("failed to execute template: %v", err), http.StatusInternalServerError)
   100  		return
   101  	}
   102  }
   103  
   104  func httpUserRegion(w http.ResponseWriter, r *http.Request) {
   105  	filter, err := newRegionFilter(r)
   106  	if err != nil {
   107  		http.Error(w, err.Error(), http.StatusBadRequest)
   108  		return
   109  	}
   110  	res, err := analyzeAnnotations()
   111  	if err != nil {
   112  		http.Error(w, err.Error(), http.StatusInternalServerError)
   113  		return
   114  	}
   115  	allRegions := res.regions
   116  
   117  	var data []regionDesc
   118  
   119  	var maxTotal int64
   120  	for id, regions := range allRegions {
   121  		for _, s := range regions {
   122  			if !filter.match(id, s) {
   123  				continue
   124  			}
   125  			data = append(data, s)
   126  			if maxTotal < s.TotalTime {
   127  				maxTotal = s.TotalTime
   128  			}
   129  		}
   130  	}
   131  
   132  	sortby := r.FormValue("sortby")
   133  	_, ok := reflect.TypeOf(regionDesc{}).FieldByNameFunc(func(s string) bool {
   134  		return s == sortby
   135  	})
   136  	if !ok {
   137  		sortby = "TotalTime"
   138  	}
   139  	sort.Slice(data, func(i, j int) bool {
   140  		ival := reflect.ValueOf(data[i]).FieldByName(sortby).Int()
   141  		jval := reflect.ValueOf(data[j]).FieldByName(sortby).Int()
   142  		return ival > jval
   143  	})
   144  
   145  	err = templUserRegionType.Execute(w, struct {
   146  		MaxTotal int64
   147  		Data     []regionDesc
   148  		Name     string
   149  	}{
   150  		MaxTotal: maxTotal,
   151  		Data:     data,
   152  		Name:     filter.name,
   153  	})
   154  	if err != nil {
   155  		http.Error(w, fmt.Sprintf("failed to execute template: %v", err), http.StatusInternalServerError)
   156  		return
   157  	}
   158  }
   159  
   160  // httpUserTask presents the details of the selected tasks.
   161  func httpUserTask(w http.ResponseWriter, r *http.Request) {
   162  	filter, err := newTaskFilter(r)
   163  	if err != nil {
   164  		http.Error(w, err.Error(), http.StatusBadRequest)
   165  		return
   166  	}
   167  
   168  	res, err := analyzeAnnotations()
   169  	if err != nil {
   170  		http.Error(w, err.Error(), http.StatusInternalServerError)
   171  		return
   172  	}
   173  	tasks := res.tasks
   174  
   175  	type event struct {
   176  		WhenString string
   177  		Elapsed    time.Duration
   178  		Go         uint64
   179  		What       string
   180  		// TODO: include stack trace of creation time
   181  	}
   182  	type entry struct {
   183  		WhenString string
   184  		ID         uint64
   185  		Duration   time.Duration
   186  		Complete   bool
   187  		Events     []event
   188  		Start, End time.Duration // Time since the beginning of the trace
   189  		GCTime     time.Duration
   190  	}
   191  
   192  	base := time.Duration(firstTimestamp()) * time.Nanosecond // trace start
   193  
   194  	var data []entry
   195  
   196  	for _, task := range tasks {
   197  		if !filter.match(task) {
   198  			continue
   199  		}
   200  		// merge events in the task.events and task.regions.Start
   201  		rawEvents := append([]*trace.Event{}, task.events...)
   202  		for _, s := range task.regions {
   203  			if s.Start != nil {
   204  				rawEvents = append(rawEvents, s.Start)
   205  			}
   206  		}
   207  		sort.SliceStable(rawEvents, func(i, j int) bool { return rawEvents[i].Ts < rawEvents[j].Ts })
   208  
   209  		var events []event
   210  		var last time.Duration
   211  		for i, ev := range rawEvents {
   212  			when := time.Duration(ev.Ts)*time.Nanosecond - base
   213  			elapsed := time.Duration(ev.Ts)*time.Nanosecond - last
   214  			if i == 0 {
   215  				elapsed = 0
   216  			}
   217  
   218  			what := describeEvent(ev)
   219  			if what != "" {
   220  				events = append(events, event{
   221  					WhenString: fmt.Sprintf("%2.9f", when.Seconds()),
   222  					Elapsed:    elapsed,
   223  					What:       what,
   224  					Go:         ev.G,
   225  				})
   226  				last = time.Duration(ev.Ts) * time.Nanosecond
   227  			}
   228  		}
   229  
   230  		data = append(data, entry{
   231  			WhenString: fmt.Sprintf("%2.9fs", (time.Duration(task.firstTimestamp())*time.Nanosecond - base).Seconds()),
   232  			Duration:   task.duration(),
   233  			ID:         task.id,
   234  			Complete:   task.complete(),
   235  			Events:     events,
   236  			Start:      time.Duration(task.firstTimestamp()) * time.Nanosecond,
   237  			End:        time.Duration(task.endTimestamp()) * time.Nanosecond,
   238  			GCTime:     task.overlappingGCDuration(res.gcEvents),
   239  		})
   240  	}
   241  	sort.Slice(data, func(i, j int) bool {
   242  		return data[i].Duration < data[j].Duration
   243  	})
   244  
   245  	// Emit table.
   246  	err = templUserTaskType.Execute(w, struct {
   247  		Name  string
   248  		Entry []entry
   249  	}{
   250  		Name:  filter.name,
   251  		Entry: data,
   252  	})
   253  	if err != nil {
   254  		log.Printf("failed to execute template: %v", err)
   255  		http.Error(w, fmt.Sprintf("failed to execute template: %v", err), http.StatusInternalServerError)
   256  		return
   257  	}
   258  }
   259  
   260  type annotationAnalysisResult struct {
   261  	tasks    map[uint64]*taskDesc          // tasks
   262  	regions  map[regionTypeID][]regionDesc // regions
   263  	gcEvents []*trace.Event                // GCStartevents, sorted
   264  }
   265  
   266  type regionTypeID struct {
   267  	Frame trace.Frame // top frame
   268  	Type  string
   269  }
   270  
   271  // analyzeAnnotations analyzes user annotation events and
   272  // returns the task descriptors keyed by internal task id.
   273  func analyzeAnnotations() (annotationAnalysisResult, error) {
   274  	res, err := parseTrace()
   275  	if err != nil {
   276  		return annotationAnalysisResult{}, fmt.Errorf("failed to parse trace: %v", err)
   277  	}
   278  
   279  	events := res.Events
   280  	if len(events) == 0 {
   281  		return annotationAnalysisResult{}, fmt.Errorf("empty trace")
   282  	}
   283  
   284  	tasks := allTasks{}
   285  	regions := map[regionTypeID][]regionDesc{}
   286  	var gcEvents []*trace.Event
   287  
   288  	for _, ev := range events {
   289  		switch typ := ev.Type; typ {
   290  		case trace.EvUserTaskCreate, trace.EvUserTaskEnd, trace.EvUserLog:
   291  			taskid := ev.Args[0]
   292  			task := tasks.task(taskid)
   293  			task.addEvent(ev)
   294  
   295  			// retrieve parent task information
   296  			if typ == trace.EvUserTaskCreate {
   297  				if parentID := ev.Args[1]; parentID != 0 {
   298  					parentTask := tasks.task(parentID)
   299  					task.parent = parentTask
   300  					if parentTask != nil {
   301  						parentTask.children = append(parentTask.children, task)
   302  					}
   303  				}
   304  			}
   305  
   306  		case trace.EvGCStart:
   307  			gcEvents = append(gcEvents, ev)
   308  		}
   309  	}
   310  	// combine region info.
   311  	analyzeGoroutines(events)
   312  	for goid, stats := range gs {
   313  		// gs is a global var defined in goroutines.go as a result
   314  		// of analyzeGoroutines. TODO(hyangah): fix this not to depend
   315  		// on a 'global' var.
   316  		for _, s := range stats.Regions {
   317  			if s.TaskID != 0 {
   318  				task := tasks.task(s.TaskID)
   319  				task.goroutines[goid] = struct{}{}
   320  				task.regions = append(task.regions, regionDesc{UserRegionDesc: s, G: goid})
   321  			}
   322  			var frame trace.Frame
   323  			if s.Start != nil {
   324  				frame = *s.Start.Stk[0]
   325  			}
   326  			id := regionTypeID{Frame: frame, Type: s.Name}
   327  			regions[id] = append(regions[id], regionDesc{UserRegionDesc: s, G: goid})
   328  		}
   329  	}
   330  
   331  	// sort regions in tasks based on the timestamps.
   332  	for _, task := range tasks {
   333  		sort.SliceStable(task.regions, func(i, j int) bool {
   334  			si, sj := task.regions[i].firstTimestamp(), task.regions[j].firstTimestamp()
   335  			if si != sj {
   336  				return si < sj
   337  			}
   338  			return task.regions[i].lastTimestamp() < task.regions[j].lastTimestamp()
   339  		})
   340  	}
   341  	return annotationAnalysisResult{tasks: tasks, regions: regions, gcEvents: gcEvents}, nil
   342  }
   343  
   344  // taskDesc represents a task.
   345  type taskDesc struct {
   346  	name       string              // user-provided task name
   347  	id         uint64              // internal task id
   348  	events     []*trace.Event      // sorted based on timestamp.
   349  	regions    []regionDesc        // associated regions, sorted based on the start timestamp and then the last timestamp.
   350  	goroutines map[uint64]struct{} // involved goroutines
   351  
   352  	create *trace.Event // Task create event
   353  	end    *trace.Event // Task end event
   354  
   355  	parent   *taskDesc
   356  	children []*taskDesc
   357  }
   358  
   359  func newTaskDesc(id uint64) *taskDesc {
   360  	return &taskDesc{
   361  		id:         id,
   362  		goroutines: make(map[uint64]struct{}),
   363  	}
   364  }
   365  
   366  func (task *taskDesc) String() string {
   367  	if task == nil {
   368  		return "task <nil>"
   369  	}
   370  	wb := new(bytes.Buffer)
   371  	fmt.Fprintf(wb, "task %d:\t%s\n", task.id, task.name)
   372  	fmt.Fprintf(wb, "\tstart: %v end: %v complete: %t\n", task.firstTimestamp(), task.endTimestamp(), task.complete())
   373  	fmt.Fprintf(wb, "\t%d goroutines\n", len(task.goroutines))
   374  	fmt.Fprintf(wb, "\t%d regions:\n", len(task.regions))
   375  	for _, s := range task.regions {
   376  		fmt.Fprintf(wb, "\t\t%s(goid=%d)\n", s.Name, s.G)
   377  	}
   378  	if task.parent != nil {
   379  		fmt.Fprintf(wb, "\tparent: %s\n", task.parent.name)
   380  	}
   381  	fmt.Fprintf(wb, "\t%d children:\n", len(task.children))
   382  	for _, c := range task.children {
   383  		fmt.Fprintf(wb, "\t\t%s\n", c.name)
   384  	}
   385  
   386  	return wb.String()
   387  }
   388  
   389  // regionDesc represents a region.
   390  type regionDesc struct {
   391  	*trace.UserRegionDesc
   392  	G uint64 // id of goroutine where the region was defined
   393  }
   394  
   395  type allTasks map[uint64]*taskDesc
   396  
   397  func (tasks allTasks) task(taskID uint64) *taskDesc {
   398  	if taskID == 0 {
   399  		return nil // notask
   400  	}
   401  
   402  	t, ok := tasks[taskID]
   403  	if ok {
   404  		return t
   405  	}
   406  
   407  	t = &taskDesc{
   408  		id:         taskID,
   409  		goroutines: make(map[uint64]struct{}),
   410  	}
   411  	tasks[taskID] = t
   412  	return t
   413  }
   414  
   415  func (task *taskDesc) addEvent(ev *trace.Event) {
   416  	if task == nil {
   417  		return
   418  	}
   419  
   420  	task.events = append(task.events, ev)
   421  	task.goroutines[ev.G] = struct{}{}
   422  
   423  	switch typ := ev.Type; typ {
   424  	case trace.EvUserTaskCreate:
   425  		task.name = ev.SArgs[0]
   426  		task.create = ev
   427  	case trace.EvUserTaskEnd:
   428  		task.end = ev
   429  	}
   430  }
   431  
   432  // complete is true only if both start and end events of this task
   433  // are present in the trace.
   434  func (task *taskDesc) complete() bool {
   435  	if task == nil {
   436  		return false
   437  	}
   438  	return task.create != nil && task.end != nil
   439  }
   440  
   441  // descendants returns all the task nodes in the subtree rooted from this task.
   442  func (task *taskDesc) descendants() []*taskDesc {
   443  	if task == nil {
   444  		return nil
   445  	}
   446  	res := []*taskDesc{task}
   447  	for i := 0; len(res[i:]) > 0; i++ {
   448  		t := res[i]
   449  		for _, c := range t.children {
   450  			res = append(res, c)
   451  		}
   452  	}
   453  	return res
   454  }
   455  
   456  // firstTimestamp returns the first timestamp of this task found in
   457  // this trace. If the trace does not contain the task creation event,
   458  // the first timestamp of the trace will be returned.
   459  func (task *taskDesc) firstTimestamp() int64 {
   460  	if task != nil && task.create != nil {
   461  		return task.create.Ts
   462  	}
   463  	return firstTimestamp()
   464  }
   465  
   466  // lastTimestamp returns the last timestamp of this task in this
   467  // trace. If the trace does not contain the task end event, the last
   468  // timestamp of the trace will be returned.
   469  func (task *taskDesc) lastTimestamp() int64 {
   470  	endTs := task.endTimestamp()
   471  	if last := task.lastEvent(); last != nil && last.Ts > endTs {
   472  		return last.Ts
   473  	}
   474  	return endTs
   475  }
   476  
   477  // endTimestamp returns the timestamp of this task's end event.
   478  // If the trace does not contain the task end event, the last
   479  // timestamp of the trace will be returned.
   480  func (task *taskDesc) endTimestamp() int64 {
   481  	if task != nil && task.end != nil {
   482  		return task.end.Ts
   483  	}
   484  	return lastTimestamp()
   485  }
   486  
   487  func (task *taskDesc) duration() time.Duration {
   488  	return time.Duration(task.endTimestamp()-task.firstTimestamp()) * time.Nanosecond
   489  }
   490  
   491  func (region *regionDesc) duration() time.Duration {
   492  	return time.Duration(region.lastTimestamp()-region.firstTimestamp()) * time.Nanosecond
   493  }
   494  
   495  // overlappingGCDuration returns the sum of GC period overlapping with the task's lifetime.
   496  func (task *taskDesc) overlappingGCDuration(evs []*trace.Event) (overlapping time.Duration) {
   497  	for _, ev := range evs {
   498  		// make sure we only consider the global GC events.
   499  		if typ := ev.Type; typ != trace.EvGCStart && typ != trace.EvGCSTWStart {
   500  			continue
   501  		}
   502  
   503  		if o, overlapped := task.overlappingDuration(ev); overlapped {
   504  			overlapping += o
   505  		}
   506  	}
   507  	return overlapping
   508  }
   509  
   510  // overlappingInstant reports whether the instantaneous event, ev, occurred during
   511  // any of the task's region if ev is a goroutine-local event, or overlaps with the
   512  // task's lifetime if ev is a global event.
   513  func (task *taskDesc) overlappingInstant(ev *trace.Event) bool {
   514  	if _, ok := isUserAnnotationEvent(ev); ok && task.id != ev.Args[0] {
   515  		return false // not this task's user event.
   516  	}
   517  
   518  	ts := ev.Ts
   519  	taskStart := task.firstTimestamp()
   520  	taskEnd := task.endTimestamp()
   521  	if ts < taskStart || taskEnd < ts {
   522  		return false
   523  	}
   524  	if ev.P == trace.GCP {
   525  		return true
   526  	}
   527  
   528  	// Goroutine local event. Check whether there are regions overlapping with the event.
   529  	goid := ev.G
   530  	for _, region := range task.regions {
   531  		if region.G != goid {
   532  			continue
   533  		}
   534  		if region.firstTimestamp() <= ts && ts <= region.lastTimestamp() {
   535  			return true
   536  		}
   537  	}
   538  	return false
   539  }
   540  
   541  // overlappingDuration reports whether the durational event, ev, overlaps with
   542  // any of the task's region if ev is a goroutine-local event, or overlaps with
   543  // the task's lifetime if ev is a global event. It returns the overlapping time
   544  // as well.
   545  func (task *taskDesc) overlappingDuration(ev *trace.Event) (time.Duration, bool) {
   546  	start := ev.Ts
   547  	end := lastTimestamp()
   548  	if ev.Link != nil {
   549  		end = ev.Link.Ts
   550  	}
   551  
   552  	if start > end {
   553  		return 0, false
   554  	}
   555  
   556  	goid := ev.G
   557  	goid2 := ev.G
   558  	if ev.Link != nil {
   559  		goid2 = ev.Link.G
   560  	}
   561  
   562  	// This event is a global GC event
   563  	if ev.P == trace.GCP {
   564  		taskStart := task.firstTimestamp()
   565  		taskEnd := task.endTimestamp()
   566  		o := overlappingDuration(taskStart, taskEnd, start, end)
   567  		return o, o > 0
   568  	}
   569  
   570  	// Goroutine local event. Check whether there are regions overlapping with the event.
   571  	var overlapping time.Duration
   572  	var lastRegionEnd int64 // the end of previous overlapping region
   573  	for _, region := range task.regions {
   574  		if region.G != goid && region.G != goid2 {
   575  			continue
   576  		}
   577  		regionStart, regionEnd := region.firstTimestamp(), region.lastTimestamp()
   578  		if regionStart < lastRegionEnd { // skip nested regions
   579  			continue
   580  		}
   581  
   582  		if o := overlappingDuration(regionStart, regionEnd, start, end); o > 0 {
   583  			// overlapping.
   584  			lastRegionEnd = regionEnd
   585  			overlapping += o
   586  		}
   587  	}
   588  	return overlapping, overlapping > 0
   589  }
   590  
   591  // overlappingDuration returns the overlapping time duration between
   592  // two time intervals [start1, end1] and [start2, end2] where
   593  // start, end parameters are all int64 representing nanoseconds.
   594  func overlappingDuration(start1, end1, start2, end2 int64) time.Duration {
   595  	// assume start1 <= end1 and start2 <= end2
   596  	if end1 < start2 || end2 < start1 {
   597  		return 0
   598  	}
   599  
   600  	if start1 < start2 { // choose the later one
   601  		start1 = start2
   602  	}
   603  	if end1 > end2 { // choose the earlier one
   604  		end1 = end2
   605  	}
   606  	return time.Duration(end1 - start1)
   607  }
   608  
   609  func (task *taskDesc) lastEvent() *trace.Event {
   610  	if task == nil {
   611  		return nil
   612  	}
   613  
   614  	if n := len(task.events); n > 0 {
   615  		return task.events[n-1]
   616  	}
   617  	return nil
   618  }
   619  
   620  // firstTimestamp returns the timestamp of region start event.
   621  // If the region's start event is not present in the trace,
   622  // the first timestamp of the trace will be returned.
   623  func (region *regionDesc) firstTimestamp() int64 {
   624  	if region.Start != nil {
   625  		return region.Start.Ts
   626  	}
   627  	return firstTimestamp()
   628  }
   629  
   630  // lastTimestamp returns the timestamp of region end event.
   631  // If the region's end event is not present in the trace,
   632  // the last timestamp of the trace will be returned.
   633  func (region *regionDesc) lastTimestamp() int64 {
   634  	if region.End != nil {
   635  		return region.End.Ts
   636  	}
   637  	return lastTimestamp()
   638  }
   639  
   640  // RelatedGoroutines returns IDs of goroutines related to the task. A goroutine
   641  // is related to the task if user annotation activities for the task occurred.
   642  // If non-zero depth is provided, this searches all events with BFS and includes
   643  // goroutines unblocked any of related goroutines to the result.
   644  func (task *taskDesc) RelatedGoroutines(events []*trace.Event, depth int) map[uint64]bool {
   645  	start, end := task.firstTimestamp(), task.endTimestamp()
   646  
   647  	gmap := map[uint64]bool{}
   648  	for k := range task.goroutines {
   649  		gmap[k] = true
   650  	}
   651  
   652  	for i := 0; i < depth; i++ {
   653  		gmap1 := make(map[uint64]bool)
   654  		for g := range gmap {
   655  			gmap1[g] = true
   656  		}
   657  		for _, ev := range events {
   658  			if ev.Ts < start || ev.Ts > end {
   659  				continue
   660  			}
   661  			if ev.Type == trace.EvGoUnblock && gmap[ev.Args[0]] {
   662  				gmap1[ev.G] = true
   663  			}
   664  			gmap = gmap1
   665  		}
   666  	}
   667  	gmap[0] = true // for GC events (goroutine id = 0)
   668  	return gmap
   669  }
   670  
   671  type taskFilter struct {
   672  	name string
   673  	cond []func(*taskDesc) bool
   674  }
   675  
   676  func (f *taskFilter) match(t *taskDesc) bool {
   677  	if t == nil {
   678  		return false
   679  	}
   680  	for _, c := range f.cond {
   681  		if !c(t) {
   682  			return false
   683  		}
   684  	}
   685  	return true
   686  }
   687  
   688  func newTaskFilter(r *http.Request) (*taskFilter, error) {
   689  	if err := r.ParseForm(); err != nil {
   690  		return nil, err
   691  	}
   692  
   693  	var name []string
   694  	var conditions []func(*taskDesc) bool
   695  
   696  	param := r.Form
   697  	if typ, ok := param["type"]; ok && len(typ) > 0 {
   698  		name = append(name, "type="+typ[0])
   699  		conditions = append(conditions, func(t *taskDesc) bool {
   700  			return t.name == typ[0]
   701  		})
   702  	}
   703  	if complete := r.FormValue("complete"); complete == "1" {
   704  		name = append(name, "complete")
   705  		conditions = append(conditions, func(t *taskDesc) bool {
   706  			return t.complete()
   707  		})
   708  	} else if complete == "0" {
   709  		name = append(name, "incomplete")
   710  		conditions = append(conditions, func(t *taskDesc) bool {
   711  			return !t.complete()
   712  		})
   713  	}
   714  	if lat, err := time.ParseDuration(r.FormValue("latmin")); err == nil {
   715  		name = append(name, fmt.Sprintf("latency >= %s", lat))
   716  		conditions = append(conditions, func(t *taskDesc) bool {
   717  			return t.complete() && t.duration() >= lat
   718  		})
   719  	}
   720  	if lat, err := time.ParseDuration(r.FormValue("latmax")); err == nil {
   721  		name = append(name, fmt.Sprintf("latency <= %s", lat))
   722  		conditions = append(conditions, func(t *taskDesc) bool {
   723  			return t.complete() && t.duration() <= lat
   724  		})
   725  	}
   726  	if text := r.FormValue("logtext"); text != "" {
   727  		name = append(name, fmt.Sprintf("log contains %q", text))
   728  		conditions = append(conditions, func(t *taskDesc) bool {
   729  			return taskMatches(t, text)
   730  		})
   731  	}
   732  
   733  	return &taskFilter{name: strings.Join(name, ","), cond: conditions}, nil
   734  }
   735  
   736  func taskMatches(t *taskDesc, text string) bool {
   737  	for _, ev := range t.events {
   738  		switch ev.Type {
   739  		case trace.EvUserTaskCreate, trace.EvUserRegion, trace.EvUserLog:
   740  			for _, s := range ev.SArgs {
   741  				if strings.Contains(s, text) {
   742  					return true
   743  				}
   744  			}
   745  		}
   746  	}
   747  	return false
   748  }
   749  
   750  type regionFilter struct {
   751  	name string
   752  	cond []func(regionTypeID, regionDesc) bool
   753  }
   754  
   755  func (f *regionFilter) match(id regionTypeID, s regionDesc) bool {
   756  	for _, c := range f.cond {
   757  		if !c(id, s) {
   758  			return false
   759  		}
   760  	}
   761  	return true
   762  }
   763  
   764  func newRegionFilter(r *http.Request) (*regionFilter, error) {
   765  	if err := r.ParseForm(); err != nil {
   766  		return nil, err
   767  	}
   768  
   769  	var name []string
   770  	var conditions []func(regionTypeID, regionDesc) bool
   771  
   772  	param := r.Form
   773  	if typ, ok := param["type"]; ok && len(typ) > 0 {
   774  		name = append(name, "type="+typ[0])
   775  		conditions = append(conditions, func(id regionTypeID, s regionDesc) bool {
   776  			return id.Type == typ[0]
   777  		})
   778  	}
   779  	if pc, err := strconv.ParseUint(r.FormValue("pc"), 16, 64); err == nil {
   780  		name = append(name, fmt.Sprintf("pc=%x", pc))
   781  		conditions = append(conditions, func(id regionTypeID, s regionDesc) bool {
   782  			return id.Frame.PC == pc
   783  		})
   784  	}
   785  
   786  	if lat, err := time.ParseDuration(r.FormValue("latmin")); err == nil {
   787  		name = append(name, fmt.Sprintf("latency >= %s", lat))
   788  		conditions = append(conditions, func(_ regionTypeID, s regionDesc) bool {
   789  			return s.duration() >= lat
   790  		})
   791  	}
   792  	if lat, err := time.ParseDuration(r.FormValue("latmax")); err == nil {
   793  		name = append(name, fmt.Sprintf("latency <= %s", lat))
   794  		conditions = append(conditions, func(_ regionTypeID, s regionDesc) bool {
   795  			return s.duration() <= lat
   796  		})
   797  	}
   798  
   799  	return &regionFilter{name: strings.Join(name, ","), cond: conditions}, nil
   800  }
   801  
   802  type durationHistogram struct {
   803  	Count                int
   804  	Buckets              []int
   805  	MinBucket, MaxBucket int
   806  }
   807  
   808  // Five buckets for every power of 10.
   809  var logDiv = math.Log(math.Pow(10, 1.0/5))
   810  
   811  func (h *durationHistogram) add(d time.Duration) {
   812  	var bucket int
   813  	if d > 0 {
   814  		bucket = int(math.Log(float64(d)) / logDiv)
   815  	}
   816  	if len(h.Buckets) <= bucket {
   817  		h.Buckets = append(h.Buckets, make([]int, bucket-len(h.Buckets)+1)...)
   818  		h.Buckets = h.Buckets[:cap(h.Buckets)]
   819  	}
   820  	h.Buckets[bucket]++
   821  	if bucket < h.MinBucket || h.MaxBucket == 0 {
   822  		h.MinBucket = bucket
   823  	}
   824  	if bucket > h.MaxBucket {
   825  		h.MaxBucket = bucket
   826  	}
   827  	h.Count++
   828  }
   829  
   830  func (h *durationHistogram) BucketMin(bucket int) time.Duration {
   831  	return time.Duration(math.Exp(float64(bucket) * logDiv))
   832  }
   833  
   834  func niceDuration(d time.Duration) string {
   835  	var rnd time.Duration
   836  	var unit string
   837  	switch {
   838  	case d < 10*time.Microsecond:
   839  		rnd, unit = time.Nanosecond, "ns"
   840  	case d < 10*time.Millisecond:
   841  		rnd, unit = time.Microsecond, "µs"
   842  	case d < 10*time.Second:
   843  		rnd, unit = time.Millisecond, "ms"
   844  	default:
   845  		rnd, unit = time.Second, "s "
   846  	}
   847  	return fmt.Sprintf("%d%s", d/rnd, unit)
   848  }
   849  
   850  func (h *durationHistogram) ToHTML(urlmaker func(min, max time.Duration) string) template.HTML {
   851  	if h == nil || h.Count == 0 {
   852  		return template.HTML("")
   853  	}
   854  
   855  	const barWidth = 400
   856  
   857  	maxCount := 0
   858  	for _, count := range h.Buckets {
   859  		if count > maxCount {
   860  			maxCount = count
   861  		}
   862  	}
   863  
   864  	w := new(bytes.Buffer)
   865  	fmt.Fprintf(w, `<table>`)
   866  	for i := h.MinBucket; i <= h.MaxBucket; i++ {
   867  		// Tick label.
   868  		if h.Buckets[i] > 0 {
   869  			fmt.Fprintf(w, `<tr><td class="histoTime" align="right"><a href=%s>%s</a></td>`, urlmaker(h.BucketMin(i), h.BucketMin(i+1)), niceDuration(h.BucketMin(i)))
   870  		} else {
   871  			fmt.Fprintf(w, `<tr><td class="histoTime" align="right">%s</td>`, niceDuration(h.BucketMin(i)))
   872  		}
   873  		// Bucket bar.
   874  		width := h.Buckets[i] * barWidth / maxCount
   875  		fmt.Fprintf(w, `<td><div style="width:%dpx;background:blue;position:relative">&nbsp;</div></td>`, width)
   876  		// Bucket count.
   877  		fmt.Fprintf(w, `<td align="right"><div style="position:relative">%d</div></td>`, h.Buckets[i])
   878  		fmt.Fprintf(w, "</tr>\n")
   879  
   880  	}
   881  	// Final tick label.
   882  	fmt.Fprintf(w, `<tr><td align="right">%s</td></tr>`, niceDuration(h.BucketMin(h.MaxBucket+1)))
   883  	fmt.Fprintf(w, `</table>`)
   884  	return template.HTML(w.String())
   885  }
   886  
   887  func (h *durationHistogram) String() string {
   888  	const barWidth = 40
   889  
   890  	labels := []string{}
   891  	maxLabel := 0
   892  	maxCount := 0
   893  	for i := h.MinBucket; i <= h.MaxBucket; i++ {
   894  		// TODO: This formatting is pretty awful.
   895  		label := fmt.Sprintf("[%-12s%-11s)", h.BucketMin(i).String()+",", h.BucketMin(i+1))
   896  		labels = append(labels, label)
   897  		if len(label) > maxLabel {
   898  			maxLabel = len(label)
   899  		}
   900  		count := h.Buckets[i]
   901  		if count > maxCount {
   902  			maxCount = count
   903  		}
   904  	}
   905  
   906  	w := new(bytes.Buffer)
   907  	for i := h.MinBucket; i <= h.MaxBucket; i++ {
   908  		count := h.Buckets[i]
   909  		bar := count * barWidth / maxCount
   910  		fmt.Fprintf(w, "%*s %-*s %d\n", maxLabel, labels[i-h.MinBucket], barWidth, strings.Repeat("█", bar), count)
   911  	}
   912  	return w.String()
   913  }
   914  
   915  type regionStats struct {
   916  	regionTypeID
   917  	Histogram durationHistogram
   918  }
   919  
   920  func (s *regionStats) UserRegionURL() func(min, max time.Duration) string {
   921  	return func(min, max time.Duration) string {
   922  		return fmt.Sprintf("/userregion?type=%s&pc=%x&latmin=%v&latmax=%v", template.URLQueryEscaper(s.Type), s.Frame.PC, template.URLQueryEscaper(min), template.URLQueryEscaper(max))
   923  	}
   924  }
   925  
   926  func (s *regionStats) add(region regionDesc) {
   927  	s.Histogram.add(region.duration())
   928  }
   929  
   930  var templUserRegionTypes = template.Must(template.New("").Parse(`
   931  <html>
   932  <style type="text/css">
   933  .histoTime {
   934     width: 20%;
   935     white-space:nowrap;
   936  }
   937  
   938  </style>
   939  <body>
   940  <table border="1" sortable="1">
   941  <tr>
   942  <th>Region type</th>
   943  <th>Count</th>
   944  <th>Duration distribution (complete tasks)</th>
   945  </tr>
   946  {{range $}}
   947    <tr>
   948      <td>{{.Type}}<br>{{.Frame.Fn}}<br>{{.Frame.File}}:{{.Frame.Line}}</td>
   949      <td><a href="/userregion?type={{.Type}}&pc={{.Frame.PC}}">{{.Histogram.Count}}</a></td>
   950      <td>{{.Histogram.ToHTML (.UserRegionURL)}}</td>
   951    </tr>
   952  {{end}}
   953  </table>
   954  </body>
   955  </html>
   956  `))
   957  
   958  type taskStats struct {
   959  	Type      string
   960  	Count     int               // Complete + incomplete tasks
   961  	Histogram durationHistogram // Complete tasks only
   962  }
   963  
   964  func (s *taskStats) UserTaskURL(complete bool) func(min, max time.Duration) string {
   965  	return func(min, max time.Duration) string {
   966  		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))
   967  	}
   968  }
   969  
   970  func (s *taskStats) add(task *taskDesc) {
   971  	s.Count++
   972  	if task.complete() {
   973  		s.Histogram.add(task.duration())
   974  	}
   975  }
   976  
   977  var templUserTaskTypes = template.Must(template.New("").Parse(`
   978  <html>
   979  <style type="text/css">
   980  .histoTime {
   981     width: 20%;
   982     white-space:nowrap;
   983  }
   984  
   985  </style>
   986  <body>
   987  Search log text: <form action="/usertask"><input name="logtext" type="text"><input type="submit"></form><br>
   988  <table border="1" sortable="1">
   989  <tr>
   990  <th>Task type</th>
   991  <th>Count</th>
   992  <th>Duration distribution (complete tasks)</th>
   993  </tr>
   994  {{range $}}
   995    <tr>
   996      <td>{{.Type}}</td>
   997      <td><a href="/usertask?type={{.Type}}">{{.Count}}</a></td>
   998      <td>{{.Histogram.ToHTML (.UserTaskURL true)}}</td>
   999    </tr>
  1000  {{end}}
  1001  </table>
  1002  </body>
  1003  </html>
  1004  `))
  1005  
  1006  var templUserTaskType = template.Must(template.New("userTask").Funcs(template.FuncMap{
  1007  	"elapsed":       elapsed,
  1008  	"asMillisecond": asMillisecond,
  1009  	"trimSpace":     strings.TrimSpace,
  1010  }).Parse(`
  1011  <html>
  1012  <head> <title>User Task: {{.Name}} </title> </head>
  1013          <style type="text/css">
  1014                  body {
  1015                          font-family: sans-serif;
  1016                  }
  1017                  table#req-status td.family {
  1018                          padding-right: 2em;
  1019                  }
  1020                  table#req-status td.active {
  1021                          padding-right: 1em;
  1022                  }
  1023                  table#req-status td.empty {
  1024                          color: #aaa;
  1025                  }
  1026                  table#reqs {
  1027                          margin-top: 1em;
  1028                  }
  1029                  table#reqs tr.first {
  1030                          font-weight: bold;
  1031                  }
  1032                  table#reqs td {
  1033                          font-family: monospace;
  1034                  }
  1035                  table#reqs td.when {
  1036                          text-align: right;
  1037                          white-space: nowrap;
  1038                  }
  1039                  table#reqs td.elapsed {
  1040                          padding: 0 0.5em;
  1041                          text-align: right;
  1042                          white-space: pre;
  1043                          width: 10em;
  1044                  }
  1045                  address {
  1046                          font-size: smaller;
  1047                          margin-top: 5em;
  1048                  }
  1049          </style>
  1050  <body>
  1051  
  1052  <h2>User Task: {{.Name}}</h2>
  1053  
  1054  Search log text: <form onsubmit="window.location.search+='&logtext='+window.logtextinput.value; return false">
  1055  <input name="logtext" id="logtextinput" type="text"><input type="submit">
  1056  </form><br>
  1057  
  1058  <table id="reqs">
  1059  <tr><th>When</th><th>Elapsed</th><th>Goroutine ID</th><th>Events</th></tr>
  1060       {{range $el := $.Entry}}
  1061          <tr class="first">
  1062                  <td class="when">{{$el.WhenString}}</td>
  1063                  <td class="elapsed">{{$el.Duration}}</td>
  1064  		<td></td>
  1065                  <td><a href="/trace?taskid={{$el.ID}}#{{asMillisecond $el.Start}}:{{asMillisecond $el.End}}">Task {{$el.ID}}</a> ({{if .Complete}}complete{{else}}incomplete{{end}})</td>
  1066          </tr>
  1067          {{range $el.Events}}
  1068          <tr>
  1069                  <td class="when">{{.WhenString}}</td>
  1070                  <td class="elapsed">{{elapsed .Elapsed}}</td>
  1071  		<td class="goid">{{.Go}}</td>
  1072                  <td>{{.What}}</td>
  1073          </tr>
  1074          {{end}}
  1075  	<tr>
  1076  		<td></td>
  1077  		<td></td>
  1078  		<td></td>
  1079  		<td>GC:{{$el.GCTime}}</td>
  1080      {{end}}
  1081  </body>
  1082  </html>
  1083  `))
  1084  
  1085  func elapsed(d time.Duration) string {
  1086  	b := []byte(fmt.Sprintf("%.9f", d.Seconds()))
  1087  
  1088  	// For subsecond durations, blank all zeros before decimal point,
  1089  	// and all zeros between the decimal point and the first non-zero digit.
  1090  	if d < time.Second {
  1091  		dot := bytes.IndexByte(b, '.')
  1092  		for i := 0; i < dot; i++ {
  1093  			b[i] = ' '
  1094  		}
  1095  		for i := dot + 1; i < len(b); i++ {
  1096  			if b[i] == '0' {
  1097  				b[i] = ' '
  1098  			} else {
  1099  				break
  1100  			}
  1101  		}
  1102  	}
  1103  
  1104  	return string(b)
  1105  }
  1106  
  1107  func asMillisecond(d time.Duration) float64 {
  1108  	return float64(d.Nanoseconds()) / 1e6
  1109  }
  1110  
  1111  func formatUserLog(ev *trace.Event) string {
  1112  	k, v := ev.SArgs[0], ev.SArgs[1]
  1113  	if k == "" {
  1114  		return v
  1115  	}
  1116  	if v == "" {
  1117  		return k
  1118  	}
  1119  	return fmt.Sprintf("%v=%v", k, v)
  1120  }
  1121  
  1122  func describeEvent(ev *trace.Event) string {
  1123  	switch ev.Type {
  1124  	case trace.EvGoCreate:
  1125  		goid := ev.Args[0]
  1126  		return fmt.Sprintf("new goroutine %d: %s", goid, gs[goid].Name)
  1127  	case trace.EvGoEnd, trace.EvGoStop:
  1128  		return "goroutine stopped"
  1129  	case trace.EvUserLog:
  1130  		return formatUserLog(ev)
  1131  	case trace.EvUserRegion:
  1132  		if ev.Args[1] == 0 {
  1133  			duration := "unknown"
  1134  			if ev.Link != nil {
  1135  				duration = (time.Duration(ev.Link.Ts-ev.Ts) * time.Nanosecond).String()
  1136  			}
  1137  			return fmt.Sprintf("region %s started (duration: %v)", ev.SArgs[0], duration)
  1138  		}
  1139  		return fmt.Sprintf("region %s ended", ev.SArgs[0])
  1140  	case trace.EvUserTaskCreate:
  1141  		return fmt.Sprintf("task %v (id %d, parent %d) created", ev.SArgs[0], ev.Args[0], ev.Args[1])
  1142  		// TODO: add child task creation events into the parent task events
  1143  	case trace.EvUserTaskEnd:
  1144  		return "task end"
  1145  	}
  1146  	return ""
  1147  }
  1148  
  1149  func isUserAnnotationEvent(ev *trace.Event) (taskID uint64, ok bool) {
  1150  	switch ev.Type {
  1151  	case trace.EvUserLog, trace.EvUserRegion, trace.EvUserTaskCreate, trace.EvUserTaskEnd:
  1152  		return ev.Args[0], true
  1153  	}
  1154  	return 0, false
  1155  }
  1156  
  1157  var templUserRegionType = template.Must(template.New("").Funcs(template.FuncMap{
  1158  	"prettyDuration": func(nsec int64) template.HTML {
  1159  		d := time.Duration(nsec) * time.Nanosecond
  1160  		return template.HTML(niceDuration(d))
  1161  	},
  1162  	"percent": func(dividened, divisor int64) template.HTML {
  1163  		if divisor == 0 {
  1164  			return ""
  1165  		}
  1166  		return template.HTML(fmt.Sprintf("(%.1f%%)", float64(dividened)/float64(divisor)*100))
  1167  	},
  1168  	"barLen": func(dividened, divisor int64) template.HTML {
  1169  		if divisor == 0 {
  1170  			return "0"
  1171  		}
  1172  		return template.HTML(fmt.Sprintf("%.2f%%", float64(dividened)/float64(divisor)*100))
  1173  	},
  1174  	"unknownTime": func(desc regionDesc) int64 {
  1175  		sum := desc.ExecTime + desc.IOTime + desc.BlockTime + desc.SyscallTime + desc.SchedWaitTime
  1176  		if sum < desc.TotalTime {
  1177  			return desc.TotalTime - sum
  1178  		}
  1179  		return 0
  1180  	},
  1181  }).Parse(`
  1182  <!DOCTYPE html>
  1183  <title>Goroutine {{.Name}}</title>
  1184  <style>
  1185  th {
  1186    background-color: #050505;
  1187    color: #fff;
  1188  }
  1189  table {
  1190    border-collapse: collapse;
  1191  }
  1192  .details tr:hover {
  1193    background-color: #f2f2f2;
  1194  }
  1195  .details td {
  1196    text-align: right;
  1197    border: 1px solid #000;
  1198  }
  1199  .details td.id {
  1200    text-align: left;
  1201  }
  1202  .stacked-bar-graph {
  1203    width: 300px;
  1204    height: 10px;
  1205    color: #414042;
  1206    white-space: nowrap;
  1207    font-size: 5px;
  1208  }
  1209  .stacked-bar-graph span {
  1210    display: inline-block;
  1211    width: 100%;
  1212    height: 100%;
  1213    box-sizing: border-box;
  1214    float: left;
  1215    padding: 0;
  1216  }
  1217  .unknown-time { background-color: #636363; }
  1218  .exec-time { background-color: #d7191c; }
  1219  .io-time { background-color: #fdae61; }
  1220  .block-time { background-color: #d01c8b; }
  1221  .syscall-time { background-color: #7b3294; }
  1222  .sched-time { background-color: #2c7bb6; }
  1223  </style>
  1224  
  1225  <script>
  1226  function reloadTable(key, value) {
  1227    let params = new URLSearchParams(window.location.search);
  1228    params.set(key, value);
  1229    window.location.search = params.toString();
  1230  }
  1231  </script>
  1232  
  1233  <h2>{{.Name}}</h2>
  1234  
  1235  <table class="details">
  1236  <tr>
  1237  <th> Goroutine </th>
  1238  <th> Task </th>
  1239  <th onclick="reloadTable('sortby', 'TotalTime')"> Total</th>
  1240  <th></th>
  1241  <th onclick="reloadTable('sortby', 'ExecTime')" class="exec-time"> Execution</th>
  1242  <th onclick="reloadTable('sortby', 'IOTime')" class="io-time"> Network wait</th>
  1243  <th onclick="reloadTable('sortby', 'BlockTime')" class="block-time"> Sync block </th>
  1244  <th onclick="reloadTable('sortby', 'SyscallTime')" class="syscall-time"> Blocking syscall</th>
  1245  <th onclick="reloadTable('sortby', 'SchedWaitTime')" class="sched-time"> Scheduler wait</th>
  1246  <th onclick="reloadTable('sortby', 'SweepTime')"> GC sweeping</th>
  1247  <th onclick="reloadTable('sortby', 'GCTime')"> GC pause</th>
  1248  </tr>
  1249  {{range .Data}}
  1250    <tr>
  1251      <td> <a href="/trace?goid={{.G}}">{{.G}}</a> </td>
  1252      <td> {{if .TaskID}}<a href="/trace?taskid={{.TaskID}}">{{.TaskID}}</a>{{end}} </td>
  1253      <td> {{prettyDuration .TotalTime}} </td>
  1254      <td>
  1255          <div class="stacked-bar-graph">
  1256            {{if unknownTime .}}<span style="width:{{barLen (unknownTime .) $.MaxTotal}}" class="unknown-time">&nbsp;</span>{{end}}
  1257            {{if .ExecTime}}<span style="width:{{barLen .ExecTime $.MaxTotal}}" class="exec-time">&nbsp;</span>{{end}}
  1258            {{if .IOTime}}<span style="width:{{barLen .IOTime $.MaxTotal}}" class="io-time">&nbsp;</span>{{end}}
  1259            {{if .BlockTime}}<span style="width:{{barLen .BlockTime $.MaxTotal}}" class="block-time">&nbsp;</span>{{end}}
  1260            {{if .SyscallTime}}<span style="width:{{barLen .SyscallTime $.MaxTotal}}" class="syscall-time">&nbsp;</span>{{end}}
  1261            {{if .SchedWaitTime}}<span style="width:{{barLen .SchedWaitTime $.MaxTotal}}" class="sched-time">&nbsp;</span>{{end}}
  1262          </div>
  1263      </td>
  1264      <td> {{prettyDuration .ExecTime}}</td>
  1265      <td> {{prettyDuration .IOTime}}</td>
  1266      <td> {{prettyDuration .BlockTime}}</td>
  1267      <td> {{prettyDuration .SyscallTime}}</td>
  1268      <td> {{prettyDuration .SchedWaitTime}}</td>
  1269      <td> {{prettyDuration .SweepTime}} {{percent .SweepTime .TotalTime}}</td>
  1270      <td> {{prettyDuration .GCTime}} {{percent .GCTime .TotalTime}}</td>
  1271    </tr>
  1272  {{end}}
  1273  </table>
  1274  `))
  1275  

View as plain text