github.com/JimmyHuang454/JLS-go@v0.0.0-20230831150107-90d536585ba0/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 // readTrace does wire-format parsing and verification. 140 // It does not care about specific event types and argument meaning. 141 func readTrace(r io.Reader) (ver int, events []rawEvent, strings map[uint64]string, err error) { 142 // Read and validate trace header. 143 var buf [16]byte 144 off, err := io.ReadFull(r, buf[:]) 145 if err != nil { 146 err = fmt.Errorf("failed to read header: read %v, err %v", off, err) 147 return 148 } 149 ver, err = parseHeader(buf[:]) 150 if err != nil { 151 return 152 } 153 switch ver { 154 case 1005, 1007, 1008, 1009, 1010, 1011, 1019: 155 // Note: When adding a new version, confirm that canned traces from the 156 // old version are part of the test suite. Add them using mkcanned.bash. 157 break 158 default: 159 err = fmt.Errorf("unsupported trace file version %v.%v (update Go toolchain) %v", ver/1000, ver%1000, ver) 160 return 161 } 162 163 // Read events. 164 strings = make(map[uint64]string) 165 for { 166 // Read event type and number of arguments (1 byte). 167 off0 := off 168 var n int 169 n, err = r.Read(buf[:1]) 170 if err == io.EOF { 171 err = nil 172 break 173 } 174 if err != nil || n != 1 { 175 err = fmt.Errorf("failed to read trace at offset 0x%x: n=%v err=%v", off0, n, err) 176 return 177 } 178 off += n 179 typ := buf[0] << 2 >> 2 180 narg := buf[0]>>6 + 1 181 inlineArgs := byte(4) 182 if ver < 1007 { 183 narg++ 184 inlineArgs++ 185 } 186 if typ == EvNone || typ >= EvCount || EventDescriptions[typ].minVersion > ver { 187 err = fmt.Errorf("unknown event type %v at offset 0x%x", typ, off0) 188 return 189 } 190 if typ == EvString { 191 // String dictionary entry [ID, length, string]. 192 var id uint64 193 id, off, err = readVal(r, off) 194 if err != nil { 195 return 196 } 197 if id == 0 { 198 err = fmt.Errorf("string at offset %d has invalid id 0", off) 199 return 200 } 201 if strings[id] != "" { 202 err = fmt.Errorf("string at offset %d has duplicate id %v", off, id) 203 return 204 } 205 var ln uint64 206 ln, off, err = readVal(r, off) 207 if err != nil { 208 return 209 } 210 if ln == 0 { 211 err = fmt.Errorf("string at offset %d has invalid length 0", off) 212 return 213 } 214 if ln > 1e6 { 215 err = fmt.Errorf("string at offset %d has too large length %v", off, ln) 216 return 217 } 218 buf := make([]byte, ln) 219 var n int 220 n, err = io.ReadFull(r, buf) 221 if err != nil { 222 err = fmt.Errorf("failed to read trace at offset %d: read %v, want %v, error %v", off, n, ln, err) 223 return 224 } 225 off += n 226 strings[id] = string(buf) 227 continue 228 } 229 ev := rawEvent{typ: typ, off: off0} 230 if narg < inlineArgs { 231 for i := 0; i < int(narg); i++ { 232 var v uint64 233 v, off, err = readVal(r, off) 234 if err != nil { 235 err = fmt.Errorf("failed to read event %v argument at offset %v (%v)", typ, off, err) 236 return 237 } 238 ev.args = append(ev.args, v) 239 } 240 } else { 241 // More than inlineArgs args, the first value is length of the event in bytes. 242 var v uint64 243 v, off, err = readVal(r, off) 244 if err != nil { 245 err = fmt.Errorf("failed to read event %v argument at offset %v (%v)", typ, off, err) 246 return 247 } 248 evLen := v 249 off1 := off 250 for evLen > uint64(off-off1) { 251 v, off, err = readVal(r, off) 252 if err != nil { 253 err = fmt.Errorf("failed to read event %v argument at offset %v (%v)", typ, off, err) 254 return 255 } 256 ev.args = append(ev.args, v) 257 } 258 if evLen != uint64(off-off1) { 259 err = fmt.Errorf("event has wrong length at offset 0x%x: want %v, got %v", off0, evLen, off-off1) 260 return 261 } 262 } 263 switch ev.typ { 264 case EvUserLog: // EvUserLog records are followed by a value string of length ev.args[len(ev.args)-1] 265 var s string 266 s, off, err = readStr(r, off) 267 ev.sargs = append(ev.sargs, s) 268 } 269 events = append(events, ev) 270 } 271 return 272 } 273 274 func readStr(r io.Reader, off0 int) (s string, off int, err error) { 275 var sz uint64 276 sz, off, err = readVal(r, off0) 277 if err != nil || sz == 0 { 278 return "", off, err 279 } 280 if sz > 1e6 { 281 return "", off, fmt.Errorf("string at offset %d is too large (len=%d)", off, sz) 282 } 283 buf := make([]byte, sz) 284 n, err := io.ReadFull(r, buf) 285 if err != nil || sz != uint64(n) { 286 return "", off + n, fmt.Errorf("failed to read trace at offset %d: read %v, want %v, error %v", off, n, sz, err) 287 } 288 return string(buf), off + n, nil 289 } 290 291 // parseHeader parses trace header of the form "go 1.7 trace\x00\x00\x00\x00" 292 // and returns parsed version as 1007. 293 func parseHeader(buf []byte) (int, error) { 294 if len(buf) != 16 { 295 return 0, fmt.Errorf("bad header length") 296 } 297 if buf[0] != 'g' || buf[1] != 'o' || buf[2] != ' ' || 298 buf[3] < '1' || buf[3] > '9' || 299 buf[4] != '.' || 300 buf[5] < '1' || buf[5] > '9' { 301 return 0, fmt.Errorf("not a trace file") 302 } 303 ver := int(buf[5] - '0') 304 i := 0 305 for ; buf[6+i] >= '0' && buf[6+i] <= '9' && i < 2; i++ { 306 ver = ver*10 + int(buf[6+i]-'0') 307 } 308 ver += int(buf[3]-'0') * 1000 309 if !bytes.Equal(buf[6+i:], []byte(" trace\x00\x00\x00\x00")[:10-i]) { 310 return 0, fmt.Errorf("not a trace file") 311 } 312 return ver, nil 313 } 314 315 // Parse events transforms raw events into events. 316 // It does analyze and verify per-event-type arguments. 317 func parseEvents(ver int, rawEvents []rawEvent, strings map[uint64]string) (events []*Event, stacks map[uint64][]*Frame, err error) { 318 var ticksPerSec, lastSeq, lastTs int64 319 var lastG uint64 320 var lastP int 321 timerGoids := make(map[uint64]bool) 322 lastGs := make(map[int]uint64) // last goroutine running on P 323 stacks = make(map[uint64][]*Frame) 324 batches := make(map[int][]*Event) // events by P 325 for _, raw := range rawEvents { 326 desc := EventDescriptions[raw.typ] 327 if desc.Name == "" { 328 err = fmt.Errorf("missing description for event type %v", raw.typ) 329 return 330 } 331 narg := argNum(raw, ver) 332 if len(raw.args) != narg { 333 err = fmt.Errorf("%v has wrong number of arguments at offset 0x%x: want %v, got %v", 334 desc.Name, raw.off, narg, len(raw.args)) 335 return 336 } 337 switch raw.typ { 338 case EvBatch: 339 lastGs[lastP] = lastG 340 lastP = int(raw.args[0]) 341 lastG = lastGs[lastP] 342 if ver < 1007 { 343 lastSeq = int64(raw.args[1]) 344 lastTs = int64(raw.args[2]) 345 } else { 346 lastTs = int64(raw.args[1]) 347 } 348 case EvFrequency: 349 ticksPerSec = int64(raw.args[0]) 350 if ticksPerSec <= 0 { 351 // The most likely cause for this is tick skew on different CPUs. 352 // For example, solaris/amd64 seems to have wildly different 353 // ticks on different CPUs. 354 err = ErrTimeOrder 355 return 356 } 357 case EvTimerGoroutine: 358 timerGoids[raw.args[0]] = true 359 case EvStack: 360 if len(raw.args) < 2 { 361 err = fmt.Errorf("EvStack has wrong number of arguments at offset 0x%x: want at least 2, got %v", 362 raw.off, len(raw.args)) 363 return 364 } 365 size := raw.args[1] 366 if size > 1000 { 367 err = fmt.Errorf("EvStack has bad number of frames at offset 0x%x: %v", 368 raw.off, size) 369 return 370 } 371 want := 2 + 4*size 372 if ver < 1007 { 373 want = 2 + size 374 } 375 if uint64(len(raw.args)) != want { 376 err = fmt.Errorf("EvStack has wrong number of arguments at offset 0x%x: want %v, got %v", 377 raw.off, want, len(raw.args)) 378 return 379 } 380 id := raw.args[0] 381 if id != 0 && size > 0 { 382 stk := make([]*Frame, size) 383 for i := 0; i < int(size); i++ { 384 if ver < 1007 { 385 stk[i] = &Frame{PC: raw.args[2+i]} 386 } else { 387 pc := raw.args[2+i*4+0] 388 fn := raw.args[2+i*4+1] 389 file := raw.args[2+i*4+2] 390 line := raw.args[2+i*4+3] 391 stk[i] = &Frame{PC: pc, Fn: strings[fn], File: strings[file], Line: int(line)} 392 } 393 } 394 stacks[id] = stk 395 } 396 default: 397 e := &Event{Off: raw.off, Type: raw.typ, P: lastP, G: lastG} 398 var argOffset int 399 if ver < 1007 { 400 e.seq = lastSeq + int64(raw.args[0]) 401 e.Ts = lastTs + int64(raw.args[1]) 402 lastSeq = e.seq 403 argOffset = 2 404 } else { 405 e.Ts = lastTs + int64(raw.args[0]) 406 argOffset = 1 407 } 408 lastTs = e.Ts 409 for i := argOffset; i < narg; i++ { 410 if i == narg-1 && desc.Stack { 411 e.StkID = raw.args[i] 412 } else { 413 e.Args[i-argOffset] = raw.args[i] 414 } 415 } 416 switch raw.typ { 417 case EvGoStart, EvGoStartLocal, EvGoStartLabel: 418 lastG = e.Args[0] 419 e.G = lastG 420 if raw.typ == EvGoStartLabel { 421 e.SArgs = []string{strings[e.Args[2]]} 422 } 423 case EvGCSTWStart: 424 e.G = 0 425 switch e.Args[0] { 426 case 0: 427 e.SArgs = []string{"mark termination"} 428 case 1: 429 e.SArgs = []string{"sweep termination"} 430 default: 431 err = fmt.Errorf("unknown STW kind %d", e.Args[0]) 432 return 433 } 434 case EvGCStart, EvGCDone, EvGCSTWDone: 435 e.G = 0 436 case EvGoEnd, EvGoStop, EvGoSched, EvGoPreempt, 437 EvGoSleep, EvGoBlock, EvGoBlockSend, EvGoBlockRecv, 438 EvGoBlockSelect, EvGoBlockSync, EvGoBlockCond, EvGoBlockNet, 439 EvGoSysBlock, EvGoBlockGC: 440 lastG = 0 441 case EvGoSysExit, EvGoWaiting, EvGoInSyscall: 442 e.G = e.Args[0] 443 case EvUserTaskCreate: 444 // e.Args 0: taskID, 1:parentID, 2:nameID 445 e.SArgs = []string{strings[e.Args[2]]} 446 case EvUserRegion: 447 // e.Args 0: taskID, 1: mode, 2:nameID 448 e.SArgs = []string{strings[e.Args[2]]} 449 case EvUserLog: 450 // e.Args 0: taskID, 1:keyID, 2: stackID 451 e.SArgs = []string{strings[e.Args[1]], raw.sargs[0]} 452 case EvCPUSample: 453 e.Ts = int64(e.Args[0]) 454 e.P = int(e.Args[1]) 455 e.G = e.Args[2] 456 e.Args[0] = 0 457 } 458 switch raw.typ { 459 default: 460 batches[lastP] = append(batches[lastP], e) 461 case EvCPUSample: 462 // Most events are written out by the active P at the exact 463 // moment they describe. CPU profile samples are different 464 // because they're written to the tracing log after some delay, 465 // by a separate worker goroutine, into a separate buffer. 466 // 467 // We keep these in their own batch until all of the batches are 468 // merged in timestamp order. We also (right before the merge) 469 // re-sort these events by the timestamp captured in the 470 // profiling signal handler. 471 batches[ProfileP] = append(batches[ProfileP], e) 472 } 473 } 474 } 475 if len(batches) == 0 { 476 err = fmt.Errorf("trace is empty") 477 return 478 } 479 if ticksPerSec == 0 { 480 err = fmt.Errorf("no EvFrequency event") 481 return 482 } 483 if BreakTimestampsForTesting { 484 var batchArr [][]*Event 485 for _, batch := range batches { 486 batchArr = append(batchArr, batch) 487 } 488 for i := 0; i < 5; i++ { 489 batch := batchArr[rand.Intn(len(batchArr))] 490 batch[rand.Intn(len(batch))].Ts += int64(rand.Intn(2000) - 1000) 491 } 492 } 493 if ver < 1007 { 494 events, err = order1005(batches) 495 } else { 496 events, err = order1007(batches) 497 } 498 if err != nil { 499 return 500 } 501 502 // Translate cpu ticks to real time. 503 minTs := events[0].Ts 504 // Use floating point to avoid integer overflows. 505 freq := 1e9 / float64(ticksPerSec) 506 for _, ev := range events { 507 ev.Ts = int64(float64(ev.Ts-minTs) * freq) 508 // Move timers and syscalls to separate fake Ps. 509 if timerGoids[ev.G] && ev.Type == EvGoUnblock { 510 ev.P = TimerP 511 } 512 if ev.Type == EvGoSysExit { 513 ev.P = SyscallP 514 } 515 } 516 517 return 518 } 519 520 // removeFutile removes all constituents of futile wakeups (block, unblock, start). 521 // For example, a goroutine was unblocked on a mutex, but another goroutine got 522 // ahead and acquired the mutex before the first goroutine is scheduled, 523 // so the first goroutine has to block again. Such wakeups happen on buffered 524 // channels and sync.Mutex, but are generally not interesting for end user. 525 func removeFutile(events []*Event) []*Event { 526 // Two non-trivial aspects: 527 // 1. A goroutine can be preempted during a futile wakeup and migrate to another P. 528 // We want to remove all of that. 529 // 2. Tracing can start in the middle of a futile wakeup. 530 // That is, we can see a futile wakeup event w/o the actual wakeup before it. 531 // postProcessTrace runs after us and ensures that we leave the trace in a consistent state. 532 533 // Phase 1: determine futile wakeup sequences. 534 type G struct { 535 futile bool 536 wakeup []*Event // wakeup sequence (subject for removal) 537 } 538 gs := make(map[uint64]G) 539 futile := make(map[*Event]bool) 540 for _, ev := range events { 541 switch ev.Type { 542 case EvGoUnblock: 543 g := gs[ev.Args[0]] 544 g.wakeup = []*Event{ev} 545 gs[ev.Args[0]] = g 546 case EvGoStart, EvGoPreempt, EvFutileWakeup: 547 g := gs[ev.G] 548 g.wakeup = append(g.wakeup, ev) 549 if ev.Type == EvFutileWakeup { 550 g.futile = true 551 } 552 gs[ev.G] = g 553 case EvGoBlock, EvGoBlockSend, EvGoBlockRecv, EvGoBlockSelect, EvGoBlockSync, EvGoBlockCond: 554 g := gs[ev.G] 555 if g.futile { 556 futile[ev] = true 557 for _, ev1 := range g.wakeup { 558 futile[ev1] = true 559 } 560 } 561 delete(gs, ev.G) 562 } 563 } 564 565 // Phase 2: remove futile wakeup sequences. 566 newEvents := events[:0] // overwrite the original slice 567 for _, ev := range events { 568 if !futile[ev] { 569 newEvents = append(newEvents, ev) 570 } 571 } 572 return newEvents 573 } 574 575 // ErrTimeOrder is returned by Parse when the trace contains 576 // time stamps that do not respect actual event ordering. 577 var ErrTimeOrder = fmt.Errorf("time stamps out of order") 578 579 // postProcessTrace does inter-event verification and information restoration. 580 // The resulting trace is guaranteed to be consistent 581 // (for example, a P does not run two Gs at the same time, or a G is indeed 582 // blocked before an unblock event). 583 func postProcessTrace(ver int, events []*Event) error { 584 const ( 585 gDead = iota 586 gRunnable 587 gRunning 588 gWaiting 589 ) 590 type gdesc struct { 591 state int 592 ev *Event 593 evStart *Event 594 evCreate *Event 595 evMarkAssist *Event 596 } 597 type pdesc struct { 598 running bool 599 g uint64 600 evSTW *Event 601 evSweep *Event 602 } 603 604 gs := make(map[uint64]gdesc) 605 ps := make(map[int]pdesc) 606 tasks := make(map[uint64]*Event) // task id to task creation events 607 activeRegions := make(map[uint64][]*Event) // goroutine id to stack of regions 608 gs[0] = gdesc{state: gRunning} 609 var evGC, evSTW *Event 610 611 checkRunning := func(p pdesc, g gdesc, ev *Event, allowG0 bool) error { 612 name := EventDescriptions[ev.Type].Name 613 if g.state != gRunning { 614 return fmt.Errorf("g %v is not running while %v (offset %v, time %v)", ev.G, name, ev.Off, ev.Ts) 615 } 616 if p.g != ev.G { 617 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) 618 } 619 if !allowG0 && ev.G == 0 { 620 return fmt.Errorf("g 0 did %v (offset %v, time %v)", EventDescriptions[ev.Type].Name, ev.Off, ev.Ts) 621 } 622 return nil 623 } 624 625 for _, ev := range events { 626 g := gs[ev.G] 627 p := ps[ev.P] 628 629 switch ev.Type { 630 case EvProcStart: 631 if p.running { 632 return fmt.Errorf("p %v is running before start (offset %v, time %v)", ev.P, ev.Off, ev.Ts) 633 } 634 p.running = true 635 case EvProcStop: 636 if !p.running { 637 return fmt.Errorf("p %v is not running before stop (offset %v, time %v)", ev.P, ev.Off, ev.Ts) 638 } 639 if p.g != 0 { 640 return fmt.Errorf("p %v is running a goroutine %v during stop (offset %v, time %v)", ev.P, p.g, ev.Off, ev.Ts) 641 } 642 p.running = false 643 case EvGCStart: 644 if evGC != nil { 645 return fmt.Errorf("previous GC is not ended before a new one (offset %v, time %v)", ev.Off, ev.Ts) 646 } 647 evGC = ev 648 // Attribute this to the global GC state. 649 ev.P = GCP 650 case EvGCDone: 651 if evGC == nil { 652 return fmt.Errorf("bogus GC end (offset %v, time %v)", ev.Off, ev.Ts) 653 } 654 evGC.Link = ev 655 evGC = nil 656 case EvGCSTWStart: 657 evp := &evSTW 658 if ver < 1010 { 659 // Before 1.10, EvGCSTWStart was per-P. 660 evp = &p.evSTW 661 } 662 if *evp != nil { 663 return fmt.Errorf("previous STW is not ended before a new one (offset %v, time %v)", ev.Off, ev.Ts) 664 } 665 *evp = ev 666 case EvGCSTWDone: 667 evp := &evSTW 668 if ver < 1010 { 669 // Before 1.10, EvGCSTWDone was per-P. 670 evp = &p.evSTW 671 } 672 if *evp == nil { 673 return fmt.Errorf("bogus STW end (offset %v, time %v)", ev.Off, ev.Ts) 674 } 675 (*evp).Link = ev 676 *evp = nil 677 case EvGCSweepStart: 678 if p.evSweep != nil { 679 return fmt.Errorf("previous sweeping is not ended before a new one (offset %v, time %v)", ev.Off, ev.Ts) 680 } 681 p.evSweep = ev 682 case EvGCMarkAssistStart: 683 if g.evMarkAssist != nil { 684 return fmt.Errorf("previous mark assist is not ended before a new one (offset %v, time %v)", ev.Off, ev.Ts) 685 } 686 g.evMarkAssist = ev 687 case EvGCMarkAssistDone: 688 // Unlike most events, mark assists can be in progress when a 689 // goroutine starts tracing, so we can't report an error here. 690 if g.evMarkAssist != nil { 691 g.evMarkAssist.Link = ev 692 g.evMarkAssist = nil 693 } 694 case EvGCSweepDone: 695 if p.evSweep == nil { 696 return fmt.Errorf("bogus sweeping end (offset %v, time %v)", ev.Off, ev.Ts) 697 } 698 p.evSweep.Link = ev 699 p.evSweep = nil 700 case EvGoWaiting: 701 if g.state != gRunnable { 702 return fmt.Errorf("g %v is not runnable before EvGoWaiting (offset %v, time %v)", ev.G, ev.Off, ev.Ts) 703 } 704 g.state = gWaiting 705 g.ev = ev 706 case EvGoInSyscall: 707 if g.state != gRunnable { 708 return fmt.Errorf("g %v is not runnable before EvGoInSyscall (offset %v, time %v)", ev.G, ev.Off, ev.Ts) 709 } 710 g.state = gWaiting 711 g.ev = ev 712 case EvGoCreate: 713 if err := checkRunning(p, g, ev, true); err != nil { 714 return err 715 } 716 if _, ok := gs[ev.Args[0]]; ok { 717 return fmt.Errorf("g %v already exists (offset %v, time %v)", ev.Args[0], ev.Off, ev.Ts) 718 } 719 gs[ev.Args[0]] = gdesc{state: gRunnable, ev: ev, evCreate: ev} 720 case EvGoStart, EvGoStartLabel: 721 if g.state != gRunnable { 722 return fmt.Errorf("g %v is not runnable before start (offset %v, time %v)", ev.G, ev.Off, ev.Ts) 723 } 724 if p.g != 0 { 725 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) 726 } 727 g.state = gRunning 728 g.evStart = ev 729 p.g = ev.G 730 if g.evCreate != nil { 731 if ver < 1007 { 732 // +1 because symbolizer expects return pc. 733 ev.Stk = []*Frame{{PC: g.evCreate.Args[1] + 1}} 734 } else { 735 ev.StkID = g.evCreate.Args[1] 736 } 737 g.evCreate = nil 738 } 739 740 if g.ev != nil { 741 g.ev.Link = ev 742 g.ev = nil 743 } 744 case EvGoEnd, EvGoStop: 745 if err := checkRunning(p, g, ev, false); err != nil { 746 return err 747 } 748 g.evStart.Link = ev 749 g.evStart = nil 750 g.state = gDead 751 p.g = 0 752 753 if ev.Type == EvGoEnd { // flush all active regions 754 regions := activeRegions[ev.G] 755 for _, s := range regions { 756 s.Link = ev 757 } 758 delete(activeRegions, ev.G) 759 } 760 761 case EvGoSched, EvGoPreempt: 762 if err := checkRunning(p, g, ev, false); err != nil { 763 return err 764 } 765 g.state = gRunnable 766 g.evStart.Link = ev 767 g.evStart = nil 768 p.g = 0 769 g.ev = ev 770 case EvGoUnblock: 771 if g.state != gRunning { 772 return fmt.Errorf("g %v is not running while unpark (offset %v, time %v)", ev.G, ev.Off, ev.Ts) 773 } 774 if ev.P != TimerP && p.g != ev.G { 775 return fmt.Errorf("p %v is not running g %v while unpark (offset %v, time %v)", ev.P, ev.G, ev.Off, ev.Ts) 776 } 777 g1 := gs[ev.Args[0]] 778 if g1.state != gWaiting { 779 return fmt.Errorf("g %v is not waiting before unpark (offset %v, time %v)", ev.Args[0], ev.Off, ev.Ts) 780 } 781 if g1.ev != nil && g1.ev.Type == EvGoBlockNet && ev.P != TimerP { 782 ev.P = NetpollP 783 } 784 if g1.ev != nil { 785 g1.ev.Link = ev 786 } 787 g1.state = gRunnable 788 g1.ev = ev 789 gs[ev.Args[0]] = g1 790 case EvGoSysCall: 791 if err := checkRunning(p, g, ev, false); err != nil { 792 return err 793 } 794 g.ev = ev 795 case EvGoSysBlock: 796 if err := checkRunning(p, g, ev, false); err != nil { 797 return err 798 } 799 g.state = gWaiting 800 g.evStart.Link = ev 801 g.evStart = nil 802 p.g = 0 803 case EvGoSysExit: 804 if g.state != gWaiting { 805 return fmt.Errorf("g %v is not waiting during syscall exit (offset %v, time %v)", ev.G, ev.Off, ev.Ts) 806 } 807 if g.ev != nil && g.ev.Type == EvGoSysCall { 808 g.ev.Link = ev 809 } 810 g.state = gRunnable 811 g.ev = ev 812 case EvGoSleep, EvGoBlock, EvGoBlockSend, EvGoBlockRecv, 813 EvGoBlockSelect, EvGoBlockSync, EvGoBlockCond, EvGoBlockNet, EvGoBlockGC: 814 if err := checkRunning(p, g, ev, false); err != nil { 815 return err 816 } 817 g.state = gWaiting 818 g.ev = ev 819 g.evStart.Link = ev 820 g.evStart = nil 821 p.g = 0 822 case EvUserTaskCreate: 823 taskid := ev.Args[0] 824 if prevEv, ok := tasks[taskid]; ok { 825 return fmt.Errorf("task id conflicts (id:%d), %q vs %q", taskid, ev, prevEv) 826 } 827 tasks[ev.Args[0]] = ev 828 case EvUserTaskEnd: 829 taskid := ev.Args[0] 830 if taskCreateEv, ok := tasks[taskid]; ok { 831 taskCreateEv.Link = ev 832 delete(tasks, taskid) 833 } 834 case EvUserRegion: 835 mode := ev.Args[1] 836 regions := activeRegions[ev.G] 837 if mode == 0 { // region start 838 activeRegions[ev.G] = append(regions, ev) // push 839 } else if mode == 1 { // region end 840 n := len(regions) 841 if n > 0 { // matching region start event is in the trace. 842 s := regions[n-1] 843 if s.Args[0] != ev.Args[0] || s.SArgs[0] != ev.SArgs[0] { // task id, region name mismatch 844 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) 845 } 846 // Link region start event with span end event 847 s.Link = ev 848 849 if n > 1 { 850 activeRegions[ev.G] = regions[:n-1] 851 } else { 852 delete(activeRegions, ev.G) 853 } 854 } 855 } else { 856 return fmt.Errorf("invalid user region mode: %q", ev) 857 } 858 } 859 860 gs[ev.G] = g 861 ps[ev.P] = p 862 } 863 864 // TODO(dvyukov): restore stacks for EvGoStart events. 865 // TODO(dvyukov): test that all EvGoStart events has non-nil Link. 866 867 return nil 868 } 869 870 // symbolize attaches func/file/line info to stack traces. 871 func symbolize(events []*Event, bin string) error { 872 // First, collect and dedup all pcs. 873 pcs := make(map[uint64]*Frame) 874 for _, ev := range events { 875 for _, f := range ev.Stk { 876 pcs[f.PC] = nil 877 } 878 } 879 880 // Start addr2line. 881 cmd := exec.Command(goCmd(), "tool", "addr2line", bin) 882 in, err := cmd.StdinPipe() 883 if err != nil { 884 return fmt.Errorf("failed to pipe addr2line stdin: %v", err) 885 } 886 cmd.Stderr = os.Stderr 887 out, err := cmd.StdoutPipe() 888 if err != nil { 889 return fmt.Errorf("failed to pipe addr2line stdout: %v", err) 890 } 891 err = cmd.Start() 892 if err != nil { 893 return fmt.Errorf("failed to start addr2line: %v", err) 894 } 895 outb := bufio.NewReader(out) 896 897 // Write all pcs to addr2line. 898 // Need to copy pcs to an array, because map iteration order is non-deterministic. 899 var pcArray []uint64 900 for pc := range pcs { 901 pcArray = append(pcArray, pc) 902 _, err := fmt.Fprintf(in, "0x%x\n", pc-1) 903 if err != nil { 904 return fmt.Errorf("failed to write to addr2line: %v", err) 905 } 906 } 907 in.Close() 908 909 // Read in answers. 910 for _, pc := range pcArray { 911 fn, err := outb.ReadString('\n') 912 if err != nil { 913 return fmt.Errorf("failed to read from addr2line: %v", err) 914 } 915 file, err := outb.ReadString('\n') 916 if err != nil { 917 return fmt.Errorf("failed to read from addr2line: %v", err) 918 } 919 f := &Frame{PC: pc} 920 f.Fn = fn[:len(fn)-1] 921 f.File = file[:len(file)-1] 922 if colon := strings.LastIndex(f.File, ":"); colon != -1 { 923 ln, err := strconv.Atoi(f.File[colon+1:]) 924 if err == nil { 925 f.File = f.File[:colon] 926 f.Line = ln 927 } 928 } 929 pcs[pc] = f 930 } 931 cmd.Wait() 932 933 // Replace frames in events array. 934 for _, ev := range events { 935 for i, f := range ev.Stk { 936 ev.Stk[i] = pcs[f.PC] 937 } 938 } 939 940 return nil 941 } 942 943 // readVal reads unsigned base-128 value from r. 944 func readVal(r io.Reader, off0 int) (v uint64, off int, err error) { 945 off = off0 946 for i := 0; i < 10; i++ { 947 var buf [1]byte 948 var n int 949 n, err = r.Read(buf[:]) 950 if err != nil || n != 1 { 951 return 0, 0, fmt.Errorf("failed to read trace at offset %d: read %v, error %v", off0, n, err) 952 } 953 off++ 954 v |= uint64(buf[0]&0x7f) << (uint(i) * 7) 955 if buf[0]&0x80 == 0 { 956 return 957 } 958 } 959 return 0, 0, fmt.Errorf("bad value at offset 0x%x", off0) 960 } 961 962 // Print dumps events to stdout. For debugging. 963 func Print(events []*Event) { 964 for _, ev := range events { 965 PrintEvent(ev) 966 } 967 } 968 969 // PrintEvent dumps the event to stdout. For debugging. 970 func PrintEvent(ev *Event) { 971 fmt.Printf("%s\n", ev) 972 } 973 974 func (ev *Event) String() string { 975 desc := EventDescriptions[ev.Type] 976 w := new(strings.Builder) 977 fmt.Fprintf(w, "%v %v p=%v g=%v off=%v", ev.Ts, desc.Name, ev.P, ev.G, ev.Off) 978 for i, a := range desc.Args { 979 fmt.Fprintf(w, " %v=%v", a, ev.Args[i]) 980 } 981 for i, a := range desc.SArgs { 982 fmt.Fprintf(w, " %v=%v", a, ev.SArgs[i]) 983 } 984 return w.String() 985 } 986 987 // argNum returns total number of args for the event accounting for timestamps, 988 // sequence numbers and differences between trace format versions. 989 func argNum(raw rawEvent, ver int) int { 990 desc := EventDescriptions[raw.typ] 991 if raw.typ == EvStack { 992 return len(raw.args) 993 } 994 narg := len(desc.Args) 995 if desc.Stack { 996 narg++ 997 } 998 switch raw.typ { 999 case EvBatch, EvFrequency, EvTimerGoroutine: 1000 if ver < 1007 { 1001 narg++ // there was an unused arg before 1.7 1002 } 1003 return narg 1004 } 1005 narg++ // timestamp 1006 if ver < 1007 { 1007 narg++ // sequence 1008 } 1009 switch raw.typ { 1010 case EvGCSweepDone: 1011 if ver < 1009 { 1012 narg -= 2 // 1.9 added two arguments 1013 } 1014 case EvGCStart, EvGoStart, EvGoUnblock: 1015 if ver < 1007 { 1016 narg-- // 1.7 added an additional seq arg 1017 } 1018 case EvGCSTWStart: 1019 if ver < 1010 { 1020 narg-- // 1.10 added an argument 1021 } 1022 } 1023 return narg 1024 } 1025 1026 // BreakTimestampsForTesting causes the parser to randomly alter timestamps (for testing of broken cputicks). 1027 var BreakTimestampsForTesting bool 1028 1029 // Event types in the trace. 1030 // Verbatim copy from src/runtime/trace.go with the "trace" prefix removed. 1031 const ( 1032 EvNone = 0 // unused 1033 EvBatch = 1 // start of per-P batch of events [pid, timestamp] 1034 EvFrequency = 2 // contains tracer timer frequency [frequency (ticks per second)] 1035 EvStack = 3 // stack [stack id, number of PCs, array of {PC, func string ID, file string ID, line}] 1036 EvGomaxprocs = 4 // current value of GOMAXPROCS [timestamp, GOMAXPROCS, stack id] 1037 EvProcStart = 5 // start of P [timestamp, thread id] 1038 EvProcStop = 6 // stop of P [timestamp] 1039 EvGCStart = 7 // GC start [timestamp, seq, stack id] 1040 EvGCDone = 8 // GC done [timestamp] 1041 EvGCSTWStart = 9 // GC mark termination start [timestamp, kind] 1042 EvGCSTWDone = 10 // GC mark termination done [timestamp] 1043 EvGCSweepStart = 11 // GC sweep start [timestamp, stack id] 1044 EvGCSweepDone = 12 // GC sweep done [timestamp, swept, reclaimed] 1045 EvGoCreate = 13 // goroutine creation [timestamp, new goroutine id, new stack id, stack id] 1046 EvGoStart = 14 // goroutine starts running [timestamp, goroutine id, seq] 1047 EvGoEnd = 15 // goroutine ends [timestamp] 1048 EvGoStop = 16 // goroutine stops (like in select{}) [timestamp, stack] 1049 EvGoSched = 17 // goroutine calls Gosched [timestamp, stack] 1050 EvGoPreempt = 18 // goroutine is preempted [timestamp, stack] 1051 EvGoSleep = 19 // goroutine calls Sleep [timestamp, stack] 1052 EvGoBlock = 20 // goroutine blocks [timestamp, stack] 1053 EvGoUnblock = 21 // goroutine is unblocked [timestamp, goroutine id, seq, stack] 1054 EvGoBlockSend = 22 // goroutine blocks on chan send [timestamp, stack] 1055 EvGoBlockRecv = 23 // goroutine blocks on chan recv [timestamp, stack] 1056 EvGoBlockSelect = 24 // goroutine blocks on select [timestamp, stack] 1057 EvGoBlockSync = 25 // goroutine blocks on Mutex/RWMutex [timestamp, stack] 1058 EvGoBlockCond = 26 // goroutine blocks on Cond [timestamp, stack] 1059 EvGoBlockNet = 27 // goroutine blocks on network [timestamp, stack] 1060 EvGoSysCall = 28 // syscall enter [timestamp, stack] 1061 EvGoSysExit = 29 // syscall exit [timestamp, goroutine id, seq, real timestamp] 1062 EvGoSysBlock = 30 // syscall blocks [timestamp] 1063 EvGoWaiting = 31 // denotes that goroutine is blocked when tracing starts [timestamp, goroutine id] 1064 EvGoInSyscall = 32 // denotes that goroutine is in syscall when tracing starts [timestamp, goroutine id] 1065 EvHeapAlloc = 33 // gcController.heapLive change [timestamp, heap live bytes] 1066 EvHeapGoal = 34 // gcController.heapGoal change [timestamp, heap goal bytes] 1067 EvTimerGoroutine = 35 // denotes timer goroutine [timer goroutine id] 1068 EvFutileWakeup = 36 // denotes that the previous wakeup of this goroutine was futile [timestamp] 1069 EvString = 37 // string dictionary entry [ID, length, string] 1070 EvGoStartLocal = 38 // goroutine starts running on the same P as the last event [timestamp, goroutine id] 1071 EvGoUnblockLocal = 39 // goroutine is unblocked on the same P as the last event [timestamp, goroutine id, stack] 1072 EvGoSysExitLocal = 40 // syscall exit on the same P as the last event [timestamp, goroutine id, real timestamp] 1073 EvGoStartLabel = 41 // goroutine starts running with label [timestamp, goroutine id, seq, label string id] 1074 EvGoBlockGC = 42 // goroutine blocks on GC assist [timestamp, stack] 1075 EvGCMarkAssistStart = 43 // GC mark assist start [timestamp, stack] 1076 EvGCMarkAssistDone = 44 // GC mark assist done [timestamp] 1077 EvUserTaskCreate = 45 // trace.NewContext [timestamp, internal task id, internal parent id, stack, name string] 1078 EvUserTaskEnd = 46 // end of task [timestamp, internal task id, stack] 1079 EvUserRegion = 47 // trace.WithRegion [timestamp, internal task id, mode(0:start, 1:end), stack, name string] 1080 EvUserLog = 48 // trace.Log [timestamp, internal id, key string id, stack, value string] 1081 EvCPUSample = 49 // CPU profiling sample [timestamp, stack, real timestamp, real P id (-1 when absent), goroutine id] 1082 EvCount = 50 1083 ) 1084 1085 var EventDescriptions = [EvCount]struct { 1086 Name string 1087 minVersion int 1088 Stack bool 1089 Args []string 1090 SArgs []string // string arguments 1091 }{ 1092 EvNone: {"None", 1005, false, []string{}, nil}, 1093 EvBatch: {"Batch", 1005, false, []string{"p", "ticks"}, nil}, // in 1.5 format it was {"p", "seq", "ticks"} 1094 EvFrequency: {"Frequency", 1005, false, []string{"freq"}, nil}, // in 1.5 format it was {"freq", "unused"} 1095 EvStack: {"Stack", 1005, false, []string{"id", "siz"}, nil}, 1096 EvGomaxprocs: {"Gomaxprocs", 1005, true, []string{"procs"}, nil}, 1097 EvProcStart: {"ProcStart", 1005, false, []string{"thread"}, nil}, 1098 EvProcStop: {"ProcStop", 1005, false, []string{}, nil}, 1099 EvGCStart: {"GCStart", 1005, true, []string{"seq"}, nil}, // in 1.5 format it was {} 1100 EvGCDone: {"GCDone", 1005, false, []string{}, nil}, 1101 EvGCSTWStart: {"GCSTWStart", 1005, false, []string{"kindid"}, []string{"kind"}}, // <= 1.9, args was {} (implicitly {0}) 1102 EvGCSTWDone: {"GCSTWDone", 1005, false, []string{}, nil}, 1103 EvGCSweepStart: {"GCSweepStart", 1005, true, []string{}, nil}, 1104 EvGCSweepDone: {"GCSweepDone", 1005, false, []string{"swept", "reclaimed"}, nil}, // before 1.9, format was {} 1105 EvGoCreate: {"GoCreate", 1005, true, []string{"g", "stack"}, nil}, 1106 EvGoStart: {"GoStart", 1005, false, []string{"g", "seq"}, nil}, // in 1.5 format it was {"g"} 1107 EvGoEnd: {"GoEnd", 1005, false, []string{}, nil}, 1108 EvGoStop: {"GoStop", 1005, true, []string{}, nil}, 1109 EvGoSched: {"GoSched", 1005, true, []string{}, nil}, 1110 EvGoPreempt: {"GoPreempt", 1005, true, []string{}, nil}, 1111 EvGoSleep: {"GoSleep", 1005, true, []string{}, nil}, 1112 EvGoBlock: {"GoBlock", 1005, true, []string{}, nil}, 1113 EvGoUnblock: {"GoUnblock", 1005, true, []string{"g", "seq"}, nil}, // in 1.5 format it was {"g"} 1114 EvGoBlockSend: {"GoBlockSend", 1005, true, []string{}, nil}, 1115 EvGoBlockRecv: {"GoBlockRecv", 1005, true, []string{}, nil}, 1116 EvGoBlockSelect: {"GoBlockSelect", 1005, true, []string{}, nil}, 1117 EvGoBlockSync: {"GoBlockSync", 1005, true, []string{}, nil}, 1118 EvGoBlockCond: {"GoBlockCond", 1005, true, []string{}, nil}, 1119 EvGoBlockNet: {"GoBlockNet", 1005, true, []string{}, nil}, 1120 EvGoSysCall: {"GoSysCall", 1005, true, []string{}, nil}, 1121 EvGoSysExit: {"GoSysExit", 1005, false, []string{"g", "seq", "ts"}, nil}, 1122 EvGoSysBlock: {"GoSysBlock", 1005, false, []string{}, nil}, 1123 EvGoWaiting: {"GoWaiting", 1005, false, []string{"g"}, nil}, 1124 EvGoInSyscall: {"GoInSyscall", 1005, false, []string{"g"}, nil}, 1125 EvHeapAlloc: {"HeapAlloc", 1005, false, []string{"mem"}, nil}, 1126 EvHeapGoal: {"HeapGoal", 1005, false, []string{"mem"}, nil}, 1127 EvTimerGoroutine: {"TimerGoroutine", 1005, false, []string{"g"}, nil}, // in 1.5 format it was {"g", "unused"} 1128 EvFutileWakeup: {"FutileWakeup", 1005, false, []string{}, nil}, 1129 EvString: {"String", 1007, false, []string{}, nil}, 1130 EvGoStartLocal: {"GoStartLocal", 1007, false, []string{"g"}, nil}, 1131 EvGoUnblockLocal: {"GoUnblockLocal", 1007, true, []string{"g"}, nil}, 1132 EvGoSysExitLocal: {"GoSysExitLocal", 1007, false, []string{"g", "ts"}, nil}, 1133 EvGoStartLabel: {"GoStartLabel", 1008, false, []string{"g", "seq", "labelid"}, []string{"label"}}, 1134 EvGoBlockGC: {"GoBlockGC", 1008, true, []string{}, nil}, 1135 EvGCMarkAssistStart: {"GCMarkAssistStart", 1009, true, []string{}, nil}, 1136 EvGCMarkAssistDone: {"GCMarkAssistDone", 1009, false, []string{}, nil}, 1137 EvUserTaskCreate: {"UserTaskCreate", 1011, true, []string{"taskid", "pid", "typeid"}, []string{"name"}}, 1138 EvUserTaskEnd: {"UserTaskEnd", 1011, true, []string{"taskid"}, nil}, 1139 EvUserRegion: {"UserRegion", 1011, true, []string{"taskid", "mode", "typeid"}, []string{"name"}}, 1140 EvUserLog: {"UserLog", 1011, true, []string{"id", "keyid"}, []string{"category", "message"}}, 1141 EvCPUSample: {"CPUSample", 1019, true, []string{"ts", "p", "g"}, nil}, 1142 }