github.com/megatontech/mynoteforgo@v0.0.0-20200507084910-5d0c6ea6e890/源码/cmd/trace/annotations.go (about) 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 ®ionFilter{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"> </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"> </span>{{end}} 1257 {{if .ExecTime}}<span style="width:{{barLen .ExecTime $.MaxTotal}}" class="exec-time"> </span>{{end}} 1258 {{if .IOTime}}<span style="width:{{barLen .IOTime $.MaxTotal}}" class="io-time"> </span>{{end}} 1259 {{if .BlockTime}}<span style="width:{{barLen .BlockTime $.MaxTotal}}" class="block-time"> </span>{{end}} 1260 {{if .SyscallTime}}<span style="width:{{barLen .SyscallTime $.MaxTotal}}" class="syscall-time"> </span>{{end}} 1261 {{if .SchedWaitTime}}<span style="width:{{barLen .SchedWaitTime $.MaxTotal}}" class="sched-time"> </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 `))