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