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