Source file src/cmd/trace/trace.go
1
2
3
4
5 package main
6
7 import (
8 "encoding/json"
9 "fmt"
10 "internal/trace"
11 "io"
12 "log"
13 "math"
14 "net/http"
15 "path/filepath"
16 "runtime"
17 "runtime/debug"
18 "sort"
19 "strconv"
20 "strings"
21 "time"
22 )
23
24 func init() {
25 http.HandleFunc("/trace", httpTrace)
26 http.HandleFunc("/jsontrace", httpJsonTrace)
27 http.HandleFunc("/trace_viewer_html", httpTraceViewerHTML)
28 }
29
30
31 func httpTrace(w http.ResponseWriter, r *http.Request) {
32 _, err := parseTrace()
33 if err != nil {
34 http.Error(w, err.Error(), http.StatusInternalServerError)
35 return
36 }
37 if err := r.ParseForm(); err != nil {
38 http.Error(w, err.Error(), http.StatusInternalServerError)
39 return
40 }
41 html := strings.ReplaceAll(templTrace, "{{PARAMS}}", r.Form.Encode())
42 w.Write([]byte(html))
43
44 }
45
46
47
48
49
50 var templTrace = `
51 <html>
52 <head>
53 <link href="/trace_viewer_html" rel="import">
54 <style type="text/css">
55 html, body {
56 box-sizing: border-box;
57 overflow: hidden;
58 margin: 0px;
59 padding: 0;
60 width: 100%;
61 height: 100%;
62 }
63 #trace-viewer {
64 width: 100%;
65 height: 100%;
66 }
67 #trace-viewer:focus {
68 outline: none;
69 }
70 </style>
71 <script>
72 'use strict';
73 (function() {
74 var viewer;
75 var url;
76 var model;
77
78 function load() {
79 var req = new XMLHttpRequest();
80 var is_binary = /[.]gz$/.test(url) || /[.]zip$/.test(url);
81 req.overrideMimeType('text/plain; charset=x-user-defined');
82 req.open('GET', url, true);
83 if (is_binary)
84 req.responseType = 'arraybuffer';
85
86 req.onreadystatechange = function(event) {
87 if (req.readyState !== 4)
88 return;
89
90 window.setTimeout(function() {
91 if (req.status === 200)
92 onResult(is_binary ? req.response : req.responseText);
93 else
94 onResultFail(req.status);
95 }, 0);
96 };
97 req.send(null);
98 }
99
100 function onResultFail(err) {
101 var overlay = new tr.ui.b.Overlay();
102 overlay.textContent = err + ': ' + url + ' could not be loaded';
103 overlay.title = 'Failed to fetch data';
104 overlay.visible = true;
105 }
106
107 function onResult(result) {
108 model = new tr.Model();
109 var opts = new tr.importer.ImportOptions();
110 opts.shiftWorldToZero = false;
111 var i = new tr.importer.Import(model, opts);
112 var p = i.importTracesWithProgressDialog([result]);
113 p.then(onModelLoaded, onImportFail);
114 }
115
116 function onModelLoaded() {
117 viewer.model = model;
118 viewer.viewTitle = "trace";
119
120 if (!model || model.bounds.isEmpty)
121 return;
122 var sel = window.location.hash.substr(1);
123 if (sel === '')
124 return;
125 var parts = sel.split(':');
126 var range = new (tr.b.Range || tr.b.math.Range)();
127 range.addValue(parseFloat(parts[0]));
128 range.addValue(parseFloat(parts[1]));
129 viewer.trackView.viewport.interestRange.set(range);
130 }
131
132 function onImportFail(err) {
133 var overlay = new tr.ui.b.Overlay();
134 overlay.textContent = tr.b.normalizeException(err).message;
135 overlay.title = 'Import error';
136 overlay.visible = true;
137 }
138
139 document.addEventListener('DOMContentLoaded', function() {
140 var container = document.createElement('track-view-container');
141 container.id = 'track_view_container';
142
143 viewer = document.createElement('tr-ui-timeline-view');
144 viewer.track_view_container = container;
145 viewer.appendChild(container);
146
147 viewer.id = 'trace-viewer';
148 viewer.globalMode = true;
149 document.body.appendChild(viewer);
150
151 url = '/jsontrace?{{PARAMS}}';
152 load();
153 });
154 }());
155 </script>
156 </head>
157 <body>
158 </body>
159 </html>
160 `
161
162
163
164 func httpTraceViewerHTML(w http.ResponseWriter, r *http.Request) {
165 http.ServeFile(w, r, filepath.Join(runtime.GOROOT(), "misc", "trace", "trace_viewer_full.html"))
166 }
167
168
169 func httpJsonTrace(w http.ResponseWriter, r *http.Request) {
170 defer debug.FreeOSMemory()
171 defer reportMemoryUsage("after httpJsonTrace")
172
173 res, err := parseTrace()
174 if err != nil {
175 log.Printf("failed to parse trace: %v", err)
176 return
177 }
178
179 params := &traceParams{
180 parsed: res,
181 endTime: math.MaxInt64,
182 }
183
184 if goids := r.FormValue("goid"); goids != "" {
185
186 goid, err := strconv.ParseUint(goids, 10, 64)
187 if err != nil {
188 log.Printf("failed to parse goid parameter %q: %v", goids, err)
189 return
190 }
191 analyzeGoroutines(res.Events)
192 g, ok := gs[goid]
193 if !ok {
194 log.Printf("failed to find goroutine %d", goid)
195 return
196 }
197 params.mode = modeGoroutineOriented
198 params.startTime = g.StartTime
199 if g.EndTime != 0 {
200 params.endTime = g.EndTime
201 } else {
202 params.endTime = lastTimestamp()
203 }
204 params.maing = goid
205 params.gs = trace.RelatedGoroutines(res.Events, goid)
206 } else if taskids := r.FormValue("taskid"); taskids != "" {
207 taskid, err := strconv.ParseUint(taskids, 10, 64)
208 if err != nil {
209 log.Printf("failed to parse taskid parameter %q: %v", taskids, err)
210 return
211 }
212 annotRes, _ := analyzeAnnotations()
213 task, ok := annotRes.tasks[taskid]
214 if !ok || len(task.events) == 0 {
215 log.Printf("failed to find task with id %d", taskid)
216 return
217 }
218 goid := task.events[0].G
219 params.mode = modeGoroutineOriented | modeTaskOriented
220 params.startTime = task.firstTimestamp() - 1
221 params.endTime = task.lastTimestamp() + 1
222 params.maing = goid
223 params.tasks = task.descendants()
224 gs := map[uint64]bool{}
225 for _, t := range params.tasks {
226
227 for k, v := range t.RelatedGoroutines(res.Events, 0) {
228 gs[k] = v
229 }
230 }
231 params.gs = gs
232 } else if taskids := r.FormValue("focustask"); taskids != "" {
233 taskid, err := strconv.ParseUint(taskids, 10, 64)
234 if err != nil {
235 log.Printf("failed to parse focustask parameter %q: %v", taskids, err)
236 return
237 }
238 annotRes, _ := analyzeAnnotations()
239 task, ok := annotRes.tasks[taskid]
240 if !ok || len(task.events) == 0 {
241 log.Printf("failed to find task with id %d", taskid)
242 return
243 }
244 params.mode = modeTaskOriented
245 params.startTime = task.firstTimestamp() - 1
246 params.endTime = task.lastTimestamp() + 1
247 params.tasks = task.descendants()
248 }
249
250 start := int64(0)
251 end := int64(math.MaxInt64)
252 if startStr, endStr := r.FormValue("start"), r.FormValue("end"); startStr != "" && endStr != "" {
253
254 start, err = strconv.ParseInt(startStr, 10, 64)
255 if err != nil {
256 log.Printf("failed to parse start parameter %q: %v", startStr, err)
257 return
258 }
259 end, err = strconv.ParseInt(endStr, 10, 64)
260 if err != nil {
261 log.Printf("failed to parse end parameter %q: %v", endStr, err)
262 return
263 }
264 }
265
266 c := viewerDataTraceConsumer(w, start, end)
267 if err := generateTrace(params, c); err != nil {
268 log.Printf("failed to generate trace: %v", err)
269 return
270 }
271 }
272
273 type Range struct {
274 Name string
275 Start int
276 End int
277 StartTime int64
278 EndTime int64
279 }
280
281 func (r Range) URL() string {
282 return fmt.Sprintf("/trace?start=%d&end=%d", r.Start, r.End)
283 }
284
285
286
287
288 func splitTrace(res trace.ParseResult) []Range {
289 params := &traceParams{
290 parsed: res,
291 endTime: math.MaxInt64,
292 }
293 s, c := splittingTraceConsumer(100 << 20)
294 if err := generateTrace(params, c); err != nil {
295 dief("%v\n", err)
296 }
297 return s.Ranges
298 }
299
300 type splitter struct {
301 Ranges []Range
302 }
303
304 func splittingTraceConsumer(max int) (*splitter, traceConsumer) {
305 type eventSz struct {
306 Time float64
307 Sz int
308 }
309
310 var (
311 data = ViewerData{Frames: make(map[string]ViewerFrame)}
312
313 sizes []eventSz
314 cw countingWriter
315 )
316
317 s := new(splitter)
318
319 return s, traceConsumer{
320 consumeTimeUnit: func(unit string) {
321 data.TimeUnit = unit
322 },
323 consumeViewerEvent: func(v *ViewerEvent, required bool) {
324 if required {
325
326
327
328 data.Events = append(data.Events, v)
329 return
330 }
331 enc := json.NewEncoder(&cw)
332 enc.Encode(v)
333 sizes = append(sizes, eventSz{v.Time, cw.size + 1})
334 cw.size = 0
335 },
336 consumeViewerFrame: func(k string, v ViewerFrame) {
337 data.Frames[k] = v
338 },
339 flush: func() {
340
341
342 cw.size = 0
343 enc := json.NewEncoder(&cw)
344 enc.Encode(data)
345 minSize := cw.size
346
347
348
349 sum := minSize
350 start := 0
351 for i, ev := range sizes {
352 if sum+ev.Sz > max {
353 startTime := time.Duration(sizes[start].Time * 1000)
354 endTime := time.Duration(ev.Time * 1000)
355 ranges = append(ranges, Range{
356 Name: fmt.Sprintf("%v-%v", startTime, endTime),
357 Start: start,
358 End: i + 1,
359 StartTime: int64(startTime),
360 EndTime: int64(endTime),
361 })
362 start = i + 1
363 sum = minSize
364 } else {
365 sum += ev.Sz + 1
366 }
367 }
368 if len(ranges) <= 1 {
369 s.Ranges = nil
370 return
371 }
372
373 if end := len(sizes) - 1; start < end {
374 ranges = append(ranges, Range{
375 Name: fmt.Sprintf("%v-%v", time.Duration(sizes[start].Time*1000), time.Duration(sizes[end].Time*1000)),
376 Start: start,
377 End: end,
378 StartTime: int64(sizes[start].Time * 1000),
379 EndTime: int64(sizes[end].Time * 1000),
380 })
381 }
382 s.Ranges = ranges
383 },
384 }
385 }
386
387 type countingWriter struct {
388 size int
389 }
390
391 func (cw *countingWriter) Write(data []byte) (int, error) {
392 cw.size += len(data)
393 return len(data), nil
394 }
395
396 type traceParams struct {
397 parsed trace.ParseResult
398 mode traceviewMode
399 startTime int64
400 endTime int64
401 maing uint64
402 gs map[uint64]bool
403 tasks []*taskDesc
404 }
405
406 type traceviewMode uint
407
408 const (
409 modeGoroutineOriented traceviewMode = 1 << iota
410 modeTaskOriented
411 )
412
413 type traceContext struct {
414 *traceParams
415 consumer traceConsumer
416 frameTree frameNode
417 frameSeq int
418 arrowSeq uint64
419 gcount uint64
420
421 heapStats, prevHeapStats heapStats
422 threadStats, prevThreadStats threadStats
423 gstates, prevGstates [gStateCount]int64
424
425 regionID int
426 }
427
428 type heapStats struct {
429 heapAlloc uint64
430 nextGC uint64
431 }
432
433 type threadStats struct {
434 insyscallRuntime int64
435 insyscall int64
436 prunning int64
437 }
438
439 type frameNode struct {
440 id int
441 children map[uint64]frameNode
442 }
443
444 type gState int
445
446 const (
447 gDead gState = iota
448 gRunnable
449 gRunning
450 gWaiting
451 gWaitingGC
452
453 gStateCount
454 )
455
456 type gInfo struct {
457 state gState
458 name string
459 isSystemG bool
460 start *trace.Event
461 markAssist *trace.Event
462 }
463
464 type ViewerData struct {
465 Events []*ViewerEvent `json:"traceEvents"`
466 Frames map[string]ViewerFrame `json:"stackFrames"`
467 TimeUnit string `json:"displayTimeUnit"`
468
469
470 footer int
471 }
472
473 type ViewerEvent struct {
474 Name string `json:"name,omitempty"`
475 Phase string `json:"ph"`
476 Scope string `json:"s,omitempty"`
477 Time float64 `json:"ts"`
478 Dur float64 `json:"dur,omitempty"`
479 Pid uint64 `json:"pid"`
480 Tid uint64 `json:"tid"`
481 ID uint64 `json:"id,omitempty"`
482 Stack int `json:"sf,omitempty"`
483 EndStack int `json:"esf,omitempty"`
484 Arg interface{} `json:"args,omitempty"`
485 Cname string `json:"cname,omitempty"`
486 Category string `json:"cat,omitempty"`
487 }
488
489 type ViewerFrame struct {
490 Name string `json:"name"`
491 Parent int `json:"parent,omitempty"`
492 }
493
494 type NameArg struct {
495 Name string `json:"name"`
496 }
497
498 type TaskArg struct {
499 ID uint64 `json:"id"`
500 StartG uint64 `json:"start_g,omitempty"`
501 EndG uint64 `json:"end_g,omitempty"`
502 }
503
504 type RegionArg struct {
505 TaskID uint64 `json:"taskid,omitempty"`
506 }
507
508 type SortIndexArg struct {
509 Index int `json:"sort_index"`
510 }
511
512 type traceConsumer struct {
513 consumeTimeUnit func(unit string)
514 consumeViewerEvent func(v *ViewerEvent, required bool)
515 consumeViewerFrame func(key string, f ViewerFrame)
516 flush func()
517 }
518
519 const (
520 procsSection = 0
521 statsSection = 1
522 tasksSection = 2
523 )
524
525
526
527
528
529
530
531
532 func generateTrace(params *traceParams, consumer traceConsumer) error {
533 defer consumer.flush()
534
535 ctx := &traceContext{traceParams: params}
536 ctx.frameTree.children = make(map[uint64]frameNode)
537 ctx.consumer = consumer
538
539 ctx.consumer.consumeTimeUnit("ns")
540 maxProc := 0
541 ginfos := make(map[uint64]*gInfo)
542 stacks := params.parsed.Stacks
543
544 getGInfo := func(g uint64) *gInfo {
545 info, ok := ginfos[g]
546 if !ok {
547 info = &gInfo{}
548 ginfos[g] = info
549 }
550 return info
551 }
552
553
554
555 var setGStateErr error
556 setGState := func(ev *trace.Event, g uint64, oldState, newState gState) {
557 info := getGInfo(g)
558 if oldState == gWaiting && info.state == gWaitingGC {
559
560 oldState = info.state
561 }
562 if info.state != oldState && setGStateErr == nil {
563 setGStateErr = fmt.Errorf("expected G %d to be in state %d, but got state %d", g, oldState, newState)
564 }
565 ctx.gstates[info.state]--
566 ctx.gstates[newState]++
567 info.state = newState
568 }
569
570 for _, ev := range ctx.parsed.Events {
571
572 switch ev.Type {
573 case trace.EvGoStart, trace.EvGoStartLabel:
574 setGState(ev, ev.G, gRunnable, gRunning)
575 info := getGInfo(ev.G)
576 info.start = ev
577 case trace.EvProcStart:
578 ctx.threadStats.prunning++
579 case trace.EvProcStop:
580 ctx.threadStats.prunning--
581 case trace.EvGoCreate:
582 newG := ev.Args[0]
583 info := getGInfo(newG)
584 if info.name != "" {
585 return fmt.Errorf("duplicate go create event for go id=%d detected at offset %d", newG, ev.Off)
586 }
587
588 stk, ok := stacks[ev.Args[1]]
589 if !ok || len(stk) == 0 {
590 return fmt.Errorf("invalid go create event: missing stack information for go id=%d at offset %d", newG, ev.Off)
591 }
592
593 fname := stk[0].Fn
594 info.name = fmt.Sprintf("G%v %s", newG, fname)
595 info.isSystemG = isSystemGoroutine(fname)
596
597 ctx.gcount++
598 setGState(ev, newG, gDead, gRunnable)
599 case trace.EvGoEnd:
600 ctx.gcount--
601 setGState(ev, ev.G, gRunning, gDead)
602 case trace.EvGoUnblock:
603 setGState(ev, ev.Args[0], gWaiting, gRunnable)
604 case trace.EvGoSysExit:
605 setGState(ev, ev.G, gWaiting, gRunnable)
606 if getGInfo(ev.G).isSystemG {
607 ctx.threadStats.insyscallRuntime--
608 } else {
609 ctx.threadStats.insyscall--
610 }
611 case trace.EvGoSysBlock:
612 setGState(ev, ev.G, gRunning, gWaiting)
613 if getGInfo(ev.G).isSystemG {
614 ctx.threadStats.insyscallRuntime++
615 } else {
616 ctx.threadStats.insyscall++
617 }
618 case trace.EvGoSched, trace.EvGoPreempt:
619 setGState(ev, ev.G, gRunning, gRunnable)
620 case trace.EvGoStop,
621 trace.EvGoSleep, trace.EvGoBlock, trace.EvGoBlockSend, trace.EvGoBlockRecv,
622 trace.EvGoBlockSelect, trace.EvGoBlockSync, trace.EvGoBlockCond, trace.EvGoBlockNet:
623 setGState(ev, ev.G, gRunning, gWaiting)
624 case trace.EvGoBlockGC:
625 setGState(ev, ev.G, gRunning, gWaitingGC)
626 case trace.EvGCMarkAssistStart:
627 getGInfo(ev.G).markAssist = ev
628 case trace.EvGCMarkAssistDone:
629 getGInfo(ev.G).markAssist = nil
630 case trace.EvGoWaiting:
631 setGState(ev, ev.G, gRunnable, gWaiting)
632 case trace.EvGoInSyscall:
633
634 setGState(ev, ev.G, gRunnable, gWaiting)
635 if getGInfo(ev.G).isSystemG {
636 ctx.threadStats.insyscallRuntime++
637 } else {
638 ctx.threadStats.insyscall++
639 }
640 case trace.EvHeapAlloc:
641 ctx.heapStats.heapAlloc = ev.Args[0]
642 case trace.EvNextGC:
643 ctx.heapStats.nextGC = ev.Args[0]
644 }
645 if setGStateErr != nil {
646 return setGStateErr
647 }
648 if ctx.gstates[gRunnable] < 0 || ctx.gstates[gRunning] < 0 || ctx.threadStats.insyscall < 0 || ctx.threadStats.insyscallRuntime < 0 {
649 return fmt.Errorf("invalid state after processing %v: runnable=%d running=%d insyscall=%d insyscallRuntime=%d", ev, ctx.gstates[gRunnable], ctx.gstates[gRunning], ctx.threadStats.insyscall, ctx.threadStats.insyscallRuntime)
650 }
651
652
653
654 if ctx.gs != nil && ev.P < trace.FakeP && !ctx.gs[ev.G] {
655 continue
656 }
657 if !withinTimeRange(ev, ctx.startTime, ctx.endTime) {
658 continue
659 }
660
661 if ev.P < trace.FakeP && ev.P > maxProc {
662 maxProc = ev.P
663 }
664
665
666 switch ev.Type {
667 case trace.EvProcStart:
668 if ctx.mode&modeGoroutineOriented != 0 {
669 continue
670 }
671 ctx.emitInstant(ev, "proc start", "")
672 case trace.EvProcStop:
673 if ctx.mode&modeGoroutineOriented != 0 {
674 continue
675 }
676 ctx.emitInstant(ev, "proc stop", "")
677 case trace.EvGCStart:
678 ctx.emitSlice(ev, "GC")
679 case trace.EvGCDone:
680 case trace.EvGCSTWStart:
681 if ctx.mode&modeGoroutineOriented != 0 {
682 continue
683 }
684 ctx.emitSlice(ev, fmt.Sprintf("STW (%s)", ev.SArgs[0]))
685 case trace.EvGCSTWDone:
686 case trace.EvGCMarkAssistStart:
687
688
689
690 markFinish := ev.Link
691 goFinish := getGInfo(ev.G).start.Link
692 fakeMarkStart := *ev
693 text := "MARK ASSIST"
694 if markFinish == nil || markFinish.Ts > goFinish.Ts {
695 fakeMarkStart.Link = goFinish
696 text = "MARK ASSIST (unfinished)"
697 }
698 ctx.emitSlice(&fakeMarkStart, text)
699 case trace.EvGCSweepStart:
700 slice := ctx.makeSlice(ev, "SWEEP")
701 if done := ev.Link; done != nil && done.Args[0] != 0 {
702 slice.Arg = struct {
703 Swept uint64 `json:"Swept bytes"`
704 Reclaimed uint64 `json:"Reclaimed bytes"`
705 }{done.Args[0], done.Args[1]}
706 }
707 ctx.emit(slice)
708 case trace.EvGoStart, trace.EvGoStartLabel:
709 info := getGInfo(ev.G)
710 if ev.Type == trace.EvGoStartLabel {
711 ctx.emitSlice(ev, ev.SArgs[0])
712 } else {
713 ctx.emitSlice(ev, info.name)
714 }
715 if info.markAssist != nil {
716
717
718 markFinish := info.markAssist.Link
719 goFinish := ev.Link
720 fakeMarkStart := *ev
721 text := "MARK ASSIST (resumed, unfinished)"
722 if markFinish != nil && markFinish.Ts < goFinish.Ts {
723 fakeMarkStart.Link = markFinish
724 text = "MARK ASSIST (resumed)"
725 }
726 ctx.emitSlice(&fakeMarkStart, text)
727 }
728 case trace.EvGoCreate:
729 ctx.emitArrow(ev, "go")
730 case trace.EvGoUnblock:
731 ctx.emitArrow(ev, "unblock")
732 case trace.EvGoSysCall:
733 ctx.emitInstant(ev, "syscall", "")
734 case trace.EvGoSysExit:
735 ctx.emitArrow(ev, "sysexit")
736 case trace.EvUserLog:
737 ctx.emitInstant(ev, formatUserLog(ev), "user event")
738 case trace.EvUserTaskCreate:
739 ctx.emitInstant(ev, "task start", "user event")
740 case trace.EvUserTaskEnd:
741 ctx.emitInstant(ev, "task end", "user event")
742 }
743
744 ctx.emitThreadCounters(ev)
745 ctx.emitHeapCounters(ev)
746 ctx.emitGoroutineCounters(ev)
747 }
748
749 ctx.emitSectionFooter(statsSection, "STATS", 0)
750
751 if ctx.mode&modeTaskOriented != 0 {
752 ctx.emitSectionFooter(tasksSection, "TASKS", 1)
753 }
754
755 if ctx.mode&modeGoroutineOriented != 0 {
756 ctx.emitSectionFooter(procsSection, "G", 2)
757 } else {
758 ctx.emitSectionFooter(procsSection, "PROCS", 2)
759 }
760
761 ctx.emitFooter(&ViewerEvent{Name: "thread_name", Phase: "M", Pid: procsSection, Tid: trace.GCP, Arg: &NameArg{"GC"}})
762 ctx.emitFooter(&ViewerEvent{Name: "thread_sort_index", Phase: "M", Pid: procsSection, Tid: trace.GCP, Arg: &SortIndexArg{-6}})
763
764 ctx.emitFooter(&ViewerEvent{Name: "thread_name", Phase: "M", Pid: procsSection, Tid: trace.NetpollP, Arg: &NameArg{"Network"}})
765 ctx.emitFooter(&ViewerEvent{Name: "thread_sort_index", Phase: "M", Pid: procsSection, Tid: trace.NetpollP, Arg: &SortIndexArg{-5}})
766
767 ctx.emitFooter(&ViewerEvent{Name: "thread_name", Phase: "M", Pid: procsSection, Tid: trace.TimerP, Arg: &NameArg{"Timers"}})
768 ctx.emitFooter(&ViewerEvent{Name: "thread_sort_index", Phase: "M", Pid: procsSection, Tid: trace.TimerP, Arg: &SortIndexArg{-4}})
769
770 ctx.emitFooter(&ViewerEvent{Name: "thread_name", Phase: "M", Pid: procsSection, Tid: trace.SyscallP, Arg: &NameArg{"Syscalls"}})
771 ctx.emitFooter(&ViewerEvent{Name: "thread_sort_index", Phase: "M", Pid: procsSection, Tid: trace.SyscallP, Arg: &SortIndexArg{-3}})
772
773
774 if ctx.mode&modeGoroutineOriented == 0 {
775 for i := 0; i <= maxProc; i++ {
776 ctx.emitFooter(&ViewerEvent{Name: "thread_name", Phase: "M", Pid: procsSection, Tid: uint64(i), Arg: &NameArg{fmt.Sprintf("Proc %v", i)}})
777 ctx.emitFooter(&ViewerEvent{Name: "thread_sort_index", Phase: "M", Pid: procsSection, Tid: uint64(i), Arg: &SortIndexArg{i}})
778 }
779 }
780
781
782 if ctx.mode&modeTaskOriented != 0 {
783
784 sortedTask := make([]*taskDesc, 0, len(ctx.tasks))
785 for _, task := range ctx.tasks {
786 sortedTask = append(sortedTask, task)
787 }
788 sort.SliceStable(sortedTask, func(i, j int) bool {
789 ti, tj := sortedTask[i], sortedTask[j]
790 if ti.firstTimestamp() == tj.firstTimestamp() {
791 return ti.lastTimestamp() < tj.lastTimestamp()
792 }
793 return ti.firstTimestamp() < tj.firstTimestamp()
794 })
795
796 for i, task := range sortedTask {
797 ctx.emitTask(task, i)
798
799
800
801 if ctx.mode&modeGoroutineOriented != 0 {
802 for _, s := range task.regions {
803 ctx.emitRegion(s)
804 }
805 }
806 }
807 }
808
809
810 if ctx.mode&modeGoroutineOriented != 0 {
811 for k, v := range ginfos {
812 if !ctx.gs[k] {
813 continue
814 }
815 ctx.emitFooter(&ViewerEvent{Name: "thread_name", Phase: "M", Pid: procsSection, Tid: k, Arg: &NameArg{v.name}})
816 }
817
818 ctx.emitFooter(&ViewerEvent{Name: "thread_sort_index", Phase: "M", Pid: procsSection, Tid: ctx.maing, Arg: &SortIndexArg{-2}})
819
820 ctx.emitFooter(&ViewerEvent{Name: "thread_sort_index", Phase: "M", Pid: procsSection, Tid: 0, Arg: &SortIndexArg{-1}})
821 }
822
823 return nil
824 }
825
826 func (ctx *traceContext) emit(e *ViewerEvent) {
827 ctx.consumer.consumeViewerEvent(e, false)
828 }
829
830 func (ctx *traceContext) emitFooter(e *ViewerEvent) {
831 ctx.consumer.consumeViewerEvent(e, true)
832 }
833 func (ctx *traceContext) emitSectionFooter(sectionID uint64, name string, priority int) {
834 ctx.emitFooter(&ViewerEvent{Name: "process_name", Phase: "M", Pid: sectionID, Arg: &NameArg{name}})
835 ctx.emitFooter(&ViewerEvent{Name: "process_sort_index", Phase: "M", Pid: sectionID, Arg: &SortIndexArg{priority}})
836 }
837
838 func (ctx *traceContext) time(ev *trace.Event) float64 {
839
840 return float64(ev.Ts) / 1000
841 }
842
843 func withinTimeRange(ev *trace.Event, s, e int64) bool {
844 if evEnd := ev.Link; evEnd != nil {
845 return ev.Ts <= e && evEnd.Ts >= s
846 }
847 return ev.Ts >= s && ev.Ts <= e
848 }
849
850 func tsWithinRange(ts, s, e int64) bool {
851 return s <= ts && ts <= e
852 }
853
854 func (ctx *traceContext) proc(ev *trace.Event) uint64 {
855 if ctx.mode&modeGoroutineOriented != 0 && ev.P < trace.FakeP {
856 return ev.G
857 } else {
858 return uint64(ev.P)
859 }
860 }
861
862 func (ctx *traceContext) emitSlice(ev *trace.Event, name string) {
863 ctx.emit(ctx.makeSlice(ev, name))
864 }
865
866 func (ctx *traceContext) makeSlice(ev *trace.Event, name string) *ViewerEvent {
867
868
869
870 durationUsec := ctx.time(ev.Link) - ctx.time(ev)
871 if ev.Link.Ts-ev.Ts <= 0 {
872 durationUsec = 0.0001
873 }
874 sl := &ViewerEvent{
875 Name: name,
876 Phase: "X",
877 Time: ctx.time(ev),
878 Dur: durationUsec,
879 Tid: ctx.proc(ev),
880 Stack: ctx.stack(ev.Stk),
881 EndStack: ctx.stack(ev.Link.Stk),
882 }
883
884
885 if ctx.mode&modeTaskOriented != 0 && ev.G != 0 {
886
887 if t := ev.Type; t == trace.EvGoStart || t == trace.EvGoStartLabel {
888 type Arg struct {
889 P int
890 }
891 sl.Arg = &Arg{P: ev.P}
892 }
893
894 overlapping := false
895 for _, task := range ctx.tasks {
896 if _, overlapped := task.overlappingDuration(ev); overlapped {
897 overlapping = true
898 break
899 }
900 }
901 if !overlapping {
902 sl.Cname = colorLightGrey
903 }
904 }
905 return sl
906 }
907
908 func (ctx *traceContext) emitTask(task *taskDesc, sortIndex int) {
909 taskRow := uint64(task.id)
910 taskName := task.name
911 durationUsec := float64(task.lastTimestamp()-task.firstTimestamp()) / 1e3
912
913 ctx.emitFooter(&ViewerEvent{Name: "thread_name", Phase: "M", Pid: tasksSection, Tid: taskRow, Arg: &NameArg{fmt.Sprintf("T%d %s", task.id, taskName)}})
914 ctx.emit(&ViewerEvent{Name: "thread_sort_index", Phase: "M", Pid: tasksSection, Tid: taskRow, Arg: &SortIndexArg{sortIndex}})
915 ts := float64(task.firstTimestamp()) / 1e3
916 sl := &ViewerEvent{
917 Name: taskName,
918 Phase: "X",
919 Time: ts,
920 Dur: durationUsec,
921 Pid: tasksSection,
922 Tid: taskRow,
923 Cname: pickTaskColor(task.id),
924 }
925 targ := TaskArg{ID: task.id}
926 if task.create != nil {
927 sl.Stack = ctx.stack(task.create.Stk)
928 targ.StartG = task.create.G
929 }
930 if task.end != nil {
931 sl.EndStack = ctx.stack(task.end.Stk)
932 targ.EndG = task.end.G
933 }
934 sl.Arg = targ
935 ctx.emit(sl)
936
937 if task.create != nil && task.create.Type == trace.EvUserTaskCreate && task.create.Args[1] != 0 {
938 ctx.arrowSeq++
939 ctx.emit(&ViewerEvent{Name: "newTask", Phase: "s", Tid: task.create.Args[1], ID: ctx.arrowSeq, Time: ts, Pid: tasksSection})
940 ctx.emit(&ViewerEvent{Name: "newTask", Phase: "t", Tid: taskRow, ID: ctx.arrowSeq, Time: ts, Pid: tasksSection})
941 }
942 }
943
944 func (ctx *traceContext) emitRegion(s regionDesc) {
945 if s.Name == "" {
946 return
947 }
948
949 if !tsWithinRange(s.firstTimestamp(), ctx.startTime, ctx.endTime) &&
950 !tsWithinRange(s.lastTimestamp(), ctx.startTime, ctx.endTime) {
951 return
952 }
953
954 ctx.regionID++
955 regionID := ctx.regionID
956
957 id := s.TaskID
958 scopeID := fmt.Sprintf("%x", id)
959 name := s.Name
960
961 sl0 := &ViewerEvent{
962 Category: "Region",
963 Name: name,
964 Phase: "b",
965 Time: float64(s.firstTimestamp()) / 1e3,
966 Tid: s.G,
967 ID: uint64(regionID),
968 Scope: scopeID,
969 Cname: pickTaskColor(s.TaskID),
970 }
971 if s.Start != nil {
972 sl0.Stack = ctx.stack(s.Start.Stk)
973 }
974 ctx.emit(sl0)
975
976 sl1 := &ViewerEvent{
977 Category: "Region",
978 Name: name,
979 Phase: "e",
980 Time: float64(s.lastTimestamp()) / 1e3,
981 Tid: s.G,
982 ID: uint64(regionID),
983 Scope: scopeID,
984 Cname: pickTaskColor(s.TaskID),
985 Arg: RegionArg{TaskID: s.TaskID},
986 }
987 if s.End != nil {
988 sl1.Stack = ctx.stack(s.End.Stk)
989 }
990 ctx.emit(sl1)
991 }
992
993 type heapCountersArg struct {
994 Allocated uint64
995 NextGC uint64
996 }
997
998 func (ctx *traceContext) emitHeapCounters(ev *trace.Event) {
999 if ctx.prevHeapStats == ctx.heapStats {
1000 return
1001 }
1002 diff := uint64(0)
1003 if ctx.heapStats.nextGC > ctx.heapStats.heapAlloc {
1004 diff = ctx.heapStats.nextGC - ctx.heapStats.heapAlloc
1005 }
1006 if tsWithinRange(ev.Ts, ctx.startTime, ctx.endTime) {
1007 ctx.emit(&ViewerEvent{Name: "Heap", Phase: "C", Time: ctx.time(ev), Pid: 1, Arg: &heapCountersArg{ctx.heapStats.heapAlloc, diff}})
1008 }
1009 ctx.prevHeapStats = ctx.heapStats
1010 }
1011
1012 type goroutineCountersArg struct {
1013 Running uint64
1014 Runnable uint64
1015 GCWaiting uint64
1016 }
1017
1018 func (ctx *traceContext) emitGoroutineCounters(ev *trace.Event) {
1019 if ctx.prevGstates == ctx.gstates {
1020 return
1021 }
1022 if tsWithinRange(ev.Ts, ctx.startTime, ctx.endTime) {
1023 ctx.emit(&ViewerEvent{Name: "Goroutines", Phase: "C", Time: ctx.time(ev), Pid: 1, Arg: &goroutineCountersArg{uint64(ctx.gstates[gRunning]), uint64(ctx.gstates[gRunnable]), uint64(ctx.gstates[gWaitingGC])}})
1024 }
1025 ctx.prevGstates = ctx.gstates
1026 }
1027
1028 type threadCountersArg struct {
1029 Running int64
1030 InSyscall int64
1031 }
1032
1033 func (ctx *traceContext) emitThreadCounters(ev *trace.Event) {
1034 if ctx.prevThreadStats == ctx.threadStats {
1035 return
1036 }
1037 if tsWithinRange(ev.Ts, ctx.startTime, ctx.endTime) {
1038 ctx.emit(&ViewerEvent{Name: "Threads", Phase: "C", Time: ctx.time(ev), Pid: 1, Arg: &threadCountersArg{
1039 Running: ctx.threadStats.prunning,
1040 InSyscall: ctx.threadStats.insyscall}})
1041 }
1042 ctx.prevThreadStats = ctx.threadStats
1043 }
1044
1045 func (ctx *traceContext) emitInstant(ev *trace.Event, name, category string) {
1046 if !tsWithinRange(ev.Ts, ctx.startTime, ctx.endTime) {
1047 return
1048 }
1049
1050 cname := ""
1051 if ctx.mode&modeTaskOriented != 0 {
1052 taskID, isUserAnnotation := isUserAnnotationEvent(ev)
1053
1054 show := false
1055 for _, task := range ctx.tasks {
1056 if isUserAnnotation && task.id == taskID || task.overlappingInstant(ev) {
1057 show = true
1058 break
1059 }
1060 }
1061
1062 if !show {
1063 if isUserAnnotation {
1064 return
1065 }
1066 cname = colorLightGrey
1067 }
1068 }
1069 var arg interface{}
1070 if ev.Type == trace.EvProcStart {
1071 type Arg struct {
1072 ThreadID uint64
1073 }
1074 arg = &Arg{ev.Args[0]}
1075 }
1076 ctx.emit(&ViewerEvent{
1077 Name: name,
1078 Category: category,
1079 Phase: "I",
1080 Scope: "t",
1081 Time: ctx.time(ev),
1082 Tid: ctx.proc(ev),
1083 Stack: ctx.stack(ev.Stk),
1084 Cname: cname,
1085 Arg: arg})
1086 }
1087
1088 func (ctx *traceContext) emitArrow(ev *trace.Event, name string) {
1089 if ev.Link == nil {
1090
1091
1092 return
1093 }
1094 if ctx.mode&modeGoroutineOriented != 0 && (!ctx.gs[ev.Link.G] || ev.Link.Ts < ctx.startTime || ev.Link.Ts > ctx.endTime) {
1095 return
1096 }
1097
1098 if ev.P == trace.NetpollP || ev.P == trace.TimerP || ev.P == trace.SyscallP {
1099
1100
1101 ctx.emitInstant(&trace.Event{P: ev.P, Ts: ev.Ts}, "unblock", "")
1102 }
1103
1104 color := ""
1105 if ctx.mode&modeTaskOriented != 0 {
1106 overlapping := false
1107
1108 for _, task := range ctx.tasks {
1109 if _, overlapped := task.overlappingDuration(ev); overlapped {
1110 overlapping = true
1111 break
1112 }
1113 }
1114 if !overlapping {
1115 return
1116 }
1117 }
1118
1119 ctx.arrowSeq++
1120 ctx.emit(&ViewerEvent{Name: name, Phase: "s", Tid: ctx.proc(ev), ID: ctx.arrowSeq, Time: ctx.time(ev), Stack: ctx.stack(ev.Stk), Cname: color})
1121 ctx.emit(&ViewerEvent{Name: name, Phase: "t", Tid: ctx.proc(ev.Link), ID: ctx.arrowSeq, Time: ctx.time(ev.Link), Cname: color})
1122 }
1123
1124 func (ctx *traceContext) stack(stk []*trace.Frame) int {
1125 return ctx.buildBranch(ctx.frameTree, stk)
1126 }
1127
1128
1129 func (ctx *traceContext) buildBranch(parent frameNode, stk []*trace.Frame) int {
1130 if len(stk) == 0 {
1131 return parent.id
1132 }
1133 last := len(stk) - 1
1134 frame := stk[last]
1135 stk = stk[:last]
1136
1137 node, ok := parent.children[frame.PC]
1138 if !ok {
1139 ctx.frameSeq++
1140 node.id = ctx.frameSeq
1141 node.children = make(map[uint64]frameNode)
1142 parent.children[frame.PC] = node
1143 ctx.consumer.consumeViewerFrame(strconv.Itoa(node.id), ViewerFrame{fmt.Sprintf("%v:%v", frame.Fn, frame.Line), parent.id})
1144 }
1145 return ctx.buildBranch(node, stk)
1146 }
1147
1148 func isSystemGoroutine(entryFn string) bool {
1149
1150
1151 return entryFn != "runtime.main" && strings.HasPrefix(entryFn, "runtime.")
1152 }
1153
1154
1155 func firstTimestamp() int64 {
1156 res, _ := parseTrace()
1157 if len(res.Events) > 0 {
1158 return res.Events[0].Ts
1159 }
1160 return 0
1161 }
1162
1163
1164 func lastTimestamp() int64 {
1165 res, _ := parseTrace()
1166 if n := len(res.Events); n > 1 {
1167 return res.Events[n-1].Ts
1168 }
1169 return 0
1170 }
1171
1172 type jsonWriter struct {
1173 w io.Writer
1174 enc *json.Encoder
1175 }
1176
1177 func viewerDataTraceConsumer(w io.Writer, start, end int64) traceConsumer {
1178 frames := make(map[string]ViewerFrame)
1179 enc := json.NewEncoder(w)
1180 written := 0
1181 index := int64(-1)
1182
1183 io.WriteString(w, "{")
1184 return traceConsumer{
1185 consumeTimeUnit: func(unit string) {
1186 io.WriteString(w, `"displayTimeUnit":`)
1187 enc.Encode(unit)
1188 io.WriteString(w, ",")
1189 },
1190 consumeViewerEvent: func(v *ViewerEvent, required bool) {
1191 index++
1192 if !required && (index < start || index > end) {
1193
1194 return
1195 }
1196 if written == 0 {
1197 io.WriteString(w, `"traceEvents": [`)
1198 }
1199 if written > 0 {
1200 io.WriteString(w, ",")
1201 }
1202 enc.Encode(v)
1203
1204
1205 written++
1206 },
1207 consumeViewerFrame: func(k string, v ViewerFrame) {
1208 frames[k] = v
1209 },
1210 flush: func() {
1211 io.WriteString(w, `], "stackFrames":`)
1212 enc.Encode(frames)
1213 io.WriteString(w, `}`)
1214 },
1215 }
1216 }
1217
1218
1219
1220
1221 const (
1222 colorLightMauve = "thread_state_uninterruptible"
1223 colorOrange = "thread_state_iowait"
1224 colorSeafoamGreen = "thread_state_running"
1225 colorVistaBlue = "thread_state_runnable"
1226 colorTan = "thread_state_unknown"
1227 colorIrisBlue = "background_memory_dump"
1228 colorMidnightBlue = "light_memory_dump"
1229 colorDeepMagenta = "detailed_memory_dump"
1230 colorBlue = "vsync_highlight_color"
1231 colorGrey = "generic_work"
1232 colorGreen = "good"
1233 colorDarkGoldenrod = "bad"
1234 colorPeach = "terrible"
1235 colorBlack = "black"
1236 colorLightGrey = "grey"
1237 colorWhite = "white"
1238 colorYellow = "yellow"
1239 colorOlive = "olive"
1240 colorCornflowerBlue = "rail_response"
1241 colorSunsetOrange = "rail_animation"
1242 colorTangerine = "rail_idle"
1243 colorShamrockGreen = "rail_load"
1244 colorGreenishYellow = "startup"
1245 colorDarkGrey = "heap_dump_stack_frame"
1246 colorTawny = "heap_dump_child_node_arrow"
1247 colorLemon = "cq_build_running"
1248 colorLime = "cq_build_passed"
1249 colorPink = "cq_build_failed"
1250 colorSilver = "cq_build_abandoned"
1251 colorManzGreen = "cq_build_attempt_runnig"
1252 colorKellyGreen = "cq_build_attempt_passed"
1253 colorAnotherGrey = "cq_build_attempt_failed"
1254 )
1255
1256 var colorForTask = []string{
1257 colorLightMauve,
1258 colorOrange,
1259 colorSeafoamGreen,
1260 colorVistaBlue,
1261 colorTan,
1262 colorMidnightBlue,
1263 colorIrisBlue,
1264 colorDeepMagenta,
1265 colorGreen,
1266 colorDarkGoldenrod,
1267 colorPeach,
1268 colorOlive,
1269 colorCornflowerBlue,
1270 colorSunsetOrange,
1271 colorTangerine,
1272 colorShamrockGreen,
1273 colorTawny,
1274 colorLemon,
1275 colorLime,
1276 colorPink,
1277 colorSilver,
1278 colorManzGreen,
1279 colorKellyGreen,
1280 }
1281
1282 func pickTaskColor(id uint64) string {
1283 idx := id % uint64(len(colorForTask))
1284 return colorForTask[idx]
1285 }
1286
View as plain text