github.com/bir3/gocompiler@v0.9.2202/src/internal/trace/parser.go (about) 1 // Copyright 2014 The Go Authors. All rights reserved. 2 // Use of this source code is governed by a BSD-style 3 // license that can be found in the LICENSE file. 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 // Event describes one event in the trace. 35 type Event struct { 36 Off int // offset in input file (for debugging and error reporting) 37 Type byte // one of Ev* 38 seq int64 // sequence number 39 Ts int64 // timestamp in nanoseconds 40 P int // P on which the event happened (can be one of TimerP, NetpollP, SyscallP) 41 G uint64 // G on which the event happened 42 StkID uint64 // unique stack ID 43 Stk []*Frame // stack trace (can be empty) 44 Args [3]uint64 // event-type-specific arguments 45 SArgs []string // event-type-specific string args 46 // linked event (can be nil), depends on event type: 47 // for GCStart: the GCStop 48 // for GCSTWStart: the GCSTWDone 49 // for GCSweepStart: the GCSweepDone 50 // for GoCreate: first GoStart of the created goroutine 51 // for GoStart/GoStartLabel: the associated GoEnd, GoBlock or other blocking event 52 // for GoSched/GoPreempt: the next GoStart 53 // for GoBlock and other blocking events: the unblock event 54 // for GoUnblock: the associated GoStart 55 // for blocking GoSysCall: the associated GoSysExit 56 // for GoSysExit: the next GoStart 57 // for GCMarkAssistStart: the associated GCMarkAssistDone 58 // for UserTaskCreate: the UserTaskEnd 59 // for UserRegion: if the start region, the corresponding UserRegion end event 60 Link *Event 61 } 62 63 // Frame is a frame in stack traces. 64 type Frame struct { 65 PC uint64 66 Fn string 67 File string 68 Line int 69 } 70 71 const ( 72 // Special P identifiers: 73 FakeP = 1000000 + iota 74 TimerP // depicts timer unblocks 75 NetpollP // depicts network unblocks 76 SyscallP // depicts returns from syscalls 77 GCP // depicts GC state 78 ProfileP // depicts recording of CPU profile samples 79 ) 80 81 // ParseResult is the result of Parse. 82 type ParseResult struct { 83 // Events is the sorted list of Events in the trace. 84 Events []*Event 85 // Stacks is the stack traces keyed by stack IDs from the trace. 86 Stacks map[uint64][]*Frame 87 } 88 89 // Parse parses, post-processes and verifies the trace. 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 // parse parses, post-processes and verifies the trace. It returns the 102 // trace version and the list of events. 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 // Attach stack traces. 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 // rawEvent is a helper type used during parsing. 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 // Read and validate trace header. 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 // readTrace does wire-format parsing and verification. 152 // It does not care about specific event types and argument meaning. 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 // Note: When adding a new version, confirm that canned traces from the 162 // old version are part of the test suite. Add them using mkcanned.bash. 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 // Read events. 170 var buf [16]byte 171 strings = make(map[uint64]string) 172 for { 173 // Read event type and number of arguments (1 byte). 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 // String dictionary entry [ID, length, string]. 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 // More than inlineArgs args, the first value is length of the event in bytes. 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: // EvUserLog records are followed by a value string of length ev.args[len(ev.args)-1] 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 // parseHeader parses trace header of the form "go 1.7 trace\x00\x00\x00\x00" 299 // and returns parsed version as 1007. 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 // Parse events transforms raw events into events. 323 // It does analyze and verify per-event-type arguments. 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) // last goroutine running on P 330 stacks = make(map[uint64][]*Frame) 331 batches := make(map[int][]*Event) // events by P 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 // The most likely cause for this is tick skew on different CPUs. 359 // For example, solaris/amd64 seems to have wildly different 360 // ticks on different CPUs. 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 // Can't make any assumptions. 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 // e.Args 0: taskID, 1:parentID, 2:nameID 463 e.SArgs = []string{strings[e.Args[2]]} 464 case EvUserRegion: 465 // e.Args 0: taskID, 1: mode, 2:nameID 466 e.SArgs = []string{strings[e.Args[2]]} 467 case EvUserLog: 468 // e.Args 0: taskID, 1:keyID, 2: stackID 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 // Most events are written out by the active P at the exact 481 // moment they describe. CPU profile samples are different 482 // because they're written to the tracing log after some delay, 483 // by a separate worker goroutine, into a separate buffer. 484 // 485 // We keep these in their own batch until all of the batches are 486 // merged in timestamp order. We also (right before the merge) 487 // re-sort these events by the timestamp captured in the 488 // profiling signal handler. 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 // Translate cpu ticks to real time. 521 minTs := events[0].Ts 522 // Use floating point to avoid integer overflows. 523 freq := 1e9 / float64(ticksPerSec) 524 for _, ev := range events { 525 ev.Ts = int64(float64(ev.Ts-minTs) * freq) 526 // Move timers and syscalls to separate fake Ps. 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 // removeFutile removes all constituents of futile wakeups (block, unblock, start). 539 // For example, a goroutine was unblocked on a mutex, but another goroutine got 540 // ahead and acquired the mutex before the first goroutine is scheduled, 541 // so the first goroutine has to block again. Such wakeups happen on buffered 542 // channels and sync.Mutex, but are generally not interesting for end user. 543 func removeFutile(events []*Event) []*Event { 544 // Two non-trivial aspects: 545 // 1. A goroutine can be preempted during a futile wakeup and migrate to another P. 546 // We want to remove all of that. 547 // 2. Tracing can start in the middle of a futile wakeup. 548 // That is, we can see a futile wakeup event w/o the actual wakeup before it. 549 // postProcessTrace runs after us and ensures that we leave the trace in a consistent state. 550 551 // Phase 1: determine futile wakeup sequences. 552 type G struct { 553 futile bool 554 wakeup []*Event // wakeup sequence (subject for removal) 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 // Phase 2: remove futile wakeup sequences. 584 newEvents := events[:0] // overwrite the original slice 585 for _, ev := range events { 586 if !futile[ev] { 587 newEvents = append(newEvents, ev) 588 } 589 } 590 return newEvents 591 } 592 593 // ErrTimeOrder is returned by Parse when the trace contains 594 // time stamps that do not respect actual event ordering. 595 var ErrTimeOrder = fmt.Errorf("time stamps out of order") 596 597 // postProcessTrace does inter-event verification and information restoration. 598 // The resulting trace is guaranteed to be consistent 599 // (for example, a P does not run two Gs at the same time, or a G is indeed 600 // blocked before an unblock event). 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) // task id to task creation events 625 activeRegions := make(map[uint64][]*Event) // goroutine id to stack of regions 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 // Attribute this to the global GC state. 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 // Before 1.10, EvSTWStart was per-P. 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 // Before 1.10, EvSTWDone was per-P. 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 // Unlike most events, mark assists can be in progress when a 707 // goroutine starts tracing, so we can't report an error here. 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 // +1 because symbolizer expects return pc. 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 { // flush all active regions 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 { // region start 856 activeRegions[ev.G] = append(regions, ev) // push 857 } else if mode == 1 { // region end 858 n := len(regions) 859 if n > 0 { // matching region start event is in the trace. 860 s := regions[n-1] 861 if s.Args[0] != ev.Args[0] || s.SArgs[0] != ev.SArgs[0] { // task id, region name mismatch 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 // Link region start event with span end event 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 // TODO(dvyukov): restore stacks for EvGoStart events. 883 // TODO(dvyukov): test that all EvGoStart events has non-nil Link. 884 885 return nil 886 } 887 888 // symbolize attaches func/file/line info to stack traces. 889 func symbolize(events []*Event, bin string) error { 890 // First, collect and dedup all pcs. 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 // Start addr2line. 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 // Write all pcs to addr2line. 916 // Need to copy pcs to an array, because map iteration order is non-deterministic. 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 // Read in answers. 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 // Replace frames in events array. 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 // readVal reads unsigned base-128 value from r. 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 // Print dumps events to stdout. For debugging. 981 func Print(events []*Event) { 982 for _, ev := range events { 983 PrintEvent(ev) 984 } 985 } 986 987 // PrintEvent dumps the event to stdout. For debugging. 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 // argNum returns total number of args for the event accounting for timestamps, 1006 // sequence numbers and differences between trace format versions. 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++ // there was an unused arg before 1.7 1020 } 1021 return narg 1022 } 1023 narg++ // timestamp 1024 if ver < 1007 { 1025 narg++ // sequence 1026 } 1027 switch raw.typ { 1028 case EvGCSweepDone: 1029 if ver < 1009 { 1030 narg -= 2 // 1.9 added two arguments 1031 } 1032 case EvGCStart, EvGoStart, EvGoUnblock: 1033 if ver < 1007 { 1034 narg-- // 1.7 added an additional seq arg 1035 } 1036 case EvSTWStart: 1037 if ver < 1010 { 1038 narg-- // 1.10 added an argument 1039 } 1040 } 1041 return narg 1042 } 1043 1044 // BreakTimestampsForTesting causes the parser to randomly alter timestamps (for testing of broken cputicks). 1045 var BreakTimestampsForTesting bool 1046 1047 // Event types in the trace. 1048 // Verbatim copy from src/runtime/trace.go with the "trace" prefix removed. 1049 const ( 1050 EvNone = 0 // unused 1051 EvBatch = 1 // start of per-P batch of events [pid, timestamp] 1052 EvFrequency = 2 // contains tracer timer frequency [frequency (ticks per second)] 1053 EvStack = 3 // stack [stack id, number of PCs, array of {PC, func string ID, file string ID, line}] 1054 EvGomaxprocs = 4 // current value of GOMAXPROCS [timestamp, GOMAXPROCS, stack id] 1055 EvProcStart = 5 // start of P [timestamp, thread id] 1056 EvProcStop = 6 // stop of P [timestamp] 1057 EvGCStart = 7 // GC start [timestamp, seq, stack id] 1058 EvGCDone = 8 // GC done [timestamp] 1059 EvSTWStart = 9 // GC mark termination start [timestamp, kind] 1060 EvSTWDone = 10 // GC mark termination done [timestamp] 1061 EvGCSweepStart = 11 // GC sweep start [timestamp, stack id] 1062 EvGCSweepDone = 12 // GC sweep done [timestamp, swept, reclaimed] 1063 EvGoCreate = 13 // goroutine creation [timestamp, new goroutine id, new stack id, stack id] 1064 EvGoStart = 14 // goroutine starts running [timestamp, goroutine id, seq] 1065 EvGoEnd = 15 // goroutine ends [timestamp] 1066 EvGoStop = 16 // goroutine stops (like in select{}) [timestamp, stack] 1067 EvGoSched = 17 // goroutine calls Gosched [timestamp, stack] 1068 EvGoPreempt = 18 // goroutine is preempted [timestamp, stack] 1069 EvGoSleep = 19 // goroutine calls Sleep [timestamp, stack] 1070 EvGoBlock = 20 // goroutine blocks [timestamp, stack] 1071 EvGoUnblock = 21 // goroutine is unblocked [timestamp, goroutine id, seq, stack] 1072 EvGoBlockSend = 22 // goroutine blocks on chan send [timestamp, stack] 1073 EvGoBlockRecv = 23 // goroutine blocks on chan recv [timestamp, stack] 1074 EvGoBlockSelect = 24 // goroutine blocks on select [timestamp, stack] 1075 EvGoBlockSync = 25 // goroutine blocks on Mutex/RWMutex [timestamp, stack] 1076 EvGoBlockCond = 26 // goroutine blocks on Cond [timestamp, stack] 1077 EvGoBlockNet = 27 // goroutine blocks on network [timestamp, stack] 1078 EvGoSysCall = 28 // syscall enter [timestamp, stack] 1079 EvGoSysExit = 29 // syscall exit [timestamp, goroutine id, seq, real timestamp] 1080 EvGoSysBlock = 30 // syscall blocks [timestamp] 1081 EvGoWaiting = 31 // denotes that goroutine is blocked when tracing starts [timestamp, goroutine id] 1082 EvGoInSyscall = 32 // denotes that goroutine is in syscall when tracing starts [timestamp, goroutine id] 1083 EvHeapAlloc = 33 // gcController.heapLive change [timestamp, heap live bytes] 1084 EvHeapGoal = 34 // gcController.heapGoal change [timestamp, heap goal bytes] 1085 EvTimerGoroutine = 35 // denotes timer goroutine [timer goroutine id] 1086 EvFutileWakeup = 36 // denotes that the previous wakeup of this goroutine was futile [timestamp] 1087 EvString = 37 // string dictionary entry [ID, length, string] 1088 EvGoStartLocal = 38 // goroutine starts running on the same P as the last event [timestamp, goroutine id] 1089 EvGoUnblockLocal = 39 // goroutine is unblocked on the same P as the last event [timestamp, goroutine id, stack] 1090 EvGoSysExitLocal = 40 // syscall exit on the same P as the last event [timestamp, goroutine id, real timestamp] 1091 EvGoStartLabel = 41 // goroutine starts running with label [timestamp, goroutine id, seq, label string id] 1092 EvGoBlockGC = 42 // goroutine blocks on GC assist [timestamp, stack] 1093 EvGCMarkAssistStart = 43 // GC mark assist start [timestamp, stack] 1094 EvGCMarkAssistDone = 44 // GC mark assist done [timestamp] 1095 EvUserTaskCreate = 45 // trace.NewTask [timestamp, internal task id, internal parent id, name string, stack] 1096 EvUserTaskEnd = 46 // end of task [timestamp, internal task id, stack] 1097 EvUserRegion = 47 // trace.WithRegion [timestamp, internal task id, mode(0:start, 1:end), name string, stack] 1098 EvUserLog = 48 // trace.Log [timestamp, internal id, key string id, stack, value string] 1099 EvCPUSample = 49 // CPU profiling sample [timestamp, real timestamp, real P id (-1 when absent), goroutine id, stack] 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 // string arguments 1109 }{ 1110 EvNone: {"None", 1005, false, []string{}, nil}, 1111 EvBatch: {"Batch", 1005, false, []string{"p", "ticks"}, nil}, // in 1.5 format it was {"p", "seq", "ticks"} 1112 EvFrequency: {"Frequency", 1005, false, []string{"freq"}, nil}, // in 1.5 format it was {"freq", "unused"} 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}, // in 1.5 format it was {} 1118 EvGCDone: {"GCDone", 1005, false, []string{}, nil}, 1119 EvSTWStart: {"STWStart", 1005, false, []string{"kindid"}, []string{"kind"}}, // <= 1.9, args was {} (implicitly {0}) 1120 EvSTWDone: {"STWDone", 1005, false, []string{}, nil}, 1121 EvGCSweepStart: {"GCSweepStart", 1005, true, []string{}, nil}, 1122 EvGCSweepDone: {"GCSweepDone", 1005, false, []string{"swept", "reclaimed"}, nil}, // before 1.9, format was {} 1123 EvGoCreate: {"GoCreate", 1005, true, []string{"g", "stack"}, nil}, 1124 EvGoStart: {"GoStart", 1005, false, []string{"g", "seq"}, nil}, // in 1.5 format it was {"g"} 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}, // in 1.5 format it was {"g"} 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}, // in 1.5 format it was {"g", "unused"} 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 // Copied from src/runtime/proc.go:stwReasonStrings in Go 1.21. 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 }