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