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