-
-
Notifications
You must be signed in to change notification settings - Fork 27
/
parser.go
1537 lines (1398 loc) · 46 KB
/
parser.go
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
55
56
57
58
59
60
61
62
63
64
65
66
67
68
69
70
71
72
73
74
75
76
77
78
79
80
81
82
83
84
85
86
87
88
89
90
91
92
93
94
95
96
97
98
99
100
101
102
103
104
105
106
107
108
109
110
111
112
113
114
115
116
117
118
119
120
121
122
123
124
125
126
127
128
129
130
131
132
133
134
135
136
137
138
139
140
141
142
143
144
145
146
147
148
149
150
151
152
153
154
155
156
157
158
159
160
161
162
163
164
165
166
167
168
169
170
171
172
173
174
175
176
177
178
179
180
181
182
183
184
185
186
187
188
189
190
191
192
193
194
195
196
197
198
199
200
201
202
203
204
205
206
207
208
209
210
211
212
213
214
215
216
217
218
219
220
221
222
223
224
225
226
227
228
229
230
231
232
233
234
235
236
237
238
239
240
241
242
243
244
245
246
247
248
249
250
251
252
253
254
255
256
257
258
259
260
261
262
263
264
265
266
267
268
269
270
271
272
273
274
275
276
277
278
279
280
281
282
283
284
285
286
287
288
289
290
291
292
293
294
295
296
297
298
299
300
301
302
303
304
305
306
307
308
309
310
311
312
313
314
315
316
317
318
319
320
321
322
323
324
325
326
327
328
329
330
331
332
333
334
335
336
337
338
339
340
341
342
343
344
345
346
347
348
349
350
351
352
353
354
355
356
357
358
359
360
361
362
363
364
365
366
367
368
369
370
371
372
373
374
375
376
377
378
379
380
381
382
383
384
385
386
387
388
389
390
391
392
393
394
395
396
397
398
399
400
401
402
403
404
405
406
407
408
409
410
411
412
413
414
415
416
417
418
419
420
421
422
423
424
425
426
427
428
429
430
431
432
433
434
435
436
437
438
439
440
441
442
443
444
445
446
447
448
449
450
451
452
453
454
455
456
457
458
459
460
461
462
463
464
465
466
467
468
469
470
471
472
473
474
475
476
477
478
479
480
481
482
483
484
485
486
487
488
489
490
491
492
493
494
495
496
497
498
499
500
501
502
503
504
505
506
507
508
509
510
511
512
513
514
515
516
517
518
519
520
521
522
523
524
525
526
527
528
529
530
531
532
533
534
535
536
537
538
539
540
541
542
543
544
545
546
547
548
549
550
551
552
553
554
555
556
557
558
559
560
561
562
563
564
565
566
567
568
569
570
571
572
573
574
575
576
577
578
579
580
581
582
583
584
585
586
587
588
589
590
591
592
593
594
595
596
597
598
599
600
601
602
603
604
605
606
607
608
609
610
611
612
613
614
615
616
617
618
619
620
621
622
623
624
625
626
627
628
629
630
631
632
633
634
635
636
637
638
639
640
641
642
643
644
645
646
647
648
649
650
651
652
653
654
655
656
657
658
659
660
661
662
663
664
665
666
667
668
669
670
671
672
673
674
675
676
677
678
679
680
681
682
683
684
685
686
687
688
689
690
691
692
693
694
695
696
697
698
699
700
701
702
703
704
705
706
707
708
709
710
711
712
713
714
715
716
717
718
719
720
721
722
723
724
725
726
727
728
729
730
731
732
733
734
735
736
737
738
739
740
741
742
743
744
745
746
747
748
749
750
751
752
753
754
755
756
757
758
759
760
761
762
763
764
765
766
767
768
769
770
771
772
773
774
775
776
777
778
779
780
781
782
783
784
785
786
787
788
789
790
791
792
793
794
795
796
797
798
799
800
801
802
803
804
805
806
807
808
809
810
811
812
813
814
815
816
817
818
819
820
821
822
823
824
825
826
827
828
829
830
831
832
833
834
835
836
837
838
839
840
841
842
843
844
845
846
847
848
849
850
851
852
853
854
855
856
857
858
859
860
861
862
863
864
865
866
867
868
869
870
871
872
873
874
875
876
877
878
879
880
881
882
883
884
885
886
887
888
889
890
891
892
893
894
895
896
897
898
899
900
901
902
903
904
905
906
907
908
909
910
911
912
913
914
915
916
917
918
919
920
921
922
923
924
925
926
927
928
929
930
931
932
933
934
935
936
937
938
939
940
941
942
943
944
945
946
947
948
949
950
951
952
953
954
955
956
957
958
959
960
961
962
963
964
965
966
967
968
969
970
971
972
973
974
975
976
977
978
979
980
981
982
983
984
985
986
987
988
989
990
991
992
993
994
995
996
997
998
999
1000
// Copyright 2014 The Go Authors. All rights reserved.
package trace
import (
"bytes"
"errors"
"fmt"
"io"
"math"
"sort"
)
var ErrTooManyEvents = fmt.Errorf("trace contains more than %d events", math.MaxInt32)
type Timestamp int64
// Event describes one event in the trace.
type Event struct {
// The Event type is carefully laid out to optimize its size and to avoid pointers, the latter so that the garbage
// collector won't have to scan any memory of our millions of events.
//
// Instead of pointers, fields like StkID and Link are indices into slices.
Ts Timestamp // timestamp in nanoseconds
G uint64 // G on which the event happened
Args [4]uint64 // event-type-specific arguments
StkID uint32 // unique stack ID
P int32 // P on which the event happened (can be one of TimerP, NetpollP, SyscallP)
// linked event (can be nil), depends on event type:
// for GCStart: the GCStop
// for GCSTWStart: the GCSTWDone
// for GCSweepStart: the GCSweepDone
// for GoCreate: first GoStart of the created goroutine
// for GoStart/GoStartLabel: the associated GoEnd, GoBlock or other blocking event
// for GoSched/GoPreempt: the next GoStart
// for GoBlock and other blocking events: the unblock event
// for GoUnblock: the associated GoStart
// for blocking GoSysCall: the associated GoSysExit
// for GoSysExit: the next GoStart
// for GCMarkAssistStart: the associated GCMarkAssistDone
// for UserTaskCreate: the UserTaskEnd
// for UserRegion: if the start region, the corresponding UserRegion end event
Link int32
Type byte // one of Ev*
}
// Frame is a frame in stack traces.
type Frame struct {
PC uint64
Fn string
File string
Line int
}
const (
// Special P identifiers:
FakeP = 1000000 + iota
NetpollP // depicts network unblocks
SyscallP // depicts returns from syscalls
GCP // depicts GC state
ProfileP // depicts recording of CPU profile samples
)
const headerLength = 16
// Trace is the result of Parse.
type Trace struct {
// Events is the sorted list of Events in the trace.
Events []Event
// Stacks is the stack traces keyed by stack IDs from the trace.
//
// OPT(dh): we could renumber stacks, PCs and Strings densely and store them in slices instead of maps. I don't know
// if the cost of accesses will outweigh the cost of renumbering.
Stacks map[uint32][]uint64
PCs map[uint64]Frame
Strings map[uint64]string
}
type batch struct {
offset int
numEvents int
}
type pState struct {
// list of batch offsets and sizes
batches []batch
// last goroutine running on P
lastG uint64
slice []Event
}
// The number of parsing stages. as reported to Parser.Progress. Each stage has its own total, and the current progress
// resets to 0 at the start of each stage.
type Parser struct {
progress func(p float64)
ver int
data []byte
off int
bigArgsBuf []byte
strings map[uint64]string
// OPT(dh): pStates doesn't need to be a map, as processor IDs are gapless and start at 0. We just have to change
// how we track fake Ps. Instead of starting them at a specific offset, give them the next free IDs.
pStates map[int32]*pState
stacks map[uint32][]uint64
stacksData []uint64
ticksPerSec int64
pcs map[uint64]Frame
cpuSamples []Event
// state for indexing
curP int32
// state for readRawEvent
args []uint64
// state for parseEvent
lastTs Timestamp
lastG uint64
lastP int32
logMessageID uint64
}
//gcassert:inline
func (p *Parser) pState(pid int32) *pState {
ps, ok := p.pStates[pid]
if ok {
return ps
}
ps = &pState{}
p.pStates[pid] = ps
return ps
}
//gcassert:inline
func (p *Parser) discard(n uint64) bool {
if n > math.MaxInt {
return false
}
if noff := p.off + int(n); noff < p.off || noff > len(p.data) {
return false
} else {
p.off = noff
}
return true
}
func NewParser(r io.Reader) (*Parser, error) {
var buf []byte
if seeker, ok := r.(io.Seeker); ok {
cur, err := seeker.Seek(0, io.SeekCurrent)
if err != nil {
return nil, err
}
end, err := seeker.Seek(0, io.SeekEnd)
if err != nil {
return nil, err
}
_, err = seeker.Seek(cur, io.SeekStart)
if err != nil {
return nil, err
}
buf = make([]byte, end-cur)
_, err = io.ReadFull(r, buf)
if err != nil {
return nil, err
}
} else {
var err error
buf, err = io.ReadAll(r)
if err != nil {
return nil, err
}
}
return &Parser{data: buf}, nil
}
func Parse(r io.Reader, progress func(float64)) (Trace, error) {
p, err := NewParser(r)
if err != nil {
return Trace{}, err
}
p.progress = progress
return p.Parse()
}
func (p *Parser) Parse() (Trace, error) {
_, res, err := p.parse()
p.data = nil
return res, err
}
// parse parses, post-processes and verifies the trace. It returns the
// trace version and the list of events.
func (p *Parser) parse() (int, Trace, error) {
p.strings = make(map[uint64]string)
p.pStates = make(map[int32]*pState)
p.stacks = make(map[uint32][]uint64)
p.pcs = make(map[uint64]Frame)
ver, err := p.readHeader()
if err != nil {
return 0, Trace{}, err
}
p.ver = ver
if err := p.indexAndPartiallyParse(); err != nil {
return 0, Trace{}, err
}
events, err := p.parseRest()
if err != nil {
return 0, Trace{}, err
}
if p.ticksPerSec == 0 {
return 0, Trace{}, errors.New("no EvFrequency event")
}
if len(events) > 0 {
// Translate cpu ticks to real time.
minTs := events[0].Ts
// Use floating point to avoid integer overflows.
freq := 1e9 / float64(p.ticksPerSec)
for i := range events {
ev := &events[i]
ev.Ts = Timestamp(float64(ev.Ts-minTs) * freq)
// Move syscalls to separate fake Ps.
if ev.Type == EvGoSysExit {
ev.P = SyscallP
}
}
}
if err := p.postProcessTrace(events); err != nil {
return 0, Trace{}, err
}
res := Trace{
Events: events,
Stacks: p.stacks,
Strings: p.strings,
PCs: p.pcs,
}
return ver, res, nil
}
// rawEvent is a helper type used during parsing.
type rawEvent struct {
typ byte
args []uint64
sargs []string
}
func (p *Parser) readHeader() (ver int, err error) {
// Read and validate trace header.
if len(p.data) < headerLength {
return 0, errors.New("trace too short")
}
ver, err = parseHeader(p.data[:headerLength])
if err != nil {
return 0, err
}
p.off += headerLength
switch ver {
case 1011, 1019:
// Note: When adding a new version, add canned traces
// from the old version to the test suite using mkcanned.bash.
default:
return 0, fmt.Errorf("unsupported trace file version %d.%d", ver/1000, ver%1000)
}
return ver, err
}
type proc struct {
pid int32
events []Event
// there are no more batches left
done bool
}
// parseRest reads per-P event batches and merges them into a single, consistent stream.
// The high level idea is as follows. Events within an individual batch are in
// correct order, because they are emitted by a single P. So we need to produce
// a correct interleaving of the batches. To do this we take first unmerged event
// from each batch (frontier). Then choose subset that is "ready" to be merged,
// that is, events for which all dependencies are already merged. Then we choose
// event with the lowest timestamp from the subset, merge it and repeat.
// This approach ensures that we form a consistent stream even if timestamps are
// incorrect (condition observed on some machines).
func (p *Parser) parseRest() ([]Event, error) {
// The ordering of CPU profile sample events in the data stream is based on
// when each run of the signal handler was able to acquire the spinlock,
// with original timestamps corresponding to when ReadTrace pulled the data
// off of the profBuf queue. Re-sort them by the timestamp we captured
// inside the signal handler.
sort.Sort((*eventList)(&p.cpuSamples))
var totalEvents uint64
allProcs := make([]proc, 0, len(p.pStates))
for m, pState := range p.pStates {
allProcs = append(allProcs, proc{pid: m})
for _, b := range pState.batches {
totalEvents += uint64(b.numEvents)
}
}
allProcs = append(allProcs, proc{pid: ProfileP, events: p.cpuSamples})
totalEvents += uint64(len(p.cpuSamples))
if totalEvents > math.MaxInt32 {
return nil, ErrTooManyEvents
}
events := make([]Event, 0, totalEvents)
// Merge events as long as at least one P has more events
gs := make(map[uint64]gState)
// Note: technically we don't need a priority queue here. We're only ever interested in the earliest elligible
// event, which means we just have to track the smallest element. However, in practice, the priority queue performs
// better, because for each event we only have to compute its state transition once, not on each iteration. If it
// was elligible before, it'll already be in the queue. Furthermore, on average, we only have one P to look at in
// each iteration, because all other Ps are already in the queue.
var frontier orderEventList
availableProcs := make([]*proc, len(allProcs))
for i := range allProcs {
availableProcs[i] = &allProcs[i]
}
for {
if p.progress != nil && len(events)%100_000 == 0 {
p.progress(0.5 + 0.5*(float64(len(events))/float64(cap(events))))
}
pidLoop:
for i := 0; i < len(availableProcs); i++ {
proc := availableProcs[i]
for len(proc.events) == 0 {
// Call loadBatch in a loop because sometimes batches are empty
evs, err := p.loadBatch(proc.pid)
if err == io.EOF {
// This P has no more events
proc.done = true
availableProcs[i], availableProcs[len(availableProcs)-1] = availableProcs[len(availableProcs)-1], availableProcs[i]
availableProcs = availableProcs[:len(availableProcs)-1]
// We swapped the element at i with another proc, so look at the index again
i--
continue pidLoop
} else if err != nil {
return nil, err
} else {
proc.events = evs
}
}
ev := &proc.events[0]
g, init, _ := stateTransition(ev)
// TODO(dh): This implementation matches the behavior of the upstream 'go tool trace', and works in
// practice, but has run into the following inconsistency during fuzzing: what happens if multiple Ps have
// events for the same G? While building the frontier we will check all of the events against the current
// state of the G. However, when we process the frontier, the state of the G changes, and a transition that
// was valid while building the frontier may no longer be valid when processing the frontier. Is this
// something that can happen for real, valid traces, or is this only possible with corrupt data?
if !transitionReady(g, gs[g], init) {
continue
}
proc.events = proc.events[1:]
availableProcs[i], availableProcs[len(availableProcs)-1] = availableProcs[len(availableProcs)-1], availableProcs[i]
availableProcs = availableProcs[:len(availableProcs)-1]
frontier.Push(orderEvent{*ev, proc})
// We swapped the element at i with another proc, so look at the index again
i--
}
if len(frontier) == 0 {
for i := range allProcs {
if !allProcs[i].done {
return nil, fmt.Errorf("no consistent ordering of events possible")
}
}
break
}
f := frontier.Pop()
// We're computing the state transition twice, once when computing the frontier, and now to apply the
// transition. This is fine because stateTransition is a pure function. Computing it again is cheaper than
// storing large items in the frontier.
g, init, next := stateTransition(&f.ev)
// Get rid of "Local" events, they are intended merely for ordering.
switch f.ev.Type {
case EvGoStartLocal:
f.ev.Type = EvGoStart
case EvGoUnblockLocal:
f.ev.Type = EvGoUnblock
case EvGoSysExitLocal:
f.ev.Type = EvGoSysExit
}
events = append(events, f.ev)
if err := transition(gs, g, init, next); err != nil {
return nil, err
}
availableProcs = append(availableProcs, f.proc)
}
// At this point we have a consistent stream of events.
// Make sure time stamps respect the ordering.
// The tests will skip (not fail) the test case if they see this error.
if !sort.IsSorted((*eventList)(&events)) {
return nil, ErrTimeOrder
}
// The last part is giving correct timestamps to EvGoSysExit events.
// The problem with EvGoSysExit is that actual syscall exit timestamp (ev.Args[2])
// is potentially acquired long before event emission. So far we've used
// timestamp of event emission (ev.Ts).
// We could not set ev.Ts = ev.Args[2] earlier, because it would produce
// seemingly broken timestamps (misplaced event).
// We also can't simply update the timestamp and resort events, because
// if timestamps are broken we will misplace the event and later report
// logically broken trace (instead of reporting broken timestamps).
lastSysBlock := make(map[uint64]Timestamp)
for _, ev := range events {
switch ev.Type {
case EvGoSysBlock, EvGoInSyscall:
lastSysBlock[ev.G] = ev.Ts
case EvGoSysExit:
ts := Timestamp(ev.Args[2])
if ts == 0 {
continue
}
block := lastSysBlock[ev.G]
if block == 0 {
return nil, fmt.Errorf("stray syscall exit")
}
if ts < block {
return nil, ErrTimeOrder
}
ev.Ts = ts
}
}
sort.Stable((*eventList)(&events))
return events, nil
}
// indexAndPartiallyParse records the offsets of batches and parses strings and CPU samples.
func (p *Parser) indexAndPartiallyParse() error {
// Read events.
var raw rawEvent
for n := uint64(0); ; n++ {
if p.progress != nil && n%1_000_000 == 0 {
p.progress(0.5 * (float64(p.off) / float64(len(p.data))))
}
err := p.readRawEvent(skipArgs|skipStrings|trackBatches, &raw)
if err == io.EOF {
break
}
if err != nil {
return err
}
if raw.typ == EvNone {
continue
}
if raw.typ == EvCPUSample {
e := Event{Type: raw.typ}
argOffset := 1
narg := argNum(&raw)
if len(raw.args) != narg {
return fmt.Errorf("CPU sample has wrong number of arguments: want %d, got %d", narg, len(raw.args))
}
for i := argOffset; i < narg; i++ {
if i == narg-1 {
e.StkID = uint32(raw.args[i])
} else {
e.Args[i-argOffset] = raw.args[i]
}
}
e.Ts = Timestamp(e.Args[0])
e.P = int32(e.Args[1])
e.G = e.Args[2]
e.Args[0] = 0
// Most events are written out by the active P at the exact
// moment they describe. CPU profile samples are different
// because they're written to the tracing log after some delay,
// by a separate worker goroutine, into a separate buffer.
//
// We keep these in their own batch until all of the batches are
// merged in timestamp order. We also (right before the merge)
// re-sort these events by the timestamp captured in the
// profiling signal handler.
//
// Note that we're not concerned about the memory usage of storing all CPU samples during the indexing
// phase. There are orders of magnitude fewer CPU samples than runtime events.
p.cpuSamples = append(p.cpuSamples, e)
}
}
if p.progress != nil {
p.progress(0.5)
}
return nil
}
const (
skipArgs = 1 << iota
skipStrings
trackBatches
)
//gcassert:inline
func (p *Parser) readByte() (byte, bool) {
if p.off < len(p.data) && p.off >= 0 {
b := p.data[p.off]
p.off++
return b, true
} else {
return 0, false
}
}
//gcassert:inline
func (p *Parser) readFull(b []byte) bool {
if p.off >= len(p.data) || p.off < 0 || p.off+len(b) > len(p.data) {
// p.off < 0 is impossible but makes BCE happy.
// We do fail outright if there's not enough data, we don't care about partial results.
return false
}
copy(b, p.data[p.off:])
p.off += len(b)
return true
}
func (p *Parser) readRawEvent(flags uint, ev *rawEvent) error {
// The number of arguments is encoded using two bits and can thus only represent the values 0–3. The value 3 (on the
// wire) indicates that arguments are prefixed by their byte length, to encode >=3 arguments.
const inlineArgs = 3
// Read event type and number of arguments (1 byte).
b, ok := p.readByte()
if !ok {
return io.EOF
}
typ := b << 2 >> 2
// Most events have a timestamp before the actual arguments, so we add 1 and parse it like it's the first argument.
// EvString has a special format and the number of arguments doesn't matter. EvBatch writes '1' as the number of
// arguments, but actually has two: a pid and a timestamp, but here the timestamp is the second argument, not the
// first; adding 1 happens to come up with the correct number, but it doesn't matter, because EvBatch has custom
// logic for parsing.
//
// Note that because we're adding 1, inlineArgs == 3 describes the largest number of logical arguments that isn't
// length-prefixed, even though the value 3 on the wire indicates length-prefixing. For us, that becomes narg == 4.
narg := b>>6 + 1
if typ == EvNone || typ >= EvCount || EventDescriptions[typ].minVersion > p.ver {
return fmt.Errorf("unknown event type %d", typ)
}
switch typ {
case EvString:
if flags&skipStrings != 0 {
// String dictionary entry [ID, length, string].
if !p.discardVal() {
return errMalformedVarint
}
ln, ok := p.readVal()
if !ok {
return errMalformedVarint
}
if !p.discard(ln) {
return fmt.Errorf("failed to read trace: %w", io.EOF)
}
} else {
// String dictionary entry [ID, length, string].
id, ok := p.readVal()
if !ok {
return errMalformedVarint
}
if id == 0 {
return errors.New("string has invalid id 0")
}
if p.strings[id] != "" {
return fmt.Errorf("string has duplicate id %d", id)
}
var ln uint64
ln, ok = p.readVal()
if !ok {
return errMalformedVarint
}
if ln == 0 {
return errors.New("string has invalid length 0")
}
if ln > 1e6 {
return fmt.Errorf("string has too large length %d", ln)
}
buf := make([]byte, ln)
if !p.readFull(buf) {
return fmt.Errorf("failed to read trace: %w", io.ErrUnexpectedEOF)
}
p.strings[id] = string(buf)
}
ev.typ = EvNone
return nil
case EvBatch:
if want := byte(2); narg != want {
return fmt.Errorf("EvBatch has wrong number of arguments: got %d, want %d", narg, want)
}
// -1 because we've already read the first byte of the batch
off := p.off - 1
pid, ok := p.readVal()
if !ok {
return errMalformedVarint
}
if pid != math.MaxUint64 && pid > math.MaxInt32 {
return fmt.Errorf("processor ID %d is larger than maximum of %d", pid, uint64(math.MaxUint))
}
var pid32 int32
if pid == math.MaxUint64 {
pid32 = -1
} else {
pid32 = int32(pid)
}
if flags&trackBatches != 0 {
p.pState(pid32).batches = append(p.pState(pid32).batches, batch{offset: off})
p.curP = pid32
}
v, ok := p.readVal()
if !ok {
return errMalformedVarint
}
*ev = rawEvent{typ: EvBatch, args: p.args[:0]}
ev.args = append(ev.args, pid, v)
return nil
default:
if flags&trackBatches != 0 {
batches := p.pState(p.curP).batches
if len(batches) == 0 {
return fmt.Errorf("read event %d with current P of %d, but P has no batches yet", typ, p.curP)
}
batches[len(batches)-1].numEvents++
}
*ev = rawEvent{typ: typ, args: p.args[:0]}
if narg <= inlineArgs {
if flags&skipArgs == 0 {
for i := 0; i < int(narg); i++ {
v, ok := p.readVal()
if !ok {
return fmt.Errorf("failed to read event %d argument: %w", typ, errMalformedVarint)
}
ev.args = append(ev.args, v)
}
} else {
for i := 0; i < int(narg); i++ {
if !p.discardVal() {
return fmt.Errorf("failed to read event %d argument: %w", typ, errMalformedVarint)
}
}
}
} else {
// More than inlineArgs args, the first value is length of the event in bytes.
//
// OPT(dh): looking at the runtime code, the length seems to be limited to < 128, i.e. a single byte. we
// don't have to use readVal. However, there are so few events with more than 4 arguments that calling
// readVal is barely noticeable.
v, ok := p.readVal()
if !ok {
return fmt.Errorf("failed to read event %d argument: %w", typ, errMalformedVarint)
}
if limit := uint64(2048); v > limit {
// At the time of Go 1.19, v seems to be at most 128. Set 2048 as a generous upper limit and guard
// against malformed traces.
return fmt.Errorf("failed to read event %d argument: length-prefixed argument too big: %d bytes, limit is %d", typ, v, limit)
}
if flags&skipArgs == 0 || typ == EvCPUSample {
buf := p.bigArgsBuf
if uint64(cap(buf)) >= v {
buf = buf[:v]
} else {
buf = make([]byte, v)
p.bigArgsBuf = buf[:0]
}
if !p.readFull(buf) {
return fmt.Errorf("failed to read trace: %w", io.ErrUnexpectedEOF)
}
for len(buf) > 0 {
var v uint64
var ok bool
v, buf, ok = readValFrom(buf)
if !ok {
return errMalformedVarint
}
ev.args = append(ev.args, v)
}
} else {
// Skip over arguments
if !p.discard(v) {
return fmt.Errorf("failed to read trace: %w", io.EOF)
}
}
if typ == EvUserLog {
// EvUserLog records are followed by a value string
if flags&skipArgs == 0 {
// Read string
s, err := p.readStr()
if err != nil {
return err
}
ev.sargs = append(ev.sargs, s)
} else {
// Skip string
v, ok := p.readVal()
if !ok {
return errMalformedVarint
}
if !p.discard(v) {
return io.EOF
}
}
}
}
p.args = ev.args[:0]
return nil
}
}
func (p *Parser) loadBatch(pid int32) ([]Event, error) {
pState := p.pState(pid)
offsets := pState.batches
if len(offsets) == 0 {
return nil, io.EOF
}
n := offsets[0].numEvents
offset := offsets[0].offset
offsets = offsets[1:]
pState.batches = offsets
p.off = offset
events := pState.slice[:0]
if cap(events) < n {
events = make([]Event, 0, n)
pState.slice = events
}
gotHeader := false
var raw rawEvent
var ev Event
for {
err := p.readRawEvent(0, &raw)
if err == io.EOF {
break
}
if err != nil {
return nil, err
}
if raw.typ == EvNone || raw.typ == EvCPUSample {
continue
}
if raw.typ == EvBatch {
if gotHeader {
break
} else {
gotHeader = true
}
}
err = p.parseEvent(&raw, &ev)
if err != nil {
return nil, err
}
if ev.Type != EvNone {
events = append(events, ev)
}
}
return events, nil
}
func (p *Parser) readStr() (s string, err error) {
sz, ok := p.readVal()
if !ok {
return "", errMalformedVarint
}
if sz == 0 {
return "", nil
}
if sz > 1e6 {
return "", fmt.Errorf("string is too large (len=%d)", sz)
}
buf := make([]byte, sz)
if !p.readFull(buf) {
return "", fmt.Errorf("failed to read trace: %w", io.ErrUnexpectedEOF)
}
return string(buf), nil
}
// parseHeader parses trace header of the form "go 1.7 trace\x00\x00\x00\x00"
// and returns parsed version as 1007.
func parseHeader(buf []byte) (int, error) {
if len(buf) != headerLength {
return 0, errors.New("bad header length")
}
if buf[0] != 'g' || buf[1] != 'o' || buf[2] != ' ' ||
buf[3] < '1' || buf[3] > '9' ||
buf[4] != '.' ||
buf[5] < '1' || buf[5] > '9' {
return 0, errors.New("not a trace file")
}
ver := int(buf[5] - '0')
i := 0
for ; buf[6+i] >= '0' && buf[6+i] <= '9' && i < 2; i++ {
ver = ver*10 + int(buf[6+i]-'0')
}
ver += int(buf[3]-'0') * 1000
if !bytes.Equal(buf[6+i:], []byte(" trace\x00\x00\x00\x00")[:10-i]) {
return 0, errors.New("not a trace file")
}
return ver, nil
}
// parseEvent transforms raw events into events.
// It does analyze and verify per-event-type arguments.
func (p *Parser) parseEvent(raw *rawEvent, ev *Event) error {
desc := &EventDescriptions[raw.typ]
if desc.Name == "" {
return fmt.Errorf("missing description for event type %d", raw.typ)
}
narg := argNum(raw)
if len(raw.args) != narg {
return fmt.Errorf("%s has wrong number of arguments: want %d, got %d", desc.Name, narg, len(raw.args))
}
switch raw.typ {
case EvBatch:
p.pState(p.lastP).lastG = p.lastG
if raw.args[0] != math.MaxUint64 && raw.args[0] > math.MaxInt32 {
return fmt.Errorf("processor ID %d is larger than maximum of %d", raw.args[0], uint64(math.MaxInt32))
}
if raw.args[0] == math.MaxUint64 {
p.lastP = -1
} else {
p.lastP = int32(raw.args[0])
}
p.lastG = p.pState(p.lastP).lastG
p.lastTs = Timestamp(raw.args[1])
case EvFrequency:
p.ticksPerSec = int64(raw.args[0])
if p.ticksPerSec <= 0 {
// The most likely cause for this is tick skew on different CPUs.
// For example, solaris/amd64 seems to have wildly different
// ticks on different CPUs.
return ErrTimeOrder
}
case EvTimerGoroutine:
// Timer goroutines haven't been used since 2019, see https://go.dev/cl/171884
return errors.New("unsupported event EvTimerGoroutine")
case EvStack:
if len(raw.args) < 2 {
return fmt.Errorf("EvStack has wrong number of arguments: want at least 2, got %d", len(raw.args))
}
size := raw.args[1]
if size > 1000 {
return fmt.Errorf("EvStack has bad number of frames: %d", size)
}
want := 2 + 4*size
if uint64(len(raw.args)) != want {
return fmt.Errorf("EvStack has wrong number of arguments: want %d, got %d", want, len(raw.args))
}
id := uint32(raw.args[0])
if id != 0 && size > 0 {
stk := p.allocateStack(size)
for i := 0; i < int(size); i++ {
pc := raw.args[2+i*4+0]
fn := raw.args[2+i*4+1]
file := raw.args[2+i*4+2]
line := raw.args[2+i*4+3]
stk[i] = pc
if _, ok := p.pcs[pc]; !ok {
p.pcs[pc] = Frame{PC: pc, Fn: p.strings[fn], File: p.strings[file], Line: int(line)}
}
}
p.stacks[id] = stk
}
case EvCPUSample:
// These events get parsed during the indexing step and don't strictly belong to the batch.
default:
*ev = Event{Type: raw.typ, P: p.lastP, G: p.lastG, Link: -1}
var argOffset int
ev.Ts = p.lastTs + Timestamp(raw.args[0])
argOffset = 1
p.lastTs = ev.Ts
for i := argOffset; i < narg; i++ {
if i == narg-1 && desc.Stack {
ev.StkID = uint32(raw.args[i])
} else {
ev.Args[i-argOffset] = raw.args[i]
}
}
switch raw.typ {
case EvGoStart, EvGoStartLocal, EvGoStartLabel:
p.lastG = ev.Args[0]
ev.G = p.lastG
case EvGoEnd, EvGoStop, EvGoSched, EvGoPreempt,
EvGoSleep, EvGoBlock, EvGoBlockSend, EvGoBlockRecv,
EvGoBlockSelect, EvGoBlockSync, EvGoBlockCond, EvGoBlockNet,
EvGoSysBlock, EvGoBlockGC:
p.lastG = 0
case EvGoSysExit, EvGoWaiting, EvGoInSyscall:
ev.G = ev.Args[0]
case EvUserTaskCreate:
// e.Args 0: taskID, 1:parentID, 2:nameID
case EvUserRegion:
// e.Args 0: taskID, 1: mode, 2:nameID
case EvUserLog:
// e.Args 0: taskID, 1:keyID, 2: stackID, 3: messageID
// raw.sargs 0: message
// EvUserLog contains the message inline, not as a string ID. We turn it into an ID. String IDs are
// (currently) sequentially allocated and start from zero, so we count backwards starting from MaxUint64,
// hoping runtime IDs and our IDs will never meet.
p.logMessageID--
p.strings[p.logMessageID] = raw.sargs[0]
ev.Args[3] = p.logMessageID
}
return nil
}
ev.Type = EvNone
return nil
}
// ErrTimeOrder is returned by Parse when the trace contains
// time stamps that do not respect actual event ordering.
var ErrTimeOrder = errors.New("time stamps out of order")
// postProcessTrace does inter-event verification and information restoration.
// The resulting trace is guaranteed to be consistent
// (for example, a P does not run two Gs at the same time, or a G is indeed
// blocked before an unblock event).
func (p *Parser) postProcessTrace(events []Event) error {
const (
gDead = iota
gRunnable
gRunning
gWaiting
)
type gdesc struct {
state int
ev *Event
evStart *Event
evCreate *Event
evMarkAssist *Event
}
type pdesc struct {
running bool
g uint64
evSweep *Event
}
gs := make(map[uint64]gdesc)
ps := make(map[int32]pdesc)
tasks := make(map[uint64]*Event) // task id to task creation events
activeRegions := make(map[uint64][]*Event) // goroutine id to stack of regions
gs[0] = gdesc{state: gRunning}
var evGC, evSTW *Event
checkRunning := func(p pdesc, g gdesc, ev *Event, allowG0 bool) error {
name := EventDescriptions[ev.Type].Name
if g.state != gRunning {
return fmt.Errorf("g %d is not running while %s (time %d)", ev.G, name, ev.Ts)
}
if p.g != ev.G {