annotations.go 33.3 KB
Newer Older
1 2 3 4 5 6 7 8 9 10
package main

import (
	"bytes"
	"fmt"
	"html/template"
	"internal/trace"
	"log"
	"math"
	"net/http"
Hana Kim's avatar
Hana Kim committed
11
	"reflect"
12
	"sort"
13
	"strconv"
14 15 16 17 18 19 20
	"strings"
	"time"
)

func init() {
	http.HandleFunc("/usertasks", httpUserTasks)
	http.HandleFunc("/usertask", httpUserTask)
21 22
	http.HandleFunc("/userregions", httpUserRegions)
	http.HandleFunc("/userregion", httpUserRegion)
23 24 25 26
}

// httpUserTasks reports all tasks found in the trace.
func httpUserTasks(w http.ResponseWriter, r *http.Request) {
27
	res, err := analyzeAnnotations()
28 29 30 31 32
	if err != nil {
		http.Error(w, err.Error(), http.StatusInternalServerError)
		return
	}

33
	tasks := res.tasks
34 35 36 37 38 39 40 41 42 43 44 45 46 47 48 49 50 51 52 53 54 55 56 57 58 59 60 61
	summary := make(map[string]taskStats)
	for _, task := range tasks {
		stats, ok := summary[task.name]
		if !ok {
			stats.Type = task.name
		}

		stats.add(task)
		summary[task.name] = stats
	}

	// Sort tasks by type.
	userTasks := make([]taskStats, 0, len(summary))
	for _, stats := range summary {
		userTasks = append(userTasks, stats)
	}
	sort.Slice(userTasks, func(i, j int) bool {
		return userTasks[i].Type < userTasks[j].Type
	})

	// Emit table.
	err = templUserTaskTypes.Execute(w, userTasks)
	if err != nil {
		http.Error(w, fmt.Sprintf("failed to execute template: %v", err), http.StatusInternalServerError)
		return
	}
}

62
func httpUserRegions(w http.ResponseWriter, r *http.Request) {
63 64 65 66 67
	res, err := analyzeAnnotations()
	if err != nil {
		http.Error(w, err.Error(), http.StatusInternalServerError)
		return
	}
68
	allRegions := res.regions
69

70 71
	summary := make(map[regionTypeID]regionStats)
	for id, regions := range allRegions {
72 73
		stats, ok := summary[id]
		if !ok {
74
			stats.regionTypeID = id
75
		}
76
		for _, s := range regions {
77 78 79 80
			stats.add(s)
		}
		summary[id] = stats
	}
81 82
	// Sort regions by pc and name
	userRegions := make([]regionStats, 0, len(summary))
83
	for _, stats := range summary {
84
		userRegions = append(userRegions, stats)
85
	}
86 87 88
	sort.Slice(userRegions, func(i, j int) bool {
		if userRegions[i].Type != userRegions[j].Type {
			return userRegions[i].Type < userRegions[j].Type
89
		}
90
		return userRegions[i].Frame.PC < userRegions[j].Frame.PC
91 92
	})
	// Emit table.
93
	err = templUserRegionTypes.Execute(w, userRegions)
94 95 96 97 98 99
	if err != nil {
		http.Error(w, fmt.Sprintf("failed to execute template: %v", err), http.StatusInternalServerError)
		return
	}
}

100 101
func httpUserRegion(w http.ResponseWriter, r *http.Request) {
	filter, err := newRegionFilter(r)
102 103 104 105 106 107 108 109 110
	if err != nil {
		http.Error(w, err.Error(), http.StatusBadRequest)
		return
	}
	res, err := analyzeAnnotations()
	if err != nil {
		http.Error(w, err.Error(), http.StatusInternalServerError)
		return
	}
111
	allRegions := res.regions
112

113
	var data []regionDesc
114

Hana Kim's avatar
Hana Kim committed
115
	var maxTotal int64
116 117
	for id, regions := range allRegions {
		for _, s := range regions {
118 119 120 121
			if !filter.match(id, s) {
				continue
			}
			data = append(data, s)
Hana Kim's avatar
Hana Kim committed
122 123 124
			if maxTotal < s.TotalTime {
				maxTotal = s.TotalTime
			}
125 126 127
		}
	}

Hana Kim's avatar
Hana Kim committed
128
	sortby := r.FormValue("sortby")
129
	_, ok := reflect.TypeOf(regionDesc{}).FieldByNameFunc(func(s string) bool {
Hana Kim's avatar
Hana Kim committed
130 131 132 133 134 135 136 137 138 139 140
		return s == sortby
	})
	if !ok {
		sortby = "TotalTime"
	}
	sort.Slice(data, func(i, j int) bool {
		ival := reflect.ValueOf(data[i]).FieldByName(sortby).Int()
		jval := reflect.ValueOf(data[j]).FieldByName(sortby).Int()
		return ival > jval
	})

141
	err = templUserRegionType.Execute(w, struct {
Hana Kim's avatar
Hana Kim committed
142
		MaxTotal int64
143
		Data     []regionDesc
Hana Kim's avatar
Hana Kim committed
144
		Name     string
145
	}{
Hana Kim's avatar
Hana Kim committed
146 147 148 149
		MaxTotal: maxTotal,
		Data:     data,
		Name:     filter.name,
	})
150 151 152 153 154 155
	if err != nil {
		http.Error(w, fmt.Sprintf("failed to execute template: %v", err), http.StatusInternalServerError)
		return
	}
}

