1
2
3
4
5 package trace
6
7 import (
8 "bufio"
9 "bytes"
10 "fmt"
11 "io"
12 "math/rand"
13 "os"
14 "os/exec"
15 "path/filepath"
16 "runtime"
17 "strconv"
18 "strings"
19 _ "unsafe"
20 )
21
22 func goCmd() string {
23 var exeSuffix string
24 if runtime.GOOS == "windows" {
25 exeSuffix = ".exe"
26 }
27 path := filepath.Join(runtime.GOROOT(), "bin", "go"+exeSuffix)
28 if _, err := os.Stat(path); err == nil {
29 return path
30 }
31 return "go"
32 }
33
34
35 type Event struct {
36 Off int
37 Type byte
38 seq int64
39 Ts int64
40 P int
41 G uint64
42 StkID uint64
43 Stk []*Frame
44 Args [3]uint64
45 SArgs []string
46
47
48
49
50
51
52
53
54
55
56
57
58
59
60 Link *Event
61 }
62
63
64 type Frame struct {
65 PC uint64
66 Fn string
67 File string
68 Line int
69 }
70
71 const (
72
73 FakeP = 1000000 + iota
74 TimerP
75 NetpollP
76 SyscallP
77 GCP
78 )
79
80
81 type ParseResult struct {
82
83 Events []*Event
84
85 Stacks map[uint64][]*Frame
86 }
87
88
89 func Parse(r io.Reader, bin string) (ParseResult, error) {
90 ver, res, err := parse(r, bin)
91 if err != nil {
92 return ParseResult{}, err
93 }
94 if ver < 1007 && bin == "" {
95 return ParseResult{}, fmt.Errorf("for traces produced by go 1.6 or below, the binary argument must be provided")
96 }
97 return res, nil
98 }
99
100
101
102 func parse(r io.Reader, bin string) (int, ParseResult, error) {
103 ver, rawEvents, strings, err := readTrace(r)
104 if err != nil {
105 return 0, ParseResult{}, err
106 }
107 events, stacks, err := parseEvents(ver, rawEvents, strings)
108 if err != nil {
109 return 0, ParseResult{}, err
110 }
111 events = removeFutile(events)
112 err = postProcessTrace(ver, events)
113 if err != nil {
114 return 0, ParseResult{}, err
115 }
116
117 for _, ev := range events {
118 if ev.StkID != 0 {
119 ev.Stk = stacks[ev.StkID]
120 }
121 }
122 if ver < 1007 && bin != "" {
123 if err := symbolize(events, bin); err != nil {
124 return 0, ParseResult{}, err
125 }
126 }
127 return ver, ParseResult{Events: events, Stacks: stacks}, nil
128 }
129
130
131 type rawEvent struct {
132 off int
133 typ byte
134 args []uint64
135 sargs []string
136 }
137
138
139
140 func readTrace(r io.Reader) (ver int, events []rawEvent, strings map[uint64]string, err error) {
141
142 var buf [16]byte
143 off, err := io.ReadFull(r, buf[:])
144 if err != nil {
145 err = fmt.Errorf("failed to read header: read %v, err %v", off, err)
146 return
147 }
148 ver, err = parseHeader(buf[:])
149 if err != nil {
150 return
151 }
152 switch ver {
153 case 1005, 1007, 1008, 1009, 1010, 1011:
154
155
156 break
157 default:
158 err = fmt.Errorf("unsupported trace file version %v.%v (update Go toolchain) %v", ver/1000, ver%1000, ver)
159 return
160 }
161
162
163 strings = make(map[uint64]string)
164 for {
165
166 off0 := off
167 var n int
168 n, err = r.Read(buf[:1])
169 if err == io.EOF {
170 err = nil
171 break
172 }
173 if err != nil || n != 1 {
174 err = fmt.Errorf("failed to read trace at offset 0x%x: n=%v err=%v", off0, n, err)
175 return
176 }
177 off += n
178 typ := buf[0] << 2 >> 2
179 narg := buf[0]>>6 + 1
180 inlineArgs := byte(4)
181 if ver < 1007 {
182 narg++
183 inlineArgs++
184 }
185 if typ == EvNone || typ >= EvCount || EventDescriptions[typ].minVersion > ver {
186 err = fmt.Errorf("unknown event type %v at offset 0x%x", typ, off0)
187 return
188 }
189 if typ == EvString {
190
191 var id uint64
192 id, off, err = readVal(r, off)
193 if err != nil {
194 return
195 }
196 if id == 0 {
197 err = fmt.Errorf("string at offset %d has invalid id 0", off)
198 return
199 }
200 if strings[id] != "" {
201 err = fmt.Errorf("string at offset %d has duplicate id %v", off, id)
202 return
203 }
204 var ln uint64
205 ln, off, err = readVal(r, off)
206 if err != nil {
207 return
208 }
209 if ln == 0 {
210 err = fmt.Errorf("string at offset %d has invalid length 0", off)
211 return
212 }
213 if ln > 1e6 {
214 err = fmt.Errorf("string at offset %d has too large length %v", off, ln)
215 return
216 }
217 buf := make([]byte, ln)
218 var n int
219 n, err = io.ReadFull(r, buf)
220 if err != nil {
221 err = fmt.Errorf("failed to read trace at offset %d: read %v, want %v, error %v", off, n, ln, err)
222 return
223 }
224 off += n
225 strings[id] = string(buf)
226 continue
227 }
228 ev := rawEvent{typ: typ, off: off0}
229 if narg < inlineArgs {
230 for i := 0; i < int(narg); i++ {
231 var v uint64
232 v, off, err = readVal(r, off)
233 if err != nil {
234 err = fmt.Errorf("failed to read event %v argument at offset %v (%v)", typ, off, err)
235 return
236 }
237 ev.args = append(ev.args, v)
238 }
239 } else {
240
241 var v uint64
242 v, off, err = readVal(r, off)
243 if err != nil {
244 err = fmt.Errorf("failed to read event %v argument at offset %v (%v)", typ, off, err)
245 return
246 }
247 evLen := v
248 off1 := off
249 for evLen > uint64(off-off1) {
250 v, off, err = readVal(r, off)
251 if err != nil {
252 err = fmt.Errorf("failed to read event %v argument at offset %v (%v)", typ, off, err)
253 return
254 }
255 ev.args = append(ev.args, v)
256 }
257 if evLen != uint64(off-off1) {
258 err = fmt.Errorf("event has wrong length at offset 0x%x: want %v, got %v", off0, evLen, off-off1)
259 return
260 }
261 }
262 switch ev.typ {
263 case EvUserLog:
264 var s string
265 s, off, err = readStr(r, off)
266 ev.sargs = append(ev.sargs, s)
267 }
268 events = append(events, ev)
269 }
270 return
271 }
272
273 func readStr(r io.Reader, off0 int) (s string, off int, err error) {
274 var sz uint64
275 sz, off, err = readVal(r, off0)
276 if err != nil || sz == 0 {
277 return "", off, err
278 }
279 if sz > 1e6 {
280 return "", off, fmt.Errorf("string at offset %d is too large (len=%d)", off, sz)
281 }
282 buf := make([]byte, sz)
283 n, err := io.ReadFull(r, buf)
284 if err != nil || sz != uint64(n) {
285 return "", off + n, fmt.Errorf("failed to read trace at offset %d: read %v, want %v, error %v", off, n, sz, err)
286 }
287 return string(buf), off + n, nil
288 }
289
290
291
292 func parseHeader(buf []byte) (int, error) {
293 if len(buf) != 16 {
294 return 0, fmt.Errorf("bad header length")
295 }
296 if buf[0] != 'g' || buf[1] != 'o' || buf[2] != ' ' ||
297 buf[3] < '1' || buf[3] > '9' ||
298 buf[4] != '.' ||
299 buf[5] < '1' || buf[5] > '9' {
300 return 0, fmt.Errorf("not a trace file")
301 }
302 ver := int(buf[5] - '0')
303 i := 0
304 for ; buf[6+i] >= '0' && buf[6+i] <= '9' && i < 2; i++ {
305 ver = ver*10 + int(buf[6+i]-'0')
306 }
307 ver += int(buf[3]-'0') * 1000
308 if !bytes.Equal(buf[6+i:], []byte(" trace\x00\x00\x00\x00")[:10-i]) {
309 return 0, fmt.Errorf("not a trace file")
310 }
311 return ver, nil
312 }
313
314
315
316 func parseEvents(ver int, rawEvents []rawEvent, strings map[uint64]string) (events []*Event, stacks map[uint64][]*Frame, err error) {
317 var ticksPerSec, lastSeq, lastTs int64
318 var lastG uint64
319 var lastP int
320 timerGoids := make(map[uint64]bool)
321 lastGs := make(map[int]uint64)
322 stacks = make(map[uint64][]*Frame)
323 batches := make(map[int][]*Event)
324 for _, raw := range rawEvents {
325 desc := EventDescriptions[raw.typ]
326 if desc.Name == "" {
327 err = fmt.Errorf("missing description for event type %v", raw.typ)
328 return
329 }
330 narg := argNum(raw, ver)
331 if len(raw.args) != narg {
332 err = fmt.Errorf("%v has wrong number of arguments at offset 0x%x: want %v, got %v",
333 desc.Name, raw.off, narg, len(raw.args))
334 return
335 }
336 switch raw.typ {
337 case EvBatch:
338 lastGs[lastP] = lastG
339 lastP = int(raw.args[0])
340 lastG = lastGs[lastP]
341 if ver < 1007 {
342 lastSeq = int64(raw.args[1])
343 lastTs = int64(raw.args[2])
344 } else {
345 lastTs = int64(raw.args[1])
346 }
347 case EvFrequency:
348 ticksPerSec = int64(raw.args[0])
349 if ticksPerSec <= 0 {
350
351
352
353 err = ErrTimeOrder
354 return
355 }
356 case EvTimerGoroutine:
357 timerGoids[raw.args[0]] = true
358 case EvStack:
359 if len(raw.args) < 2 {
360 err = fmt.Errorf("EvStack has wrong number of arguments at offset 0x%x: want at least 2, got %v",
361 raw.off, len(raw.args))
362 return
363 }
364 size := raw.args[1]
365 if size > 1000 {
366 err = fmt.Errorf("EvStack has bad number of frames at offset 0x%x: %v",
367 raw.off, size)
368 return
369 }
370 want := 2 + 4*size
371 if ver < 1007 {
372 want = 2 + size
373 }
374 if uint64(len(raw.args)) != want {
375 err = fmt.Errorf("EvStack has wrong number of arguments at offset 0x%x: want %v, got %v",
376 raw.off, want, len(raw.args))
377 return
378 }
379 id := raw.args[0]
380 if id != 0 && size > 0 {
381 stk := make([]*Frame, size)
382 for i := 0; i < int(size); i++ {
383 if ver < 1007 {
384 stk[i] = &Frame{PC: raw.args[2+i]}
385 } else {
386 pc := raw.args[2+i*4+0]
387 fn := raw.args[2+i*4+1]
388 file := raw.args[2+i*4+2]
389 line := raw.args[2+i*4+3]
390 stk[i] = &Frame{PC: pc, Fn: strings[fn], File: strings[file], Line: int(line)}
391 }
392 }
393 stacks[id] = stk
394 }
395 default:
396 e := &Event{Off: raw.off, Type: raw.typ, P: lastP, G: lastG}
397 var argOffset int
398 if ver < 1007 {
399 e.seq = lastSeq + int64(raw.args[0])
400 e.Ts = lastTs + int64(raw.args[1])
401 lastSeq = e.seq
402 argOffset = 2
403 } else {
404 e.Ts = lastTs + int64(raw.args[0])
405 argOffset = 1
406 }
407 lastTs = e.Ts
408 for i := argOffset; i < narg; i++ {
409 if i == narg-1 && desc.Stack {
410 e.StkID = raw.args[i]
411 } else {
412 e.Args[i-argOffset] = raw.args[i]
413 }
414 }
415 switch raw.typ {
416 case EvGoStart, EvGoStartLocal, EvGoStartLabel:
417 lastG = e.Args[0]
418 e.G = lastG
419 if raw.typ == EvGoStartLabel {
420 e.SArgs = []string{strings[e.Args[2]]}
421 }
422 case EvGCSTWStart:
423 e.G = 0
424 switch e.Args[0] {
425 case 0:
426 e.SArgs = []string{"mark termination"}
427 case 1:
428 e.SArgs = []string{"sweep termination"}
429 default:
430 err = fmt.Errorf("unknown STW kind %d", e.Args[0])
431 return
432 }
433 case EvGCStart, EvGCDone, EvGCSTWDone:
434 e.G = 0
435 case EvGoEnd, EvGoStop, EvGoSched, EvGoPreempt,
436 EvGoSleep, EvGoBlock, EvGoBlockSend, EvGoBlockRecv,
437 EvGoBlockSelect, EvGoBlockSync, EvGoBlockCond, EvGoBlockNet,
438 EvGoSysBlock, EvGoBlockGC:
439 lastG = 0
440 case EvGoSysExit, EvGoWaiting, EvGoInSyscall:
441 e.G = e.Args[0]
442 case EvUserTaskCreate:
443
444 e.SArgs = []string{strings[e.Args[2]]}
445 case EvUserRegion:
446
447 e.SArgs = []string{strings[e.Args[2]]}
448 case EvUserLog:
449
450 e.SArgs = []string{strings[e.Args[1]], raw.sargs[0]}
451 }
452 batches[lastP] = append(batches[lastP], e)
453 }
454 }
455 if len(batches) == 0 {
456 err = fmt.Errorf("trace is empty")
457 return
458 }
459 if ticksPerSec == 0 {
460 err = fmt.Errorf("no EvFrequency event")
461 return
462 }
463 if BreakTimestampsForTesting {
464 var batchArr [][]*Event
465 for _, batch := range batches {
466 batchArr = append(batchArr, batch)
467 }
468 for i := 0; i < 5; i++ {
469 batch := batchArr[rand.Intn(len(batchArr))]
470 batch[rand.Intn(len(batch))].Ts += int64(rand.Intn(2000) - 1000)
471 }
472 }
473 if ver < 1007 {
474 events, err = order1005(batches)
475 } else {
476 events, err = order1007(batches)
477 }
478 if err != nil {
479 return
480 }
481
482
483 minTs := events[0].Ts
484
485 freq := 1e9 / float64(ticksPerSec)
486 for _, ev := range events {
487 ev.Ts = int64(float64(ev.Ts-minTs) * freq)
488
489 if timerGoids[ev.G] && ev.Type == EvGoUnblock {
490 ev.P = TimerP
491 }
492 if ev.Type == EvGoSysExit {
493 ev.P = SyscallP
494 }
495 }
496
497 return
498 }
499
500
501
502
503
504
505 func removeFutile(events []*Event) []*Event {
506
507
508
509
510
511
512
513
514 type G struct {
515 futile bool
516 wakeup []*Event
517 }
518 gs := make(map[uint64]G)
519 futile := make(map[*Event]bool)
520 for _, ev := range events {
521 switch ev.Type {
522 case EvGoUnblock:
523 g := gs[ev.Args[0]]
524 g.wakeup = []*Event{ev}
525 gs[ev.Args[0]] = g
526 case EvGoStart, EvGoPreempt, EvFutileWakeup:
527 g := gs[ev.G]
528 g.wakeup = append(g.wakeup, ev)
529 if ev.Type == EvFutileWakeup {
530 g.futile = true
531 }
532 gs[ev.G] = g
533 case EvGoBlock, EvGoBlockSend, EvGoBlockRecv, EvGoBlockSelect, EvGoBlockSync, EvGoBlockCond:
534 g := gs[ev.G]
535 if g.futile {
536 futile[ev] = true
537 for _, ev1 := range g.wakeup {
538 futile[ev1] = true
539 }
540 }
541 delete(gs, ev.G)
542 }
543 }
544
545
546 newEvents := events[:0]
547 for _, ev := range events {
548 if !futile[ev] {
549 newEvents = append(newEvents, ev)
550 }
551 }
552 return newEvents
553 }
554
555
556
557 var ErrTimeOrder = fmt.Errorf("time stamps out of order")
558
559
560
561
562
563 func postProcessTrace(ver int, events []*Event) error {
564 const (
565 gDead = iota
566 gRunnable
567 gRunning
568 gWaiting
569 )
570 type gdesc struct {
571 state int
572 ev *Event
573 evStart *Event
574 evCreate *Event
575 evMarkAssist *Event
576 }
577 type pdesc struct {
578 running bool
579 g uint64
580 evSTW *Event
581 evSweep *Event
582 }
583
584 gs := make(map[uint64]gdesc)
585 ps := make(map[int]pdesc)
586 tasks := make(map[uint64]*Event)
587 activeRegions := make(map[uint64][]*Event)
588 gs[0] = gdesc{state: gRunning}
589 var evGC, evSTW *Event
590
591 checkRunning := func(p pdesc, g gdesc, ev *Event, allowG0 bool) error {
592 name := EventDescriptions[ev.Type].Name
593 if g.state != gRunning {
594 return fmt.Errorf("g %v is not running while %v (offset %v, time %v)", ev.G, name, ev.Off, ev.Ts)
595 }
596 if p.g != ev.G {
597 return fmt.Errorf("p %v is not running g %v while %v (offset %v, time %v)", ev.P, ev.G, name, ev.Off, ev.Ts)
598 }
599 if !allowG0 && ev.G == 0 {
600 return fmt.Errorf("g 0 did %v (offset %v, time %v)", EventDescriptions[ev.Type].Name, ev.Off, ev.Ts)
601 }
602 return nil
603 }
604
605 for _, ev := range events {
606 g := gs[ev.G]
607 p := ps[ev.P]
608
609 switch ev.Type {
610 case EvProcStart:
611 if p.running {
612 return fmt.Errorf("p %v is running before start (offset %v, time %v)", ev.P, ev.Off, ev.Ts)
613 }
614 p.running = true
615 case EvProcStop:
616 if !p.running {
617 return fmt.Errorf("p %v is not running before stop (offset %v, time %v)", ev.P, ev.Off, ev.Ts)
618 }
619 if p.g != 0 {
620 return fmt.Errorf("p %v is running a goroutine %v during stop (offset %v, time %v)", ev.P, p.g, ev.Off, ev.Ts)
621 }
622 p.running = false
623 case EvGCStart:
624 if evGC != nil {
625 return fmt.Errorf("previous GC is not ended before a new one (offset %v, time %v)", ev.Off, ev.Ts)
626 }
627 evGC = ev
628
629 ev.P = GCP
630 case EvGCDone:
631 if evGC == nil {
632 return fmt.Errorf("bogus GC end (offset %v, time %v)", ev.Off, ev.Ts)
633 }
634 evGC.Link = ev
635 evGC = nil
636 case EvGCSTWStart:
637 evp := &evSTW
638 if ver < 1010 {
639
640 evp = &p.evSTW
641 }
642 if *evp != nil {
643 return fmt.Errorf("previous STW is not ended before a new one (offset %v, time %v)", ev.Off, ev.Ts)
644 }
645 *evp = ev
646 case EvGCSTWDone:
647 evp := &evSTW
648 if ver < 1010 {
649
650 evp = &p.evSTW
651 }
652 if *evp == nil {
653 return fmt.Errorf("bogus STW end (offset %v, time %v)", ev.Off, ev.Ts)
654 }
655 (*evp).Link = ev
656 *evp = nil
657 case EvGCSweepStart:
658 if p.evSweep != nil {
659 return fmt.Errorf("previous sweeping is not ended before a new one (offset %v, time %v)", ev.Off, ev.Ts)
660 }
661 p.evSweep = ev
662 case EvGCMarkAssistStart:
663 if g.evMarkAssist != nil {
664 return fmt.Errorf("previous mark assist is not ended before a new one (offset %v, time %v)", ev.Off, ev.Ts)
665 }
666 g.evMarkAssist = ev
667 case EvGCMarkAssistDone:
668
669
670 if g.evMarkAssist != nil {
671 g.evMarkAssist.Link = ev
672 g.evMarkAssist = nil
673 }
674 case EvGCSweepDone:
675 if p.evSweep == nil {
676 return fmt.Errorf("bogus sweeping end (offset %v, time %v)", ev.Off, ev.Ts)
677 }
678 p.evSweep.Link = ev
679 p.evSweep = nil
680 case EvGoWaiting:
681 if g.state != gRunnable {
682 return fmt.Errorf("g %v is not runnable before EvGoWaiting (offset %v, time %v)", ev.G, ev.Off, ev.Ts)
683 }
684 g.state = gWaiting
685 g.ev = ev
686 case EvGoInSyscall:
687 if g.state != gRunnable {
688 return fmt.Errorf("g %v is not runnable before EvGoInSyscall (offset %v, time %v)", ev.G, ev.Off, ev.Ts)
689 }
690 g.state = gWaiting
691 g.ev = ev
692 case EvGoCreate:
693 if err := checkRunning(p, g, ev, true); err != nil {
694 return err
695 }
696 if _, ok := gs[ev.Args[0]]; ok {
697 return fmt.Errorf("g %v already exists (offset %v, time %v)", ev.Args[0], ev.Off, ev.Ts)
698 }
699 gs[ev.Args[0]] = gdesc{state: gRunnable, ev: ev, evCreate: ev}
700 case EvGoStart, EvGoStartLabel:
701 if g.state != gRunnable {
702 return fmt.Errorf("g %v is not runnable before start (offset %v, time %v)", ev.G, ev.Off, ev.Ts)
703 }
704 if p.g != 0 {
705 return fmt.Errorf("p %v is already running g %v while start g %v (offset %v, time %v)", ev.P, p.g, ev.G, ev.Off, ev.Ts)
706 }
707 g.state = gRunning
708 g.evStart = ev
709 p.g = ev.G
710 if g.evCreate != nil {
711 if ver < 1007 {
712
713 ev.Stk = []*Frame{{PC: g.evCreate.Args[1] + 1}}
714 } else {
715 ev.StkID = g.evCreate.Args[1]
716 }
717 g.evCreate = nil
718 }
719
720 if g.ev != nil {
721 g.ev.Link = ev
722 g.ev = nil
723 }
724 case EvGoEnd, EvGoStop:
725 if err := checkRunning(p, g, ev, false); err != nil {
726 return err
727 }
728 g.evStart.Link = ev
729 g.evStart = nil
730 g.state = gDead
731 p.g = 0
732
733 if ev.Type == EvGoEnd {
734 regions := activeRegions[ev.G]
735 for _, s := range regions {
736 s.Link = ev
737 }
738 delete(activeRegions, ev.G)
739 }
740
741 case EvGoSched, EvGoPreempt:
742 if err := checkRunning(p, g, ev, false); err != nil {
743 return err
744 }
745 g.state = gRunnable
746 g.evStart.Link = ev
747 g.evStart = nil
748 p.g = 0
749 g.ev = ev
750 case EvGoUnblock:
751 if g.state != gRunning {
752 return fmt.Errorf("g %v is not running while unpark (offset %v, time %v)", ev.G, ev.Off, ev.Ts)
753 }
754 if ev.P != TimerP && p.g != ev.G {
755 return fmt.Errorf("p %v is not running g %v while unpark (offset %v, time %v)", ev.P, ev.G, ev.Off, ev.Ts)
756 }
757 g1 := gs[ev.Args[0]]
758 if g1.state != gWaiting {
759 return fmt.Errorf("g %v is not waiting before unpark (offset %v, time %v)", ev.Args[0], ev.Off, ev.Ts)
760 }
761 if g1.ev != nil && g1.ev.Type == EvGoBlockNet && ev.P != TimerP {
762 ev.P = NetpollP
763 }
764 if g1.ev != nil {
765 g1.ev.Link = ev
766 }
767 g1.state = gRunnable
768 g1.ev = ev
769 gs[ev.Args[0]] = g1
770 case EvGoSysCall:
771 if err := checkRunning(p, g, ev, false); err != nil {
772 return err
773 }
774 g.ev = ev
775 case EvGoSysBlock:
776 if err := checkRunning(p, g, ev, false); err != nil {
777 return err
778 }
779 g.state = gWaiting
780 g.evStart.Link = ev
781 g.evStart = nil
782 p.g = 0
783 case EvGoSysExit:
784 if g.state != gWaiting {
785 return fmt.Errorf("g %v is not waiting during syscall exit (offset %v, time %v)", ev.G, ev.Off, ev.Ts)
786 }
787 if g.ev != nil && g.ev.Type == EvGoSysCall {
788 g.ev.Link = ev
789 }
790 g.state = gRunnable
791 g.ev = ev
792 case EvGoSleep, EvGoBlock, EvGoBlockSend, EvGoBlockRecv,
793 EvGoBlockSelect, EvGoBlockSync, EvGoBlockCond, EvGoBlockNet, EvGoBlockGC:
794 if err := checkRunning(p, g, ev, false); err != nil {
795 return err
796 }
797 g.state = gWaiting
798 g.ev = ev
799 g.evStart.Link = ev
800 g.evStart = nil
801 p.g = 0
802 case EvUserTaskCreate:
803 taskid := ev.Args[0]
804 if prevEv, ok := tasks[taskid]; ok {
805 return fmt.Errorf("task id conflicts (id:%d), %q vs %q", taskid, ev, prevEv)
806 }
807 tasks[ev.Args[0]] = ev
808 case EvUserTaskEnd:
809 taskid := ev.Args[0]
810 if taskCreateEv, ok := tasks[taskid]; ok {
811 taskCreateEv.Link = ev
812 delete(tasks, taskid)
813 }
814 case EvUserRegion:
815 mode := ev.Args[1]
816 regions := activeRegions[ev.G]
817 if mode == 0 {
818 activeRegions[ev.G] = append(regions, ev)
819 } else if mode == 1 {
820 n := len(regions)
821 if n > 0 {
822 s := regions[n-1]
823 if s.Args[0] != ev.Args[0] || s.SArgs[0] != ev.SArgs[0] {
824 return fmt.Errorf("misuse of region in goroutine %d: span end %q when the inner-most active span start event is %q", ev.G, ev, s)
825 }
826
827 s.Link = ev
828
829 if n > 1 {
830 activeRegions[ev.G] = regions[:n-1]
831 } else {
832 delete(activeRegions, ev.G)
833 }
834 }
835 } else {
836 return fmt.Errorf("invalid user region mode: %q", ev)
837 }
838 }
839
840 gs[ev.G] = g
841 ps[ev.P] = p
842 }
843
844
845
846
847 return nil
848 }
849
850
851 func symbolize(events []*Event, bin string) error {
852
853 pcs := make(map[uint64]*Frame)
854 for _, ev := range events {
855 for _, f := range ev.Stk {
856 pcs[f.PC] = nil
857 }
858 }
859
860
861 cmd := exec.Command(goCmd(), "tool", "addr2line", bin)
862 in, err := cmd.StdinPipe()
863 if err != nil {
864 return fmt.Errorf("failed to pipe addr2line stdin: %v", err)
865 }
866 cmd.Stderr = os.Stderr
867 out, err := cmd.StdoutPipe()
868 if err != nil {
869 return fmt.Errorf("failed to pipe addr2line stdout: %v", err)
870 }
871 err = cmd.Start()
872 if err != nil {
873 return fmt.Errorf("failed to start addr2line: %v", err)
874 }
875 outb := bufio.NewReader(out)
876
877
878
879 var pcArray []uint64
880 for pc := range pcs {
881 pcArray = append(pcArray, pc)
882 _, err := fmt.Fprintf(in, "0x%x\n", pc-1)
883 if err != nil {
884 return fmt.Errorf("failed to write to addr2line: %v", err)
885 }
886 }
887 in.Close()
888
889
890 for _, pc := range pcArray {
891 fn, err := outb.ReadString('\n')
892 if err != nil {
893 return fmt.Errorf("failed to read from addr2line: %v", err)
894 }
895 file, err := outb.ReadString('\n')
896 if err != nil {
897 return fmt.Errorf("failed to read from addr2line: %v", err)
898 }
899 f := &Frame{PC: pc}
900 f.Fn = fn[:len(fn)-1]
901 f.File = file[:len(file)-1]
902 if colon := strings.LastIndex(f.File, ":"); colon != -1 {
903 ln, err := strconv.Atoi(f.File[colon+1:])
904 if err == nil {
905 f.File = f.File[:colon]
906 f.Line = ln
907 }
908 }
909 pcs[pc] = f
910 }
911 cmd.Wait()
912
913
914 for _, ev := range events {
915 for i, f := range ev.Stk {
916 ev.Stk[i] = pcs[f.PC]
917 }
918 }
919
920 return nil
921 }
922
923
924 func readVal(r io.Reader, off0 int) (v uint64, off int, err error) {
925 off = off0
926 for i := 0; i < 10; i++ {
927 var buf [1]byte
928 var n int
929 n, err = r.Read(buf[:])
930 if err != nil || n != 1 {
931 return 0, 0, fmt.Errorf("failed to read trace at offset %d: read %v, error %v", off0, n, err)
932 }
933 off++
934 v |= uint64(buf[0]&0x7f) << (uint(i) * 7)
935 if buf[0]&0x80 == 0 {
936 return
937 }
938 }
939 return 0, 0, fmt.Errorf("bad value at offset 0x%x", off0)
940 }
941
942
943 func Print(events []*Event) {
944 for _, ev := range events {
945 PrintEvent(ev)
946 }
947 }
948
949
950 func PrintEvent(ev *Event) {
951 fmt.Printf("%s\n", ev)
952 }
953
954 func (ev *Event) String() string {
955 desc := EventDescriptions[ev.Type]
956 w := new(bytes.Buffer)
957 fmt.Fprintf(w, "%v %v p=%v g=%v off=%v", ev.Ts, desc.Name, ev.P, ev.G, ev.Off)
958 for i, a := range desc.Args {
959 fmt.Fprintf(w, " %v=%v", a, ev.Args[i])
960 }
961 for i, a := range desc.SArgs {
962 fmt.Fprintf(w, " %v=%v", a, ev.SArgs[i])
963 }
964 return w.String()
965 }
966
967
968
969 func argNum(raw rawEvent, ver int) int {
970 desc := EventDescriptions[raw.typ]
971 if raw.typ == EvStack {
972 return len(raw.args)
973 }
974 narg := len(desc.Args)
975 if desc.Stack {
976 narg++
977 }
978 switch raw.typ {
979 case EvBatch, EvFrequency, EvTimerGoroutine:
980 if ver < 1007 {
981 narg++
982 }
983 return narg
984 }
985 narg++
986 if ver < 1007 {
987 narg++
988 }
989 switch raw.typ {
990 case EvGCSweepDone:
991 if ver < 1009 {
992 narg -= 2
993 }
994 case EvGCStart, EvGoStart, EvGoUnblock:
995 if ver < 1007 {
996 narg--
997 }
998 case EvGCSTWStart:
999 if ver < 1010 {
1000 narg--
1001 }
1002 }
1003 return narg
1004 }
1005
1006
1007 var BreakTimestampsForTesting bool
1008
1009
1010
1011 const (
1012 EvNone = 0
1013 EvBatch = 1
1014 EvFrequency = 2
1015 EvStack = 3
1016 EvGomaxprocs = 4
1017 EvProcStart = 5
1018 EvProcStop = 6
1019 EvGCStart = 7
1020 EvGCDone = 8
1021 EvGCSTWStart = 9
1022 EvGCSTWDone = 10
1023 EvGCSweepStart = 11
1024 EvGCSweepDone = 12
1025 EvGoCreate = 13
1026 EvGoStart = 14
1027 EvGoEnd = 15
1028 EvGoStop = 16
1029 EvGoSched = 17
1030 EvGoPreempt = 18
1031 EvGoSleep = 19
1032 EvGoBlock = 20
1033 EvGoUnblock = 21
1034 EvGoBlockSend = 22
1035 EvGoBlockRecv = 23
1036 EvGoBlockSelect = 24
1037 EvGoBlockSync = 25
1038 EvGoBlockCond = 26
1039 EvGoBlockNet = 27
1040 EvGoSysCall = 28
1041 EvGoSysExit = 29
1042 EvGoSysBlock = 30
1043 EvGoWaiting = 31
1044 EvGoInSyscall = 32
1045 EvHeapAlloc = 33
1046 EvHeapGoal = 34
1047 EvTimerGoroutine = 35
1048 EvFutileWakeup = 36
1049 EvString = 37
1050 EvGoStartLocal = 38
1051 EvGoUnblockLocal = 39
1052 EvGoSysExitLocal = 40
1053 EvGoStartLabel = 41
1054 EvGoBlockGC = 42
1055 EvGCMarkAssistStart = 43
1056 EvGCMarkAssistDone = 44
1057 EvUserTaskCreate = 45
1058 EvUserTaskEnd = 46
1059 EvUserRegion = 47
1060 EvUserLog = 48
1061 EvCount = 49
1062 )
1063
1064 var EventDescriptions = [EvCount]struct {
1065 Name string
1066 minVersion int
1067 Stack bool
1068 Args []string
1069 SArgs []string
1070 }{
1071 EvNone: {"None", 1005, false, []string{}, nil},
1072 EvBatch: {"Batch", 1005, false, []string{"p", "ticks"}, nil},
1073 EvFrequency: {"Frequency", 1005, false, []string{"freq"}, nil},
1074 EvStack: {"Stack", 1005, false, []string{"id", "siz"}, nil},
1075 EvGomaxprocs: {"Gomaxprocs", 1005, true, []string{"procs"}, nil},
1076 EvProcStart: {"ProcStart", 1005, false, []string{"thread"}, nil},
1077 EvProcStop: {"ProcStop", 1005, false, []string{}, nil},
1078 EvGCStart: {"GCStart", 1005, true, []string{"seq"}, nil},
1079 EvGCDone: {"GCDone", 1005, false, []string{}, nil},
1080 EvGCSTWStart: {"GCSTWStart", 1005, false, []string{"kindid"}, []string{"kind"}},
1081 EvGCSTWDone: {"GCSTWDone", 1005, false, []string{}, nil},
1082 EvGCSweepStart: {"GCSweepStart", 1005, true, []string{}, nil},
1083 EvGCSweepDone: {"GCSweepDone", 1005, false, []string{"swept", "reclaimed"}, nil},
1084 EvGoCreate: {"GoCreate", 1005, true, []string{"g", "stack"}, nil},
1085 EvGoStart: {"GoStart", 1005, false, []string{"g", "seq"}, nil},
1086 EvGoEnd: {"GoEnd", 1005, false, []string{}, nil},
1087 EvGoStop: {"GoStop", 1005, true, []string{}, nil},
1088 EvGoSched: {"GoSched", 1005, true, []string{}, nil},
1089 EvGoPreempt: {"GoPreempt", 1005, true, []string{}, nil},
1090 EvGoSleep: {"GoSleep", 1005, true, []string{}, nil},
1091 EvGoBlock: {"GoBlock", 1005, true, []string{}, nil},
1092 EvGoUnblock: {"GoUnblock", 1005, true, []string{"g", "seq"}, nil},
1093 EvGoBlockSend: {"GoBlockSend", 1005, true, []string{}, nil},
1094 EvGoBlockRecv: {"GoBlockRecv", 1005, true, []string{}, nil},
1095 EvGoBlockSelect: {"GoBlockSelect", 1005, true, []string{}, nil},
1096 EvGoBlockSync: {"GoBlockSync", 1005, true, []string{}, nil},
1097 EvGoBlockCond: {"GoBlockCond", 1005, true, []string{}, nil},
1098 EvGoBlockNet: {"GoBlockNet", 1005, true, []string{}, nil},
1099 EvGoSysCall: {"GoSysCall", 1005, true, []string{}, nil},
1100 EvGoSysExit: {"GoSysExit", 1005, false, []string{"g", "seq", "ts"}, nil},
1101 EvGoSysBlock: {"GoSysBlock", 1005, false, []string{}, nil},
1102 EvGoWaiting: {"GoWaiting", 1005, false, []string{"g"}, nil},
1103 EvGoInSyscall: {"GoInSyscall", 1005, false, []string{"g"}, nil},
1104 EvHeapAlloc: {"HeapAlloc", 1005, false, []string{"mem"}, nil},
1105 EvHeapGoal: {"HeapGoal", 1005, false, []string{"mem"}, nil},
1106 EvTimerGoroutine: {"TimerGoroutine", 1005, false, []string{"g"}, nil},
1107 EvFutileWakeup: {"FutileWakeup", 1005, false, []string{}, nil},
1108 EvString: {"String", 1007, false, []string{}, nil},
1109 EvGoStartLocal: {"GoStartLocal", 1007, false, []string{"g"}, nil},
1110 EvGoUnblockLocal: {"GoUnblockLocal", 1007, true, []string{"g"}, nil},
1111 EvGoSysExitLocal: {"GoSysExitLocal", 1007, false, []string{"g", "ts"}, nil},
1112 EvGoStartLabel: {"GoStartLabel", 1008, false, []string{"g", "seq", "labelid"}, []string{"label"}},
1113 EvGoBlockGC: {"GoBlockGC", 1008, true, []string{}, nil},
1114 EvGCMarkAssistStart: {"GCMarkAssistStart", 1009, true, []string{}, nil},
1115 EvGCMarkAssistDone: {"GCMarkAssistDone", 1009, false, []string{}, nil},
1116 EvUserTaskCreate: {"UserTaskCreate", 1011, true, []string{"taskid", "pid", "typeid"}, []string{"name"}},
1117 EvUserTaskEnd: {"UserTaskEnd", 1011, true, []string{"taskid"}, nil},
1118 EvUserRegion: {"UserRegion", 1011, true, []string{"taskid", "mode", "typeid"}, []string{"name"}},
1119 EvUserLog: {"UserLog", 1011, true, []string{"id", "keyid"}, []string{"category", "message"}},
1120 }
1121
View as plain text