Source file src/cmd/trace/annotations.go

     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(dividend, divisor int64) template.HTML {
  1163			if divisor == 0 {
  1164				return ""
  1165			}
  1166			return template.HTML(fmt.Sprintf("(%.1f%%)", float64(dividend)/float64(divisor)*100))
  1167		},
  1168		"barLen": func(dividend, divisor int64) template.HTML {
  1169			if divisor == 0 {
  1170				return "0"
  1171			}
  1172			return template.HTML(fmt.Sprintf("%.2f%%", float64(dividend)/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