156 157 158 159 160 161 162 163
// httpUserTask presents the details of the selected tasks.
func httpUserTask(w http.ResponseWriter, r *http.Request) {
	filter, err := newTaskFilter(r)
	if err != nil {
		http.Error(w, err.Error(), http.StatusBadRequest)
		return
	}

164
	res, err := analyzeAnnotations()
165 166 167 168
	if err != nil {
		http.Error(w, err.Error(), http.StatusInternalServerError)
		return
	}
169
	tasks := res.tasks
170 171 172 173 174 175 176 177 178 179 180 181 182 183 184

	type event struct {
		WhenString string
		Elapsed    time.Duration
		Go         uint64
		What       string
		// TODO: include stack trace of creation time
	}
	type entry struct {
		WhenString string
		ID         uint64
		Duration   time.Duration
		Complete   bool
		Events     []event
		Start, End time.Duration // Time since the beginning of the trace
185
		GCTime     time.Duration
186 187 188 189 190 191 192 193 194 195
	}

	base := time.Duration(firstTimestamp()) * time.Nanosecond // trace start

	var data []entry

	for _, task := range tasks {
		if !filter.match(task) {
			continue
		}
196
		// merge events in the task.events and task.regions.Start
197
		rawEvents := append([]*trace.Event{}, task.events...)
198
		for _, s := range task.regions {
199 200 201 202 203 204
			if s.Start != nil {
				rawEvents = append(rawEvents, s.Start)
			}
		}
		sort.SliceStable(rawEvents, func(i, j int) bool { return rawEvents[i].Ts < rawEvents[j].Ts })

205 206
		var events []event
		var last time.Duration
207
		for i, ev := range rawEvents {
208 209 210 211 212 213
			when := time.Duration(ev.Ts)*time.Nanosecond - base
			elapsed := time.Duration(ev.Ts)*time.Nanosecond - last
			if i == 0 {
				elapsed = 0
			}

214 215 216 217 218 219 220 221 222 223
			what := describeEvent(ev)
			if what != "" {
				events = append(events, event{
					WhenString: fmt.Sprintf("%2.9f", when.Seconds()),
					Elapsed:    elapsed,
					What:       what,
					Go:         ev.G,
				})
				last = time.Duration(ev.Ts) * time.Nanosecond
			}
224
		}
225

226 227 228 229 230 231 232 233
		data = append(data, entry{
			WhenString: fmt.Sprintf("%2.9fs", (time.Duration(task.firstTimestamp())*time.Nanosecond - base).Seconds()),
			Duration:   task.duration(),
			ID:         task.id,
			Complete:   task.complete(),
			Events:     events,
			Start:      time.Duration(task.firstTimestamp()) * time.Nanosecond,
			End:        time.Duration(task.lastTimestamp()) * time.Nanosecond,
234
			GCTime:     task.overlappingGCDuration(res.gcEvents),
235 236 237 238 239 240 241 242 243 244 245 246 247 248 249 250 251 252 253 254 255
		})
	}
	sort.Slice(data, func(i, j int) bool {
		return data[i].Duration < data[j].Duration
	})

	// Emit table.
	err = templUserTaskType.Execute(w, struct {
		Name  string
		Entry []entry
	}{
		Name:  filter.name,
		Entry: data,
	})
	if err != nil {
		log.Printf("failed to execute template: %v", err)
		http.Error(w, fmt.Sprintf("failed to execute template: %v", err), http.StatusInternalServerError)
		return
	}
}

256
type annotationAnalysisResult struct {
257 258 259
	tasks    map[uint64]*taskDesc          // tasks
	regions  map[regionTypeID][]regionDesc // regions
	gcEvents []*trace.Event                // GCStartevents, sorted
260 261
}

262
type regionTypeID struct {
263 264
	Frame trace.Frame // top frame
	Type  string
265 266
}

267 268
// analyzeAnnotations analyzes user annotation events and
// returns the task descriptors keyed by internal task id.
269
func analyzeAnnotations() (annotationAnalysisResult, error) {
270 271
	res, err := parseTrace()
	if err != nil {
272
		return annotationAnalysisResult{}, fmt.Errorf("failed to parse trace: %v", err)
273 274 275 276
	}

	events := res.Events
	if len(events) == 0 {
277
		return annotationAnalysisResult{}, fmt.Errorf("empty trace")
278 279 280
	}

	tasks := allTasks{}
281
	regions := map[regionTypeID][]regionDesc{}
282
	var gcEvents []*trace.Event
283 284 285

	for _, ev := range events {
		switch typ := ev.Type; typ {
286
		case trace.EvUserTaskCreate, trace.EvUserTaskEnd, trace.EvUserLog:
287 288 289 290
			taskid := ev.Args[0]
			task := tasks.task(taskid)
			task.addEvent(ev)

291 292 293 294 295 296 297 298 299 300 301 302 303
			// retrieve parent task information
			if typ == trace.EvUserTaskCreate {
				if parentID := ev.Args[1]; parentID != 0 {
					parentTask := tasks.task(parentID)
					task.parent = parentTask
					if parentTask != nil {
						parentTask.children = append(parentTask.children, task)
					}
				}
			}

		case trace.EvGCStart:
			gcEvents = append(gcEvents, ev)
304 305
		}
	}
306
	// combine region info.
307 308
	analyzeGoroutines(events)
	for goid, stats := range gs {
309 310 311
		// gs is a global var defined in goroutines.go as a result
		// of analyzeGoroutines. TODO(hyangah): fix this not to depend
		// on a 'global' var.
312
		for _, s := range stats.Regions {
313 314 315
			if s.TaskID != 0 {
				task := tasks.task(s.TaskID)
				task.goroutines[goid] = struct{}{}
316
				task.regions = append(task.regions, regionDesc{UserRegionDesc: s, G: goid})
317
			}
318 319 320 321
			var frame trace.Frame
			if s.Start != nil {
				frame = *s.Start.Stk[0]
			}
322 323
			id := regionTypeID{Frame: frame, Type: s.Name}
			regions[id] = append(regions[id], regionDesc{UserRegionDesc: s, G: goid})
324 325 326
		}
	}

327
	// sort regions in tasks based on the timestamps.
328
	for _, task := range tasks {
329 330
		sort.SliceStable(task.regions, func(i, j int) bool {
			si, sj := task.regions[i].firstTimestamp(), task.regions[j].firstTimestamp()
331 332 333
			if si != sj {
				return si < sj
			}
334
			return task.regions[i].lastTimestamp() < task.regions[i].lastTimestamp()
335 336
		})
	}
337
	return annotationAnalysisResult{tasks: tasks, regions: regions, gcEvents: gcEvents}, nil
338 339 340 341
}

