github.com/AndrienkoAleksandr/go@v0.0.19/src/intern/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, 1021: 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 EvSTWStart: 424 e.G = 0 425 if ver < 1021 { 426 switch e.Args[0] { 427 case 0: 428 e.SArgs = []string{"mark termination"} 429 case 1: 430 e.SArgs = []string{"sweep termination"} 431 default: 432 err = fmt.Errorf("unknown STW kind %d", e.Args[0]) 433 return 434 } 435 } else if ver == 1021 { 436 if kind := e.Args[0]; kind < uint64(len(stwReasonStringsGo121)) { 437 e.SArgs = []string{stwReasonStringsGo121[kind]} 438 } else { 439 e.SArgs = []string{"unknown"} 440 } 441 } else { 442 // Can't make any assumptions. 443 e.SArgs = []string{"unknown"} 444 } 445 case EvGCStart, EvGCDone, EvSTWDone: 446 e.G = 0 447 case EvGoEnd, EvGoStop, EvGoSched, EvGoPreempt, 448 EvGoSleep, EvGoBlock, EvGoBlockSend, EvGoBlockRecv, 449 EvGoBlockSelect, EvGoBlockSync, EvGoBlockCond, EvGoBlockNet, 450 EvGoSysBlock, EvGoBlockGC: 451 lastG = 0 452 case EvGoSysExit, EvGoWaiting, EvGoInSyscall: 453 e.G = e.Args[0] 454 case EvUserTaskCreate: 455 // e.Args 0: taskID, 1:parentID, 2:nameID 456 e.SArgs = []string{strings[e.Args[2]]} 457 case EvUserRegion: 458 // e.Args 0: taskID, 1: mode, 2:nameID 459 e.SArgs = []string{strings[e.Args[2]]} 460 case EvUserLog: 461 // e.Args 0: taskID, 1:keyID, 2: stackID 462 e.SArgs = []string{strings[e.Args[1]], raw.sargs[0]} 463 case EvCPUSample: 464 e.Ts = int64(e.Args[0]) 465 e.P = int(e.Args[1]) 466 e.G = e.Args[2] 467 e.Args[0] = 0 468 } 469 switch raw.typ { 470 default: 471 batches[lastP] = append(batches[lastP], e) 472 case EvCPUSample: 473 // Most events are written out by the active P at the exact 474 // moment they describe. CPU profile samples are different 475 // because they're written to the tracing log after some delay, 476 // by a separate worker goroutine, into a separate buffer. 477 // 478 // We keep these in their own batch until all of the batches are 479 // merged in timestamp order. We also (right before the merge) 480 // re-sort these events by the timestamp captured in the 481 // profiling signal handler. 482 batches[ProfileP] = append(batches[ProfileP], e) 483 } 484 } 485 } 486 if len(batches) == 0 { 487 err = fmt.Errorf("trace is empty") 488 return 489 } 490 if ticksPerSec == 0 { 491 err = fmt.Errorf("no EvFrequency event") 492 return 493 } 494 if BreakTimestampsForTesting { 495 var batchArr [][]*Event 496 for _, batch := range batches { 497 batchArr = append(batchArr, batch) 498 } 499 for i := 0; i < 5; i++ { 500 batch := batchArr[rand.Intn(len(batchArr))] 501 batch[rand.Intn(len(batch))].Ts += int64(rand.Intn(2000) - 1000) 502 } 503 } 504 if ver < 1007 { 505 events, err = order1005(batches) 506 } else { 507 events, err = order1007(batches) 508 } 509 if err != nil { 510 return 511 } 512 513 // Translate cpu ticks to real time. 514 minTs := events[0].Ts 515 // Use floating point to avoid integer overflows. 516 freq := 1e9 / float64(ticksPerSec) 517 for _, ev := range events { 518 ev.Ts = int64(float64(ev.Ts-minTs) * freq) 519 // Move timers and syscalls to separate fake Ps. 520 if timerGoids[ev.G] && ev.Type == EvGoUnblock { 521 ev.P = TimerP 522 } 523 if ev.Type == EvGoSysExit { 524 ev.P = SyscallP 525 } 526 } 527 528 return 529 } 530 531 // removeFutile removes all constituents of futile wakeups (block, unblock, start). 532 // For example, a goroutine was unblocked on a mutex, but another goroutine got 533 // ahead and acquired the mutex before the first goroutine is scheduled, 534 // so the first goroutine has to block again. Such wakeups happen on buffered 535 // channels and sync.Mutex, but are generally not interesting for end user. 536 func removeFutile(events []*Event) []*Event { 537 // Two non-trivial aspects: 538 // 1. A goroutine can be preempted during a futile wakeup and migrate to another P. 539 // We want to remove all of that. 540 // 2. Tracing can start in the middle of a futile wakeup. 541 // That is, we can see a futile wakeup event w/o the actual wakeup before it. 542 // postProcessTrace runs after us and ensures that we leave the trace in a consistent state. 543 544 // Phase 1: determine futile wakeup sequences. 545 type G struct { 546 futile bool 547 wakeup []*Event // wakeup sequence (subject for removal) 548 } 549 gs := make(map[uint64]G) 550 futile := make(map[*Event]bool) 551 for _, ev := range events { 552 switch ev.Type { 553 case EvGoUnblock: 554 g := gs[ev.Args[0]] 555 g.wakeup = []*Event{ev} 556 gs[ev.Args[0]] = g 557 case EvGoStart, EvGoPreempt, EvFutileWakeup: 558 g := gs[ev.G] 559 g.wakeup = append(g.wakeup, ev) 560 if ev.Type == EvFutileWakeup { 561 g.futile = true 562 } 563 gs[ev.G] = g 564 case EvGoBlock, EvGoBlockSend, EvGoBlockRecv, EvGoBlockSelect, EvGoBlockSync, EvGoBlockCond: 565 g := gs[ev.G] 566 if g.futile { 567 futile[ev] = true 568 for _, ev1 := range g.wakeup { 569 futile[ev1] = true 570 } 571 } 572 delete(gs, ev.G) 573 } 574 } 575 576 // Phase 2: remove futile wakeup sequences. 577 newEvents := events[:0] // overwrite the original slice 578 for _, ev := range events { 579 if !futile[ev] { 580 newEvents = append(newEvents, ev) 581 } 582 } 583 return newEvents 584 } 585 586 // ErrTimeOrder is returned by Parse when the trace contains 587 // time stamps that do not respect actual event ordering. 588 var ErrTimeOrder = fmt.Errorf("time stamps out of order") 589 590 // postProcessTrace does inter-event verification and information restoration. 591 // The resulting trace is guaranteed to be consistent 592 // (for example, a P does not run two Gs at the same time, or a G is indeed 593 // blocked before an unblock event). 594 func postProcessTrace(ver int, events []*Event) error { 595 const ( 596 gDead = iota 597 gRunnable 598 gRunning 599 gWaiting 600 ) 601 type gdesc struct { 602 state int 603 ev *Event 604 evStart *Event 605 evCreate *Event 606 evMarkAssist *Event 607 } 608 type pdesc struct { 609 running bool 610 g uint64 611 evSTW *Event 612 evSweep *Event 613 } 614 615 gs := make(map[uint64]gdesc) 616 ps := make(map[int]pdesc) 617 tasks := make(map[uint64]*Event) // task id to task creation events 618 activeRegions := make(map[uint64][]*Event) // goroutine id to stack of regions 619 gs[0] = gdesc{state: gRunning} 620 var evGC, evSTW *Event 621 622 checkRunning := func(p pdesc, g gdesc, ev *Event, allowG0 bool) error { 623 name := EventDescriptions[ev.Type].Name 624 if g.state != gRunning { 625 return fmt.Errorf("g %v is not running while %v (offset %v, time %v)", ev.G, name, ev.Off, ev.Ts) 626 } 627 if p.g != ev.G { 628 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) 629 } 630 if !allowG0 && ev.G == 0 { 631 return fmt.Errorf("g 0 did %v (offset %v, time %v)", EventDescriptions[ev.Type].Name, ev.Off, ev.Ts) 632 } 633 return nil 634 } 635 636 for _, ev := range events { 637 g := gs[ev.G] 638 p := ps[ev.P] 639 640 switch ev.Type { 641 case EvProcStart: 642 if p.running { 643 return fmt.Errorf("p %v is running before start (offset %v, time %v)", ev.P, ev.Off, ev.Ts) 644 } 645 p.running = true 646 case EvProcStop: 647 if !p.running { 648 return fmt.Errorf("p %v is not running before stop (offset %v, time %v)", ev.P, ev.Off, ev.Ts) 649 } 650 if p.g != 0 { 651 return fmt.Errorf("p %v is running a goroutine %v during stop (offset %v, time %v)", ev.P, p.g, ev.Off, ev.Ts) 652 } 653 p.running = false 654 case EvGCStart: 655 if evGC != nil { 656 return fmt.Errorf("previous GC is not ended before a new one (offset %v, time %v)", ev.Off, ev.Ts) 657 } 658 evGC = ev 659 // Attribute this to the global GC state. 660 ev.P = GCP 661 case EvGCDone: 662 if evGC == nil { 663 return fmt.Errorf("bogus GC end (offset %v, time %v)", ev.Off, ev.Ts) 664 } 665 evGC.Link = ev 666 evGC = nil 667 case EvSTWStart: 668 evp := &evSTW 669 if ver < 1010 { 670 // Before 1.10, EvSTWStart was per-P. 671 evp = &p.evSTW 672 } 673 if *evp != nil { 674 return fmt.Errorf("previous STW is not ended before a new one (offset %v, time %v)", ev.Off, ev.Ts) 675 } 676 *evp = ev 677 case EvSTWDone: 678 evp := &evSTW 679 if ver < 1010 { 680 // Before 1.10, EvSTWDone was per-P. 681 evp = &p.evSTW 682 } 683 if *evp == nil { 684 return fmt.Errorf("bogus STW end (offset %v, time %v)", ev.Off, ev.Ts) 685 } 686 (*evp).Link = ev 687 *evp = nil 688 case EvGCSweepStart: 689 if p.evSweep != nil { 690 return fmt.Errorf("previous sweeping is not ended before a new one (offset %v, time %v)", ev.Off, ev.Ts) 691 } 692 p.evSweep = ev 693 case EvGCMarkAssistStart: 694 if g.evMarkAssist != nil { 695 return fmt.Errorf("previous mark assist is not ended before a new one (offset %v, time %v)", ev.Off, ev.Ts) 696 } 697 g.evMarkAssist = ev 698 case EvGCMarkAssistDone: 699 // Unlike most events, mark assists can be in progress when a 700 // goroutine starts tracing, so we can't report an error here. 701 if g.evMarkAssist != nil { 702 g.evMarkAssist.Link = ev 703 g.evMarkAssist = nil 704 } 705 case EvGCSweepDone: 706 if p.evSweep == nil { 707 return fmt.Errorf("bogus sweeping end (offset %v, time %v)", ev.Off, ev.Ts) 708 } 709 p.evSweep.Link = ev 710 p.evSweep = nil 711 case EvGoWaiting: 712 if g.state != gRunnable { 713 return fmt.Errorf("g %v is not runnable before EvGoWaiting (offset %v, time %v)", ev.G, ev.Off, ev.Ts) 714 } 715 g.state = gWaiting 716 g.ev = ev 717 case EvGoInSyscall: 718 if g.state != gRunnable { 719 return fmt.Errorf("g %v is not runnable before EvGoInSyscall (offset %v, time %v)", ev.G, ev.Off, ev.Ts) 720 } 721 g.state = gWaiting 722 g.ev = ev 723 case EvGoCreate: 724 if err := checkRunning(p, g, ev, true); err != nil { 725 return err 726 } 727 if _, ok := gs[ev.Args[0]]; ok { 728 return fmt.Errorf("g %v already exists (offset %v, time %v)", ev.Args[0], ev.Off, ev.Ts) 729 } 730 gs[ev.Args[0]] = gdesc{state: gRunnable, ev: ev, evCreate: ev} 731 case EvGoStart, EvGoStartLabel: 732 if g.state != gRunnable { 733 return fmt.Errorf("g %v is not runnable before start (offset %v, time %v)", ev.G, ev.Off, ev.Ts) 734 } 735 if p.g != 0 { 736 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) 737 } 738 g.state = gRunning 739 g.evStart = ev 740 p.g = ev.G 741 if g.evCreate != nil { 742 if ver < 1007 { 743 // +1 because symbolizer expects return pc. 744 ev.Stk = []*Frame{{PC: g.evCreate.Args[1] + 1}} 745 } else { 746 ev.StkID = g.evCreate.Args[1] 747 } 748 g.evCreate = nil 749 } 750 751 if g.ev != nil { 752 g.ev.Link = ev 753 g.ev = nil 754 } 755 case EvGoEnd, EvGoStop: 756 if err := checkRunning(p, g, ev, false); err != nil { 757 return err 758 } 759 g.evStart.Link = ev 760 g.evStart = nil 761 g.state = gDead 762 p.g = 0 763 764 if ev.Type == EvGoEnd { // flush all active regions 765 regions := activeRegions[ev.G] 766 for _, s := range regions { 767 s.Link = ev 768 } 769 delete(activeRegions, ev.G) 770 } 771 772 case EvGoSched, EvGoPreempt: 773 if err := checkRunning(p, g, ev, false); err != nil { 774 return err 775 } 776 g.state = gRunnable 777 g.evStart.Link = ev 778 g.evStart = nil 779 p.g = 0 780 g.ev = ev 781 case EvGoUnblock: 782 if g.state != gRunning { 783 return fmt.Errorf("g %v is not running while unpark (offset %v, time %v)", ev.G, ev.Off, ev.Ts) 784 } 785 if ev.P != TimerP && p.g != ev.G { 786 return fmt.Errorf("p %v is not running g %v while unpark (offset %v, time %v)", ev.P, ev.G, ev.Off, ev.Ts) 787 } 788 g1 := gs[ev.Args[0]] 789 if g1.state != gWaiting { 790 return fmt.Errorf("g %v is not waiting before unpark (offset %v, time %v)", ev.Args[0], ev.Off, ev.Ts) 791 } 792 if g1.ev != nil && g1.ev.Type == EvGoBlockNet && ev.P != TimerP { 793 ev.P = NetpollP 794 } 795 if g1.ev != nil { 796 g1.ev.Link = ev 797 } 798 g1.state = gRunnable 799 g1.ev = ev 800 gs[ev.Args[0]] = g1 801 case EvGoSysCall: 802 if err := checkRunning(p, g, ev, false); err != nil { 803 return err 804 } 805 g.ev = ev 806 case EvGoSysBlock: 807 if err := checkRunning(p, g, ev, false); err != nil { 808 return err 809 } 810 g.state = gWaiting 811 g.evStart.Link = ev 812 g.evStart = nil 813 p.g = 0 814 case EvGoSysExit: 815 if g.state != gWaiting { 816 return fmt.Errorf("g %v is not waiting during syscall exit (offset %v, time %v)", ev.G, ev.Off, ev.Ts) 817 } 818 if g.ev != nil && g.ev.Type == EvGoSysCall { 819 g.ev.Link = ev 820 } 821 g.state = gRunnable 822 g.ev = ev 823 case EvGoSleep, EvGoBlock, EvGoBlockSend, EvGoBlockRecv, 824 EvGoBlockSelect, EvGoBlockSync, EvGoBlockCond, EvGoBlockNet, EvGoBlockGC: 825 if err := checkRunning(p, g, ev, false); err != nil { 826 return err 827 } 828 g.state = gWaiting 829 g.ev = ev 830 g.evStart.Link = ev 831 g.evStart = nil 832 p.g = 0 833 case EvUserTaskCreate: 834 taskid := ev.Args[0] 835 if prevEv, ok := tasks[taskid]; ok { 836 return fmt.Errorf("task id conflicts (id:%d), %q vs %q", taskid, ev, prevEv) 837 } 838 tasks[ev.Args[0]] = ev 839 case EvUserTaskEnd: 840 taskid := ev.Args[0] 841 if taskCreateEv, ok := tasks[taskid]; ok { 842 taskCreateEv.Link = ev 843 delete(tasks, taskid) 844 } 845 case EvUserRegion: 846 mode := ev.Args[1] 847 regions := activeRegions[ev.G] 848 if mode == 0 { // region start 849 activeRegions[ev.G] = append(regions, ev) // push 850 } else if mode == 1 { // region end 851 n := len(regions) 852 if n > 0 { // matching region start event is in the trace. 853 s := regions[n-1] 854 if s.Args[0] != ev.Args[0] || s.SArgs[0] != ev.SArgs[0] { // task id, region name mismatch 855 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) 856 } 857 // Link region start event with span end event 858 s.Link = ev 859 860 if n > 1 { 861 activeRegions[ev.G] = regions[:n-1] 862 } else { 863 delete(activeRegions, ev.G) 864 } 865 } 866 } else { 867 return fmt.Errorf("invalid user region mode: %q", ev) 868 } 869 } 870 871 gs[ev.G] = g 872 ps[ev.P] = p 873 } 874 875 // TODO(dvyukov): restore stacks for EvGoStart events. 876 // TODO(dvyukov): test that all EvGoStart events has non-nil Link. 877 878 return nil 879 } 880 881 // symbolize attaches func/file/line info to stack traces. 882 func symbolize(events []*Event, bin string) error { 883 // First, collect and dedup all pcs. 884 pcs := make(map[uint64]*Frame) 885 for _, ev := range events { 886 for _, f := range ev.Stk { 887 pcs[f.PC] = nil 888 } 889 } 890 891 // Start addr2line. 892 cmd := exec.Command(goCmd(), "tool", "addr2line", bin) 893 in, err := cmd.StdinPipe() 894 if err != nil { 895 return fmt.Errorf("failed to pipe addr2line stdin: %v", err) 896 } 897 cmd.Stderr = os.Stderr 898 out, err := cmd.StdoutPipe() 899 if err != nil { 900 return fmt.Errorf("failed to pipe addr2line stdout: %v", err) 901 } 902 err = cmd.Start() 903 if err != nil { 904 return fmt.Errorf("failed to start addr2line: %v", err) 905 } 906 outb := bufio.NewReader(out) 907 908 // Write all pcs to addr2line. 909 // Need to copy pcs to an array, because map iteration order is non-deterministic. 910 var pcArray []uint64 911 for pc := range pcs { 912 pcArray = append(pcArray, pc) 913 _, err := fmt.Fprintf(in, "0x%x\n", pc-1) 914 if err != nil { 915 return fmt.Errorf("failed to write to addr2line: %v", err) 916 } 917 } 918 in.Close() 919 920 // Read in answers. 921 for _, pc := range pcArray { 922 fn, err := outb.ReadString('\n') 923 if err != nil { 924 return fmt.Errorf("failed to read from addr2line: %v", err) 925 } 926 file, err := outb.ReadString('\n') 927 if err != nil { 928 return fmt.Errorf("failed to read from addr2line: %v", err) 929 } 930 f := &Frame{PC: pc} 931 f.Fn = fn[:len(fn)-1] 932 f.File = file[:len(file)-1] 933 if colon := strings.LastIndex(f.File, ":"); colon != -1 { 934 ln, err := strconv.Atoi(f.File[colon+1:]) 935 if err == nil { 936 f.File = f.File[:colon] 937 f.Line = ln 938 } 939 } 940 pcs[pc] = f 941 } 942 cmd.Wait() 943 944 // Replace frames in events array. 945 for _, ev := range events { 946 for i, f := range ev.Stk { 947 ev.Stk[i] = pcs[f.PC] 948 } 949 } 950 951 return nil 952 } 953 954 // readVal reads unsigned base-128 value from r. 955 func readVal(r io.Reader, off0 int) (v uint64, off int, err error) { 956 off = off0 957 for i := 0; i < 10; i++ { 958 var buf [1]byte 959 var n int 960 n, err = r.Read(buf[:]) 961 if err != nil || n != 1 { 962 return 0, 0, fmt.Errorf("failed to read trace at offset %d: read %v, error %v", off0, n, err) 963 } 964 off++ 965 v |= uint64(buf[0]&0x7f) << (uint(i) * 7) 966 if buf[0]&0x80 == 0 { 967 return 968 } 969 } 970 return 0, 0, fmt.Errorf("bad value at offset 0x%x", off0) 971 } 972 973 // Print dumps events to stdout. For debugging. 974 func Print(events []*Event) { 975 for _, ev := range events { 976 PrintEvent(ev) 977 } 978 } 979 980 // PrintEvent dumps the event to stdout. For debugging. 981 func PrintEvent(ev *Event) { 982 fmt.Printf("%s\n", ev) 983 } 984 985 func (ev *Event) String() string { 986 desc := EventDescriptions[ev.Type] 987 w := new(strings.Builder) 988 fmt.Fprintf(w, "%v %v p=%v g=%v off=%v", ev.Ts, desc.Name, ev.P, ev.G, ev.Off) 989 for i, a := range desc.Args { 990 fmt.Fprintf(w, " %v=%v", a, ev.Args[i]) 991 } 992 for i, a := range desc.SArgs { 993 fmt.Fprintf(w, " %v=%v", a, ev.SArgs[i]) 994 } 995 return w.String() 996 } 997 998 // argNum returns total number of args for the event accounting for timestamps, 999 // sequence numbers and differences between trace format versions. 1000 func argNum(raw rawEvent, ver int) int { 1001 desc := EventDescriptions[raw.typ] 1002 if raw.typ == EvStack { 1003 return len(raw.args) 1004 } 1005 narg := len(desc.Args) 1006 if desc.Stack { 1007 narg++ 1008 } 1009 switch raw.typ { 1010 case EvBatch, EvFrequency, EvTimerGoroutine: 1011 if ver < 1007 { 1012 narg++ // there was an unused arg before 1.7 1013 } 1014 return narg 1015 } 1016 narg++ // timestamp 1017 if ver < 1007 { 1018 narg++ // sequence 1019 } 1020 switch raw.typ { 1021 case EvGCSweepDone: 1022 if ver < 1009 { 1023 narg -= 2 // 1.9 added two arguments 1024 } 1025 case EvGCStart, EvGoStart, EvGoUnblock: 1026 if ver < 1007 { 1027 narg-- // 1.7 added an additional seq arg 1028 } 1029 case EvSTWStart: 1030 if ver < 1010 { 1031 narg-- // 1.10 added an argument 1032 } 1033 } 1034 return narg 1035 } 1036 1037 // BreakTimestampsForTesting causes the parser to randomly alter timestamps (for testing of broken cputicks). 1038 var BreakTimestampsForTesting bool 1039 1040 // Event types in the trace. 1041 // Verbatim copy from src/runtime/trace.go with the "trace" prefix removed. 1042 const ( 1043 EvNone = 0 // unused 1044 EvBatch = 1 // start of per-P batch of events [pid, timestamp] 1045 EvFrequency = 2 // contains tracer timer frequency [frequency (ticks per second)] 1046 EvStack = 3 // stack [stack id, number of PCs, array of {PC, func string ID, file string ID, line}] 1047 EvGomaxprocs = 4 // current value of GOMAXPROCS [timestamp, GOMAXPROCS, stack id] 1048 EvProcStart = 5 // start of P [timestamp, thread id] 1049 EvProcStop = 6 // stop of P [timestamp] 1050 EvGCStart = 7 // GC start [timestamp, seq, stack id] 1051 EvGCDone = 8 // GC done [timestamp] 1052 EvSTWStart = 9 // GC mark termination start [timestamp, kind] 1053 EvSTWDone = 10 // GC mark termination done [timestamp] 1054 EvGCSweepStart = 11 // GC sweep start [timestamp, stack id] 1055 EvGCSweepDone = 12 // GC sweep done [timestamp, swept, reclaimed] 1056 EvGoCreate = 13 // goroutine creation [timestamp, new goroutine id, new stack id, stack id] 1057 EvGoStart = 14 // goroutine starts running [timestamp, goroutine id, seq] 1058 EvGoEnd = 15 // goroutine ends [timestamp] 1059 EvGoStop = 16 // goroutine stops (like in select{}) [timestamp, stack] 1060 EvGoSched = 17 // goroutine calls Gosched [timestamp, stack] 1061 EvGoPreempt = 18 // goroutine is preempted [timestamp, stack] 1062 EvGoSleep = 19 // goroutine calls Sleep [timestamp, stack] 1063 EvGoBlock = 20 // goroutine blocks [timestamp, stack] 1064 EvGoUnblock = 21 // goroutine is unblocked [timestamp, goroutine id, seq, stack] 1065 EvGoBlockSend = 22 // goroutine blocks on chan send [timestamp, stack] 1066 EvGoBlockRecv = 23 // goroutine blocks on chan recv [timestamp, stack] 1067 EvGoBlockSelect = 24 // goroutine blocks on select [timestamp, stack] 1068 EvGoBlockSync = 25 // goroutine blocks on Mutex/RWMutex [timestamp, stack] 1069 EvGoBlockCond = 26 // goroutine blocks on Cond [timestamp, stack] 1070 EvGoBlockNet = 27 // goroutine blocks on network [timestamp, stack] 1071 EvGoSysCall = 28 // syscall enter [timestamp, stack] 1072 EvGoSysExit = 29 // syscall exit [timestamp, goroutine id, seq, real timestamp] 1073 EvGoSysBlock = 30 // syscall blocks [timestamp] 1074 EvGoWaiting = 31 // denotes that goroutine is blocked when tracing starts [timestamp, goroutine id] 1075 EvGoInSyscall = 32 // denotes that goroutine is in syscall when tracing starts [timestamp, goroutine id] 1076 EvHeapAlloc = 33 // gcController.heapLive change [timestamp, heap live bytes] 1077 EvHeapGoal = 34 // gcController.heapGoal change [timestamp, heap goal bytes] 1078 EvTimerGoroutine = 35 // denotes timer goroutine [timer goroutine id] 1079 EvFutileWakeup = 36 // denotes that the previous wakeup of this goroutine was futile [timestamp] 1080 EvString = 37 // string dictionary entry [ID, length, string] 1081 EvGoStartLocal = 38 // goroutine starts running on the same P as the last event [timestamp, goroutine id] 1082 EvGoUnblockLocal = 39 // goroutine is unblocked on the same P as the last event [timestamp, goroutine id, stack] 1083 EvGoSysExitLocal = 40 // syscall exit on the same P as the last event [timestamp, goroutine id, real timestamp] 1084 EvGoStartLabel = 41 // goroutine starts running with label [timestamp, goroutine id, seq, label string id] 1085 EvGoBlockGC = 42 // goroutine blocks on GC assist [timestamp, stack] 1086 EvGCMarkAssistStart = 43 // GC mark assist start [timestamp, stack] 1087 EvGCMarkAssistDone = 44 // GC mark assist done [timestamp] 1088 EvUserTaskCreate = 45 // trace.NewTask [timestamp, internal task id, internal parent id, name string, stack] 1089 EvUserTaskEnd = 46 // end of task [timestamp, internal task id, stack] 1090 EvUserRegion = 47 // trace.WithRegion [timestamp, internal task id, mode(0:start, 1:end), name string, stack] 1091 EvUserLog = 48 // trace.Log [timestamp, internal id, key string id, stack, value string] 1092 EvCPUSample = 49 // CPU profiling sample [timestamp, real timestamp, real P id (-1 when absent), goroutine id, stack] 1093 EvCount = 50 1094 ) 1095 1096 var EventDescriptions = [EvCount]struct { 1097 Name string 1098 minVersion int 1099 Stack bool 1100 Args []string 1101 SArgs []string // string arguments 1102 }{ 1103 EvNone: {"None", 1005, false, []string{}, nil}, 1104 EvBatch: {"Batch", 1005, false, []string{"p", "ticks"}, nil}, // in 1.5 format it was {"p", "seq", "ticks"} 1105 EvFrequency: {"Frequency", 1005, false, []string{"freq"}, nil}, // in 1.5 format it was {"freq", "unused"} 1106 EvStack: {"Stack", 1005, false, []string{"id", "siz"}, nil}, 1107 EvGomaxprocs: {"Gomaxprocs", 1005, true, []string{"procs"}, nil}, 1108 EvProcStart: {"ProcStart", 1005, false, []string{"thread"}, nil}, 1109 EvProcStop: {"ProcStop", 1005, false, []string{}, nil}, 1110 EvGCStart: {"GCStart", 1005, true, []string{"seq"}, nil}, // in 1.5 format it was {} 1111 EvGCDone: {"GCDone", 1005, false, []string{}, nil}, 1112 EvSTWStart: {"STWStart", 1005, false, []string{"kindid"}, []string{"kind"}}, // <= 1.9, args was {} (implicitly {0}) 1113 EvSTWDone: {"STWDone", 1005, false, []string{}, nil}, 1114 EvGCSweepStart: {"GCSweepStart", 1005, true, []string{}, nil}, 1115 EvGCSweepDone: {"GCSweepDone", 1005, false, []string{"swept", "reclaimed"}, nil}, // before 1.9, format was {} 1116 EvGoCreate: {"GoCreate", 1005, true, []string{"g", "stack"}, nil}, 1117 EvGoStart: {"GoStart", 1005, false, []string{"g", "seq"}, nil}, // in 1.5 format it was {"g"} 1118 EvGoEnd: {"GoEnd", 1005, false, []string{}, nil}, 1119 EvGoStop: {"GoStop", 1005, true, []string{}, nil}, 1120 EvGoSched: {"GoSched", 1005, true, []string{}, nil}, 1121 EvGoPreempt: {"GoPreempt", 1005, true, []string{}, nil}, 1122 EvGoSleep: {"GoSleep", 1005, true, []string{}, nil}, 1123 EvGoBlock: {"GoBlock", 1005, true, []string{}, nil}, 1124 EvGoUnblock: {"GoUnblock", 1005, true, []string{"g", "seq"}, nil}, // in 1.5 format it was {"g"} 1125 EvGoBlockSend: {"GoBlockSend", 1005, true, []string{}, nil}, 1126 EvGoBlockRecv: {"GoBlockRecv", 1005, true, []string{}, nil}, 1127 EvGoBlockSelect: {"GoBlockSelect", 1005, true, []string{}, nil}, 1128 EvGoBlockSync: {"GoBlockSync", 1005, true, []string{}, nil}, 1129 EvGoBlockCond: {"GoBlockCond", 1005, true, []string{}, nil}, 1130 EvGoBlockNet: {"GoBlockNet", 1005, true, []string{}, nil}, 1131 EvGoSysCall: {"GoSysCall", 1005, true, []string{}, nil}, 1132 EvGoSysExit: {"GoSysExit", 1005, false, []string{"g", "seq", "ts"}, nil}, 1133 EvGoSysBlock: {"GoSysBlock", 1005, false, []string{}, nil}, 1134 EvGoWaiting: {"GoWaiting", 1005, false, []string{"g"}, nil}, 1135 EvGoInSyscall: {"GoInSyscall", 1005, false, []string{"g"}, nil}, 1136 EvHeapAlloc: {"HeapAlloc", 1005, false, []string{"mem"}, nil}, 1137 EvHeapGoal: {"HeapGoal", 1005, false, []string{"mem"}, nil}, 1138 EvTimerGoroutine: {"TimerGoroutine", 1005, false, []string{"g"}, nil}, // in 1.5 format it was {"g", "unused"} 1139 EvFutileWakeup: {"FutileWakeup", 1005, false, []string{}, nil}, 1140 EvString: {"String", 1007, false, []string{}, nil}, 1141 EvGoStartLocal: {"GoStartLocal", 1007, false, []string{"g"}, nil}, 1142 EvGoUnblockLocal: {"GoUnblockLocal", 1007, true, []string{"g"}, nil}, 1143 EvGoSysExitLocal: {"GoSysExitLocal", 1007, false, []string{"g", "ts"}, nil}, 1144 EvGoStartLabel: {"GoStartLabel", 1008, false, []string{"g", "seq", "labelid"}, []string{"label"}}, 1145 EvGoBlockGC: {"GoBlockGC", 1008, true, []string{}, nil}, 1146 EvGCMarkAssistStart: {"GCMarkAssistStart", 1009, true, []string{}, nil}, 1147 EvGCMarkAssistDone: {"GCMarkAssistDone", 1009, false, []string{}, nil}, 1148 EvUserTaskCreate: {"UserTaskCreate", 1011, true, []string{"taskid", "pid", "typeid"}, []string{"name"}}, 1149 EvUserTaskEnd: {"UserTaskEnd", 1011, true, []string{"taskid"}, nil}, 1150 EvUserRegion: {"UserRegion", 1011, true, []string{"taskid", "mode", "typeid"}, []string{"name"}}, 1151 EvUserLog: {"UserLog", 1011, true, []string{"id", "keyid"}, []string{"category", "message"}}, 1152 EvCPUSample: {"CPUSample", 1019, true, []string{"ts", "p", "g"}, nil}, 1153 } 1154 1155 // Copied from src/runtime/proc.go:stwReasonStrings in Go 1.21. 1156 var stwReasonStringsGo121 = [...]string{ 1157 "unknown", 1158 "GC mark termination", 1159 "GC sweep termination", 1160 "write heap dump", 1161 "goroutine profile", 1162 "goroutine profile cleanup", 1163 "all goroutines stack trace", 1164 "read mem stats", 1165 "AllThreadsSyscall", 1166 "GOMAXPROCS", 1167 "start trace", 1168 "stop trace", 1169 "CountPagesInUse (test)", 1170 "ReadMetricsSlow (test)", 1171 "ReadMemStatsSlow (test)", 1172 "PageCachePagesLeaked (test)", 1173 "ResetDebugLog (test)", 1174 }