// taskDesc represents a task.
type taskDesc struct {
342 343 344
	name       string              // user-provided task name
	id         uint64              // internal task id
	events     []*trace.Event      // sorted based on timestamp.
345
	regions    []regionDesc        // associated regions, sorted based on the start timestamp and then the last timestamp.
346
	goroutines map[uint64]struct{} // involved goroutines
347 348 349

	create *trace.Event // Task create event
	end    *trace.Event // Task end event
350 351 352 353 354 355 356 357

	parent   *taskDesc
	children []*taskDesc
}

func newTaskDesc(id uint64) *taskDesc {
	return &taskDesc{
		id:         id,
358
		goroutines: make(map[uint64]struct{}),
359
	}
360 361 362 363 364 365 366 367 368 369
}

func (task *taskDesc) String() string {
	if task == nil {
		return "task <nil>"
	}
	wb := new(bytes.Buffer)
	fmt.Fprintf(wb, "task %d:\t%s\n", task.id, task.name)
	fmt.Fprintf(wb, "\tstart: %v end: %v complete: %t\n", task.firstTimestamp(), task.lastTimestamp(), task.complete())
	fmt.Fprintf(wb, "\t%d goroutines\n", len(task.goroutines))
370 371
	fmt.Fprintf(wb, "\t%d regions:\n", len(task.regions))
	for _, s := range task.regions {
372
		fmt.Fprintf(wb, "\t\t%s(goid=%d)\n", s.Name, s.G)
373
	}
374 375 376 377 378 379 380 381
	if task.parent != nil {
		fmt.Fprintf(wb, "\tparent: %s\n", task.parent.name)
	}
	fmt.Fprintf(wb, "\t%d children:\n", len(task.children))
	for _, c := range task.children {
		fmt.Fprintf(wb, "\t\t%s\n", c.name)
	}

382 383 384
	return wb.String()
}

385 386 387 388
// regionDesc represents a region.
type regionDesc struct {
	*trace.UserRegionDesc
	G uint64 // id of goroutine where the region was defined
389 390 391 392 393 394 395 396 397 398 399 400 401 402 403 404
}

type allTasks map[uint64]*taskDesc

func (tasks allTasks) task(taskID uint64) *taskDesc {
	if taskID == 0 {
		return nil // notask
	}

	t, ok := tasks[taskID]
	if ok {
		return t
	}

	t = &taskDesc{
		id:         taskID,
405
		goroutines: make(map[uint64]struct{}),
406 407 408 409 410 411 412 413 414 415
	}
	tasks[taskID] = t
	return t
}

func (task *taskDesc) addEvent(ev *trace.Event) {
	if task == nil {
		return
	}

416 417
	task.events = append(task.events, ev)
	task.goroutines[ev.G] = struct{}{}
418 419 420 421 422 423 424 425 426 427 428 429 430 431 432 433 434 435 436

	switch typ := ev.Type; typ {
	case trace.EvUserTaskCreate:
		task.name = ev.SArgs[0]
		task.create = ev
	case trace.EvUserTaskEnd:
		task.end = ev
	}
}

// complete is true only if both start and end events of this task
// are present in the trace.
func (task *taskDesc) complete() bool {
	if task == nil {
		return false
	}
	return task.create != nil && task.end != nil
}

437 438 439 440 441 442 443 444 445 446 447 448 449 450 451
// descendents returns all the task nodes in the subtree rooted from this task.
func (task *taskDesc) decendents() []*taskDesc {
	if task == nil {
		return nil
	}
	res := []*taskDesc{task}
	for i := 0; len(res[i:]) > 0; i++ {
		t := res[i]
		for _, c := range t.children {
			res = append(res, c)
		}
	}
	return res
}

452 453 454 455 456 457 458 459 460 461 462 463 464 465 466 467 468 469 470 471 472 473 474 475
// firstTimestamp returns the first timestamp of this task found in
// this trace. If the trace does not contain the task creation event,
// the first timestamp of the trace will be returned.
func (task *taskDesc) firstTimestamp() int64 {
	if task != nil && task.create != nil {
		return task.create.Ts
	}
	return firstTimestamp()
}

// lastTimestamp returns the last timestamp of this task in this
// trace. If the trace does not contain the task end event, the last
// timestamp of the trace will be returned.
func (task *taskDesc) lastTimestamp() int64 {
	if task != nil && task.end != nil {
		return task.end.Ts
	}
	return lastTimestamp()
}

func (task *taskDesc) duration() time.Duration {
	return time.Duration(task.lastTimestamp()-task.firstTimestamp()) * time.Nanosecond
}

476 477
func (region *regionDesc) duration() time.Duration {
	return time.Duration(region.lastTimestamp()-region.firstTimestamp()) * time.Nanosecond
478 479
}

480 481 482 483 484 485 486 487 488 489 490 491 492 493 494
// overlappingGCDuration returns the sum of GC period overlapping with the task's lifetime.
func (task *taskDesc) overlappingGCDuration(evs []*trace.Event) (overlapping time.Duration) {
	for _, ev := range evs {
		// make sure we only consider the global GC events.
		if typ := ev.Type; typ != trace.EvGCStart && typ != trace.EvGCSTWStart {
			continue
		}

		if o, overlapped := task.overlappingDuration(ev); overlapped {
			overlapping += o
		}
	}
	return overlapping
}

495
// overlappingInstant returns true if the instantaneous event, ev, occurred during
496
// any of the task's region if ev is a goroutine-local event, or overlaps with the
497 498 499 500 501 502 503 504 505 506 507 508 509 510 511 512
// task's lifetime if ev is a global event.
func (task *taskDesc) overlappingInstant(ev *trace.Event) bool {
	if isUserAnnotationEvent(ev) && task.id != ev.Args[0] {
		return false // not this task's user event.
	}

	ts := ev.Ts
	taskStart := task.firstTimestamp()
	taskEnd := task.lastTimestamp()
	if ts < taskStart || taskEnd < ts {
		return false
	}
	if ev.P == trace.GCP {
		return true
	}

513
	// Goroutine local event. Check whether there are regions overlapping with the event.
514
	goid := ev.G
515 516
	for _, region := range task.regions {
		if region.G != goid {
517 518
			continue
		}
519
		if region.firstTimestamp() <= ts && ts <= region.lastTimestamp() {
520 521 522 523 524 525
			return true
		}
	}
	return false
}

526
// overlappingDuration returns whether the durational event, ev, overlaps with
527
// any of the task's region if ev is a goroutine-local event, or overlaps with
528 529 530 531 532 533 534 535 536 537 538 539 540 541
// the task's lifetime if ev is a global event. It returns the overlapping time
// as well.
func (task *taskDesc) overlappingDuration(ev *trace.Event) (time.Duration, bool) {
	start := ev.Ts
	end := lastTimestamp()
	if ev.Link != nil {
		end = ev.Link.Ts
	}

	if start > end {
		return 0, false
	}

	goid := ev.G
542 543 544 545
	goid2 := ev.G
	if ev.Link != nil {
		goid2 = ev.Link.G
	}
546

547 548
	// This event is a global GC event
	if ev.P == trace.GCP {
549 550 551 552 553 554
		taskStart := task.firstTimestamp()
		taskEnd := task.lastTimestamp()
		o := overlappingDuration(taskStart, taskEnd, start, end)
		return o, o > 0
	}

555
	// Goroutine local event. Check whether there are regions overlapping with the event.
556
	var overlapping time.Duration
557 558 559
	var lastRegionEnd int64 // the end of previous overlapping region
	for _, region := range task.regions {
		if region.G != goid && region.G != goid2 {
560 561
			continue
		}
562 563
		regionStart, regionEnd := region.firstTimestamp(), region.lastTimestamp()
		if regionStart < lastRegionEnd { // skip nested regions
564 565 566
			continue
		}

567
		if o := overlappingDuration(regionStart, regionEnd, start, end); o > 0 {
568
			// overlapping.
569
			lastRegionEnd = regionEnd
570 571 572 573 574 575 576 577 578 579 580 581 582 583 584
			overlapping += o
		}
	}
	return overlapping, overlapping > 0
}

// overlappingDuration returns the overlapping time duration between
// two time intervals [start1, end1] and [start2, end2] where
// start, end parameters are all int64 representing nanoseconds.
func overlappingDuration(start1, end1, start2, end2 int64) time.Duration {
	// assume start1 <= end1 and start2 <= end2
	if end1 < start2 || end2 < start1 {
		return 0
	}

Hana Kim's avatar
Hana Kim committed
585
	if start1 < start2 { // choose the later one
586 587
		start1 = start2
	}
Hana Kim's avatar
Hana Kim committed
588
	if end1 > end2 { // choose the earlier one
589 590 591 592 593
		end1 = end2
	}
	return time.Duration(end1 - start1)
}

594 595 596 597 598 599 600 601 602 603 604
func (task *taskDesc) lastEvent() *trace.Event {
	if task == nil {
		return nil
	}

	if n := len(task.events); n > 0 {
		return task.events[n-1]
	}
	return nil
}

605 606
// firstTimestamp returns the timestamp of region start event.
// If the region's start event is not present in the trace,
607
// the first timestamp of the trace will be returned.
608 609 610
func (region *regionDesc) firstTimestamp() int64 {
	if region.Start != nil {
		return region.Start.Ts
611
	}
612
	return firstTimestamp()
613 614
}

615 616
// lastTimestamp returns the timestamp of region end event.
// If the region's end event is not present in the trace,
617
// the last timestamp of the trace will be returned.
618 619 620
func (region *regionDesc) lastTimestamp() int64 {
	if region.End != nil {
		return region.End.Ts
621
	}
622
	return lastTimestamp()
623 624 625 626 627 628 629 630 631 632 633 634 635 636 637 638 639 640 641 642 643 644 645 646 647 648 649 650 651 652 653 654 655
}

// RelatedGoroutines returns IDs of goroutines related to the task. A goroutine
// is related to the task if user annotation activities for the task occurred.
// If non-zero depth is provided, this searches all events with BFS and includes
// goroutines unblocked any of related goroutines to the result.
func (task *taskDesc) RelatedGoroutines(events []*trace.Event, depth int) map[uint64]bool {
	start, end := task.firstTimestamp(), task.lastTimestamp()

	gmap := map[uint64]bool{}
	for k := range task.goroutines {
		gmap[k] = true
	}

	for i := 0; i < depth; i++ {
		gmap1 := make(map[uint64]bool)
		for g := range gmap {
			gmap1[g] = true
		}
		for _, ev := range events {
			if ev.Ts < start || ev.Ts > end {
				continue
			}
			if ev.Type == trace.EvGoUnblock && gmap[ev.Args[0]] {
				gmap1[ev.G] = true
			}
			gmap = gmap1
		}
	}
	gmap[0] = true // for GC events (goroutine id = 0)
	return gmap
}

656 657 658 659 660 661 662 663 664 665 666 667 668 669 670 671 672 673 674 675 676 677 678 679 680 681 682 683 684 685 686 687 688 689 690 691 692 693 694 695 696 697 698 699 700 701 702 703 704 705 706 707 708 709 710
type taskFilter struct {
	name string
	cond []func(*taskDesc) bool
}

func (f *taskFilter) match(t *taskDesc) bool {
	if t == nil {
		return false
	}
	for _, c := range f.cond {
		if !c(t) {
			return false
		}
	}
	return true
}

func newTaskFilter(r *http.Request) (*taskFilter, error) {
	if err := r.ParseForm(); err != nil {
		return nil, err
	}

	var name []string
	var conditions []func(*taskDesc) bool

	param := r.Form
	if typ, ok := param["type"]; ok && len(typ) > 0 {
		name = append(name, "type="+typ[0])
		conditions = append(conditions, func(t *taskDesc) bool {
			return t.name == typ[0]
		})
	}
	if complete := r.FormValue("complete"); complete == "1" {
		name = append(name, "complete")
		conditions = append(conditions, func(t *taskDesc) bool {
			return t.complete()
		})
	} else if complete == "0" {
		name = append(name, "incomplete")
		conditions = append(conditions, func(t *taskDesc) bool {
			return !t.complete()
		})
	}
	if lat, err := time.ParseDuration(r.FormValue("latmin")); err == nil {
		name = append(name, fmt.Sprintf("latency >= %s", lat))
		conditions = append(conditions, func(t *taskDesc) bool {
			return t.complete() && t.duration() >= lat
		})
	}
	if lat, err := time.ParseDuration(r.FormValue("latmax")); err == nil {
		name = append(name, fmt.Sprintf("latency <= %s", lat))
		conditions = append(conditions, func(t *taskDesc) bool {
			return t.complete() && t.duration() <= lat
		})
	}
711 712 713 714 715 716
	if text := r.FormValue("logtext"); text != "" {
		name = append(name, fmt.Sprintf("log contains %q", text))
		conditions = append(conditions, func(t *taskDesc) bool {
			return taskMatches(t, text)
		})
	}
717 718 719 720

	return &taskFilter{name: strings.Join(name, ","), cond: conditions}, nil
}

721 722 723
func taskMatches(t *taskDesc, text string) bool {
	for _, ev := range t.events {
		switch ev.Type {
724
		case trace.EvUserTaskCreate, trace.EvUserRegion, trace.EvUserLog:
725 726 727 728 729 730 731 732 733 734
			for _, s := range ev.SArgs {
				if strings.Contains(s, text) {
					return true
				}
			}
		}
	}
	return false
}

735
type regionFilter struct {
736
	name string
737
	cond []func(regionTypeID, regionDesc) bool
738 739
}

740
func (f *regionFilter) match(id regionTypeID, s regionDesc) bool {
741 742 743 744 745 746 747 748
	for _, c := range f.cond {
		if !c(id, s) {
			return false
		}
	}
	return true
}

749
func newRegionFilter(r *http.Request) (*regionFilter, error) {
750 751 752 753 754
	if err := r.ParseForm(); err != nil {
		return nil, err
	}

	var name []string
755
	var conditions []func(regionTypeID, regionDesc) bool
756 757 758 759

	param := r.Form
	if typ, ok := param["type"]; ok && len(typ) > 0 {
		name = append(name, "type="+typ[0])
760
		conditions = append(conditions, func(id regionTypeID, s regionDesc) bool {
761 762 763 764 765
			return id.Type == typ[0]
		})
	}
	if pc, err := strconv.ParseUint(r.FormValue("pc"), 16, 64); err == nil {
		name = append(name, fmt.Sprintf("pc=%x", pc))
766
		conditions = append(conditions, func(id regionTypeID, s regionDesc) bool {
767 768 769 770 771 772
			return id.Frame.PC == pc
		})
	}

	if lat, err := time.ParseDuration(r.FormValue("latmin")); err == nil {
		name = append(name, fmt.Sprintf("latency >= %s", lat))
773
		conditions = append(conditions, func(_ regionTypeID, s regionDesc) bool {
774 775 776 777 778
			return s.duration() >= lat
		})
	}
	if lat, err := time.ParseDuration(r.FormValue("latmax")); err == nil {
		name = append(name, fmt.Sprintf("latency <= %s", lat))
779
		conditions = append(conditions, func(_ regionTypeID, s regionDesc) bool {
780 781 782 783
			return s.duration() <= lat
		})
	}

784
	return &regionFilter{name: strings.Join(name, ","), cond: conditions}, nil
785 786
}

787 788 789 790 791 792 793 794 795 796 797 798 799 800 801 802 803 804 805 806 807 808 809 810 811 812 813 814 815 816 817 818 819 820 821 822 823 824 825 826 827 828 829 830 831 832 833 834 835 836 837 838 839 840 841 842 843 844 845 846 847 848 849 850 851 852 853 854 855 856 857 858 859 860 861 862 863 864 865 866 867 868 869 870 871 872 873 874 875 876 877 878 879 880 881 882 883 884 885 886 887 888 889 890 891 892 893 894 895
type durationHistogram struct {
	Count                int
	Buckets              []int
	MinBucket, MaxBucket int
}

// Five buckets for every power of 10.
var logDiv = math.Log(math.Pow(10, 1.0/5))

func (h *durationHistogram) add(d time.Duration) {
	var bucket int
	if d > 0 {
		bucket = int(math.Log(float64(d)) / logDiv)
	}
	if len(h.Buckets) <= bucket {
		h.Buckets = append(h.Buckets, make([]int, bucket-len(h.Buckets)+1)...)
		h.Buckets = h.Buckets[:cap(h.Buckets)]
	}
	h.Buckets[bucket]++
	if bucket < h.MinBucket || h.MaxBucket == 0 {
		h.MinBucket = bucket
	}
	if bucket > h.MaxBucket {
		h.MaxBucket = bucket
	}
	h.Count++
}

func (h *durationHistogram) BucketMin(bucket int) time.Duration {
	return time.Duration(math.Exp(float64(bucket) * logDiv))
}

func niceDuration(d time.Duration) string {
	var rnd time.Duration
	var unit string
	switch {
	case d < 10*time.Microsecond:
		rnd, unit = time.Nanosecond, "ns"
	case d < 10*time.Millisecond:
		rnd, unit = time.Microsecond, "µs"
	case d < 10*time.Second:
		rnd, unit = time.Millisecond, "ms"
	default:
		rnd, unit = time.Second, "s "
	}
	return fmt.Sprintf("%d%s", d/rnd, unit)
}

func (h *durationHistogram) ToHTML(urlmaker func(min, max time.Duration) string) template.HTML {
	if h == nil || h.Count == 0 {
		return template.HTML("")
	}

	const barWidth = 400

	maxCount := 0
	for _, count := range h.Buckets {
		if count > maxCount {
			maxCount = count
		}
	}

	w := new(bytes.Buffer)
	fmt.Fprintf(w, `<table>`)
	for i := h.MinBucket; i <= h.MaxBucket; i++ {
		// Tick label.
		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)))
		// Bucket bar.
		width := h.Buckets[i] * barWidth / maxCount
		fmt.Fprintf(w, `<td><div style="width:%dpx;background:blue;top:.6em;position:relative">&nbsp;</div></td>`, width)
		// Bucket count.
		fmt.Fprintf(w, `<td align="right"><div style="top:.6em;position:relative">%d</div></td>`, h.Buckets[i])
		fmt.Fprintf(w, "</tr>\n")

	}
	// Final tick label.
	fmt.Fprintf(w, `<tr><td align="right">%s</td></tr>`, niceDuration(h.BucketMin(h.MaxBucket+1)))
	fmt.Fprintf(w, `</table>`)
	return template.HTML(w.String())
}

func (h *durationHistogram) String() string {
	const barWidth = 40

	labels := []string{}
	maxLabel := 0
	maxCount := 0
	for i := h.MinBucket; i <= h.MaxBucket; i++ {
		// TODO: This formatting is pretty awful.
		label := fmt.Sprintf("[%-12s%-11s)", h.BucketMin(i).String()+",", h.BucketMin(i+1))
		labels = append(labels, label)
		if len(label) > maxLabel {
			maxLabel = len(label)
		}
		count := h.Buckets[i]
		if count > maxCount {
			maxCount = count
		}
	}

	w := new(bytes.Buffer)
	for i := h.MinBucket; i <= h.MaxBucket; i++ {
		count := h.Buckets[i]
		bar := count * barWidth / maxCount
		fmt.Fprintf(w, "%*s %-*s %d\n", maxLabel, labels[i-h.MinBucket], barWidth, strings.Repeat("█", bar), count)
	}
	return w.String()
}

896 897
type regionStats struct {
	regionTypeID
898 899 900
	Histogram durationHistogram
}

901
func (s *regionStats) UserRegionURL() func(min, max time.Duration) string {
902
	return func(min, max time.Duration) string {
903
		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))
904 905 906
	}
}

907 908
func (s *regionStats) add(region regionDesc) {
	s.Histogram.add(region.duration())
909 910
}

911
var templUserRegionTypes = template.Must(template.New("").Parse(`
912 913 914 915 916 917 918 919 920 921 922
<html>
<style type="text/css">
.histoTime {
   width: 20%;
   white-space:nowrap;
}

</style>
<body>
<table border="1" sortable="1">
<tr>
923
<th>Region type</th>
924 925 926 927 928 929
<th>Count</th>
<th>Duration distribution (complete tasks)</th>
</tr>
{{range $}}
  <tr>
    <td>{{.Type}}<br>{{.Frame.Fn}}<br>{{.Frame.File}}:{{.Frame.Line}}</td>
930 931
    <td><a href="/userregion?type={{.Type}}&pc={{.Frame.PC}}">{{.Histogram.Count}}</a></td>
    <td>{{.Histogram.ToHTML (.UserRegionURL)}}</td>
932 933 934 935 936 937 938
  </tr>
{{end}}
</table>
</body>
</html>
`))

939 940 941 942 943 944 945 946 947 948 949 950 951 952 953 954 955 956 957 958 959 960 961 962 963 964 965 966 967
type taskStats struct {
	Type      string
	Count     int               // Complete + incomplete tasks
	Histogram durationHistogram // Complete tasks only
}

func (s *taskStats) UserTaskURL(complete bool) func(min, max time.Duration) string {
	return func(min, max time.Duration) string {
		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))
	}
}

func (s *taskStats) add(task *taskDesc) {
	s.Count++
	if task.complete() {
		s.Histogram.add(task.duration())
	}
}

var templUserTaskTypes = template.Must(template.New("").Parse(`
<html>
<style type="text/css">
.histoTime {
   width: 20%;
   white-space:nowrap;
}

</style>
<body>
968
Search log text: <form action="/usertask"><input name="logtext" type="text"><input type="submit"></form><br>
969 970 971 972 973 974 975 976 977 978 979 980 981 982 983 984 985 986 987 988 989 990 991 992 993 994 995 996 997 998 999 1000 1001 1002 1003 1004 1005 1006 1007 1008 1009 1010 1011 1012 1013 1014 1015 1016 1017 1018 1019 1020 1021 1022 1023 1024 1025 1026 1027 1028 1029 1030 1031 1032 1033 1034
<table border="1" sortable="1">
<tr>
<th>Task type</th>
<th>Count</th>
<th>Duration distribution (complete tasks)</th>
</tr>
{{range $}}
  <tr>
    <td>{{.Type}}</td>
    <td><a href="/usertask?type={{.Type}}">{{.Count}}</a></td>
    <td>{{.Histogram.ToHTML (.UserTaskURL true)}}</td>
  </tr>
{{end}}
</table>
</body>
</html>
`))

var templUserTaskType = template.Must(template.New("userTask").Funcs(template.FuncMap{
	"elapsed":       elapsed,
	"asMillisecond": asMillisecond,
	"trimSpace":     strings.TrimSpace,
}).Parse(`
<html>
<head> <title>User Task: {{.Name}} </title> </head>
        <style type="text/css">
                body {
                        font-family: sans-serif;
                }
                table#req-status td.family {
                        padding-right: 2em;
                }
                table#req-status td.active {
                        padding-right: 1em;
                }
                table#req-status td.empty {
                        color: #aaa;
                }
                table#reqs {
                        margin-top: 1em;
                }
                table#reqs tr.first {
                        font-weight: bold;
                }
                table#reqs td {
                        font-family: monospace;
                }
                table#reqs td.when {
                        text-align: right;
                        white-space: nowrap;
                }
                table#reqs td.elapsed {
                        padding: 0 0.5em;
                        text-align: right;
                        white-space: pre;
                        width: 10em;
                }
                address {
                        font-size: smaller;
                        margin-top: 5em;
                }
        </style>
<body>

<h2>User Task: {{.Name}}</h2>

1035 1036 1037 1038
Search log text: <form onsubmit="window.location.search+='&logtext='+window.logtextinput.value; return false">
<input name="logtext" id="logtextinput" type="text"><input type="submit">
</form><br>

1039 1040 1041 1042 1043 1044 1045 1046 1047 1048 1049 1050 1051 1052 1053 1054 1055
<table id="reqs">
<tr><th>When</th><th>Elapsed</th><th>Goroutine ID</th><th>Events</th></tr>
     {{range $el := $.Entry}}
        <tr class="first">
                <td class="when">{{$el.WhenString}}</td>
                <td class="elapsed">{{$el.Duration}}</td>
		<td></td>
                <td><a href="/trace?taskid={{$el.ID}}#{{asMillisecond $el.Start}}:{{asMillisecond $el.End}}">Task {{$el.ID}}</a> ({{if .Complete}}complete{{else}}incomplete{{end}})</td>
        </tr>
        {{range $el.Events}}
        <tr>
                <td class="when">{{.WhenString}}</td>
                <td class="elapsed">{{elapsed .Elapsed}}</td>
		<td class="goid">{{.Go}}</td>
                <td>{{.What}}</td>
        </tr>
        {{end}}
1056 1057 1058 1059 1060
	<tr>
		<td></td>
		<td></td>
		<td></td>
		<td>GC:{{$el.GCTime}}</td>
1061 1062 1063 1064 1065 1066 1067 1068 1069 1070 1071 1072 1073 1074 1075 1076 1077 1078 1079 1080 1081 1082 1083 1084 1085 1086 1087 1088 1089 1090 1091
    {{end}}
</body>
</html>
`))

func elapsed(d time.Duration) string {
	b := []byte(fmt.Sprintf("%.9f", d.Seconds()))

	// For subsecond durations, blank all zeros before decimal point,
	// and all zeros between the decimal point and the first non-zero digit.
	if d < time.Second {
		dot := bytes.IndexByte(b, '.')
		for i := 0; i < dot; i++ {
			b[i] = ' '
		}
		for i := dot + 1; i < len(b); i++ {
			if b[i] == '0' {
				b[i] = ' '
			} else {
				break
			}
		}
	}

	return string(b)
}

func asMillisecond(d time.Duration) float64 {
	return float64(d.Nanoseconds()) / 1e6
}

1092 1093 1094 1095 1096 1097 1098 1099 1100 1101 1102
func formatUserLog(ev *trace.Event) string {
	k, v := ev.SArgs[0], ev.SArgs[1]
	if k == "" {
		return v
	}
	if v == "" {
		return k
	}
	return fmt.Sprintf("%v=%v", k, v)
}

1103 1104 1105
func describeEvent(ev *trace.Event) string {
	switch ev.Type {
	case trace.EvGoCreate:
1106 1107
		goid := ev.Args[0]
		return fmt.Sprintf("new goroutine %d: %s", goid, gs[goid].Name)
1108 1109 1110
	case trace.EvGoEnd, trace.EvGoStop:
		return "goroutine stopped"
	case trace.EvUserLog:
1111
		return formatUserLog(ev)
1112
	case trace.EvUserRegion:
1113 1114 1115 1116 1117
		if ev.Args[1] == 0 {
			duration := "unknown"
			if ev.Link != nil {
				duration = (time.Duration(ev.Link.Ts-ev.Ts) * time.Nanosecond).String()
			}
1118
			return fmt.Sprintf("region %s started (duration: %v)", ev.SArgs[0], duration)
1119
		}
1120
		return fmt.Sprintf("region %s ended", ev.SArgs[0])
1121 1122 1123 1124 1125 1126 1127 1128
	case trace.EvUserTaskCreate:
		return fmt.Sprintf("task %v (id %d, parent %d) created", ev.SArgs[0], ev.Args[0], ev.Args[1])
		// TODO: add child task creation events into the parent task events
	case trace.EvUserTaskEnd:
		return "task end"
	}
	return ""
}
1129 1130 1131

func isUserAnnotationEvent(ev *trace.Event) bool {
	switch ev.Type {
1132
	case trace.EvUserLog, trace.EvUserRegion, trace.EvUserTaskCreate, trace.EvUserTaskEnd:
1133 1134 1135 1136
		return true
	}
	return false
}
1137

1138
var templUserRegionType = template.Must(template.New("").Funcs(template.FuncMap{
Hana Kim's avatar
Hana Kim committed
1139 1140 1141 1142 1143 1144 1145 1146 1147 1148 1149 1150 1151 1152 1153 1154
	"prettyDuration": func(nsec int64) template.HTML {
		d := time.Duration(nsec) * time.Nanosecond
		return template.HTML(niceDuration(d))
	},
	"percent": func(dividened, divisor int64) template.HTML {
		if divisor == 0 {
			return ""
		}
		return template.HTML(fmt.Sprintf("(%.1f%%)", float64(dividened)/float64(divisor)*100))
	},
	"barLen": func(dividened, divisor int64) template.HTML {
		if divisor == 0 {
			return "0"
		}
		return template.HTML(fmt.Sprintf("%.2f%%", float64(dividened)/float64(divisor)*100))
	},
1155
	"unknownTime": func(desc regionDesc) int64 {
Hana Kim's avatar
Hana Kim committed
1156 1157 1158 1159 1160 1161 1162 1163 1164 1165 1166 1167 1168 1169 1170 1171 1172 1173 1174 1175 1176 1177 1178 1179 1180 1181 1182 1183 1184 1185 1186 1187 1188 1189 1190 1191 1192 1193 1194 1195 1196 1197 1198 1199 1200 1201 1202 1203 1204 1205 1206 1207 1208 1209 1210 1211 1212 1213 1214 1215 1216
		sum := desc.ExecTime + desc.IOTime + desc.BlockTime + desc.SyscallTime + desc.SchedWaitTime
		if sum < desc.TotalTime {
			return desc.TotalTime - sum
		}
		return 0
	},
}).Parse(`
<!DOCTYPE html>
<title>Goroutine {{.Name}}</title>
<style>
th {
  background-color: #050505;
  color: #fff;
}
table {
  border-collapse: collapse;
}
.details tr:hover {
  background-color: #f2f2f2;
}
.details td {
  text-align: right;
  border: 1px solid #000;
}
.details td.id {
  text-align: left;
}
.stacked-bar-graph {
  width: 300px;
  height: 10px;
  color: #414042;
  white-space: nowrap;
  font-size: 5px;
}
.stacked-bar-graph span {
  display: inline-block;
  width: 100%;
  height: 100%;
  box-sizing: border-box;
  float: left;
  padding: 0;
}
.unknown-time { background-color: #636363; }
.exec-time { background-color: #d7191c; }
.io-time { background-color: #fdae61; }
.block-time { background-color: #d01c8b; }
.syscall-time { background-color: #7b3294; }
.sched-time { background-color: #2c7bb6; }
</style>

<script>
function reloadTable(key, value) {
  let params = new URLSearchParams(window.location.search);
  params.set(key, value);
  window.location.search = params.toString();
}
</script>

<h2>{{.Name}}</h2>

<table class="details">
1217 1218 1219
<tr>
<th> Goroutine </th>
<th> Task </th>
Hana Kim's avatar
Hana Kim committed
1220 1221 1222 1223 1224 1225 1226 1227 1228
<th onclick="reloadTable('sortby', 'TotalTime')"> Total</th>
<th></th>
<th onclick="reloadTable('sortby', 'ExecTime')" class="exec-time"> Execution</th>
<th onclick="reloadTable('sortby', 'IOTime')" class="io-time"> Network wait</th>
<th onclick="reloadTable('sortby', 'BlockTime')" class="block-time"> Sync block </th>
<th onclick="reloadTable('sortby', 'SyscallTime')" class="syscall-time"> Blocking syscall</th>
<th onclick="reloadTable('sortby', 'SchedWaitTime')" class="sched-time"> Scheduler wait</th>
<th onclick="reloadTable('sortby', 'SweepTime')"> GC sweeping</th>
<th onclick="reloadTable('sortby', 'GCTime')"> GC pause</th>
1229 1230 1231 1232
</tr>
{{range .Data}}
  <tr>
    <td> <a href="/trace?goid={{.G}}">{{.G}}</a> </td>
1233
    <td> {{if .TaskID}}<a href="/trace?taskid={{.TaskID}}">{{.TaskID}}</a>{{end}} </td>
Hana Kim's avatar
Hana Kim committed
1234 1235 1236 1237 1238 1239 1240 1241 1242 1243 1244 1245 1246 1247 1248 1249 1250 1251
    <td> {{prettyDuration .TotalTime}} </td>
    <td>
        <div class="stacked-bar-graph">
          {{if unknownTime .}}<span style="width:{{barLen (unknownTime .) $.MaxTotal}}" class="unknown-time">&nbsp;</span>{{end}}
          {{if .ExecTime}}<span style="width:{{barLen .ExecTime $.MaxTotal}}" class="exec-time">&nbsp;</span>{{end}}
          {{if .IOTime}}<span style="width:{{barLen .IOTime $.MaxTotal}}" class="io-time">&nbsp;</span>{{end}}
          {{if .BlockTime}}<span style="width:{{barLen .BlockTime $.MaxTotal}}" class="block-time">&nbsp;</span>{{end}}
          {{if .SyscallTime}}<span style="width:{{barLen .SyscallTime $.MaxTotal}}" class="syscall-time">&nbsp;</span>{{end}}
          {{if .SchedWaitTime}}<span style="width:{{barLen .SchedWaitTime $.MaxTotal}}" class="sched-time">&nbsp;</span>{{end}}
        </div>
    </td>
    <td> {{prettyDuration .ExecTime}}</td>
    <td> {{prettyDuration .IOTime}}</td>
    <td> {{prettyDuration .BlockTime}}</td>
    <td> {{prettyDuration .SyscallTime}}</td>
    <td> {{prettyDuration .SchedWaitTime}}</td>
    <td> {{prettyDuration .SweepTime}} {{percent .SweepTime .TotalTime}}</td>
    <td> {{prettyDuration .GCTime}} {{percent .GCTime .TotalTime}}</td>
1252 1253 1254 1255
  </tr>
{{end}}
</table>
`))