github.com/gocuntian/go@v0.0.0-20160610041250-fee02d270bf8/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 "strconv" 16 "strings" 17 _ "unsafe" 18 ) 19 20 // Event describes one event in the trace. 21 type Event struct { 22 Off int // offset in input file (for debugging and error reporting) 23 Type byte // one of Ev* 24 seq int64 // sequence number 25 Ts int64 // timestamp in nanoseconds 26 P int // P on which the event happened (can be one of TimerP, NetpollP, SyscallP) 27 G uint64 // G on which the event happened 28 StkID uint64 // unique stack ID 29 Stk []*Frame // stack trace (can be empty) 30 Args [3]uint64 // event-type-specific arguments 31 // linked event (can be nil), depends on event type: 32 // for GCStart: the GCStop 33 // for GCScanStart: the GCScanDone 34 // for GCSweepStart: the GCSweepDone 35 // for GoCreate: first GoStart of the created goroutine 36 // for GoStart: the associated GoEnd, GoBlock or other blocking event 37 // for GoSched/GoPreempt: the next GoStart 38 // for GoBlock and other blocking events: the unblock event 39 // for GoUnblock: the associated GoStart 40 // for blocking GoSysCall: the associated GoSysExit 41 // for GoSysExit: the next GoStart 42 Link *Event 43 } 44 45 // Frame is a frame in stack traces. 46 type Frame struct { 47 PC uint64 48 Fn string 49 File string 50 Line int 51 } 52 53 const ( 54 // Special P identifiers: 55 FakeP = 1000000 + iota 56 TimerP // depicts timer unblocks 57 NetpollP // depicts network unblocks 58 SyscallP // depicts returns from syscalls 59 ) 60 61 // Parse parses, post-processes and verifies the trace. 62 func Parse(r io.Reader, bin string) ([]*Event, error) { 63 ver, rawEvents, strings, err := readTrace(r) 64 if err != nil { 65 return nil, err 66 } 67 events, stacks, err := parseEvents(ver, rawEvents, strings) 68 if err != nil { 69 return nil, err 70 } 71 events, err = removeFutile(events) 72 if err != nil { 73 return nil, err 74 } 75 err = postProcessTrace(ver, events) 76 if err != nil { 77 return nil, err 78 } 79 // Attach stack traces. 80 for _, ev := range events { 81 if ev.StkID != 0 { 82 ev.Stk = stacks[ev.StkID] 83 } 84 } 85 if ver < 1007 && bin != "" { 86 if err := symbolize(events, bin); err != nil { 87 return nil, err 88 } 89 } 90 return events, nil 91 } 92 93 // rawEvent is a helper type used during parsing. 94 type rawEvent struct { 95 off int 96 typ byte 97 args []uint64 98 } 99 100 // readTrace does wire-format parsing and verification. 101 // It does not care about specific event types and argument meaning. 102 func readTrace(r io.Reader) (ver int, events []rawEvent, strings map[uint64]string, err error) { 103 // Read and validate trace header. 104 var buf [16]byte 105 off, err := io.ReadFull(r, buf[:]) 106 if err != nil { 107 err = fmt.Errorf("failed to read header: read %v, err %v", off, err) 108 return 109 } 110 ver, err = parseHeader(buf[:]) 111 if err != nil { 112 return 113 } 114 switch ver { 115 case 1005, 1007: 116 break 117 default: 118 err = fmt.Errorf("unsupported trace file version %v.%v (update Go toolchain) %v", ver/1000, ver%1000, ver) 119 return 120 } 121 122 // Read events. 123 strings = make(map[uint64]string) 124 for { 125 // Read event type and number of arguments (1 byte). 126 off0 := off 127 var n int 128 n, err = r.Read(buf[:1]) 129 if err == io.EOF { 130 err = nil 131 break 132 } 133 if err != nil || n != 1 { 134 err = fmt.Errorf("failed to read trace at offset 0x%x: n=%v err=%v", off0, n, err) 135 return 136 } 137 off += n 138 typ := buf[0] << 2 >> 2 139 narg := buf[0]>>6 + 1 140 inlineArgs := byte(4) 141 if ver < 1007 { 142 narg++ 143 inlineArgs++ 144 } 145 if typ == EvNone || typ >= EvCount || EventDescriptions[typ].minVersion > ver { 146 err = fmt.Errorf("unknown event type %v at offset 0x%x", typ, off0) 147 return 148 } 149 if typ == EvString { 150 // String dictionary entry [ID, length, string]. 151 var id uint64 152 id, off, err = readVal(r, off) 153 if err != nil { 154 return 155 } 156 if id == 0 { 157 err = fmt.Errorf("string at offset %d has invalid id 0", off) 158 return 159 } 160 if strings[id] != "" { 161 err = fmt.Errorf("string at offset %d has duplicate id %v", off, id) 162 return 163 } 164 var ln uint64 165 ln, off, err = readVal(r, off) 166 if err != nil { 167 return 168 } 169 if ln == 0 { 170 err = fmt.Errorf("string at offset %d has invalid length 0", off) 171 return 172 } 173 if ln > 1e6 { 174 err = fmt.Errorf("string at offset %d has too large length %v", off, ln) 175 return 176 } 177 buf := make([]byte, ln) 178 var n int 179 n, err = io.ReadFull(r, buf) 180 if err != nil { 181 err = fmt.Errorf("failed to read trace at offset %d: read %v, want %v, error %v", off, n, ln, err) 182 return 183 } 184 off += n 185 strings[id] = string(buf) 186 continue 187 } 188 ev := rawEvent{typ: typ, off: off0} 189 if narg < inlineArgs { 190 for i := 0; i < int(narg); i++ { 191 var v uint64 192 v, off, err = readVal(r, off) 193 if err != nil { 194 err = fmt.Errorf("failed to read event %v argument at offset %v (%v)", typ, off, err) 195 return 196 } 197 ev.args = append(ev.args, v) 198 } 199 } else { 200 // More than inlineArgs args, the first value is length of the event in bytes. 201 var v uint64 202 v, off, err = readVal(r, off) 203 if err != nil { 204 err = fmt.Errorf("failed to read event %v argument at offset %v (%v)", typ, off, err) 205 return 206 } 207 evLen := v 208 off1 := off 209 for evLen > uint64(off-off1) { 210 v, off, err = readVal(r, off) 211 if err != nil { 212 err = fmt.Errorf("failed to read event %v argument at offset %v (%v)", typ, off, err) 213 return 214 } 215 ev.args = append(ev.args, v) 216 } 217 if evLen != uint64(off-off1) { 218 err = fmt.Errorf("event has wrong length at offset 0x%x: want %v, got %v", off0, evLen, off-off1) 219 return 220 } 221 } 222 events = append(events, ev) 223 } 224 return 225 } 226 227 // parseHeader parses trace header of the form "go 1.7 trace\x00\x00\x00\x00" 228 // and returns parsed version as 1007. 229 func parseHeader(buf []byte) (int, error) { 230 if len(buf) != 16 { 231 return 0, fmt.Errorf("bad header length") 232 } 233 if buf[0] != 'g' || buf[1] != 'o' || buf[2] != ' ' || 234 buf[3] < '1' || buf[3] > '9' || 235 buf[4] != '.' || 236 buf[5] < '1' || buf[5] > '9' { 237 return 0, fmt.Errorf("not a trace file") 238 } 239 ver := int(buf[5] - '0') 240 i := 0 241 for ; buf[6+i] >= '0' && buf[6+i] <= '9' && i < 2; i++ { 242 ver = ver*10 + int(buf[6+i]-'0') 243 } 244 ver += int(buf[3]-'0') * 1000 245 if !bytes.Equal(buf[6+i:], []byte(" trace\x00\x00\x00\x00")[:10-i]) { 246 return 0, fmt.Errorf("not a trace file") 247 } 248 return ver, nil 249 } 250 251 // Parse events transforms raw events into events. 252 // It does analyze and verify per-event-type arguments. 253 func parseEvents(ver int, rawEvents []rawEvent, strings map[uint64]string) (events []*Event, stacks map[uint64][]*Frame, err error) { 254 var ticksPerSec, lastSeq, lastTs int64 255 var lastG, timerGoid uint64 256 var lastP int 257 lastGs := make(map[int]uint64) // last goroutine running on P 258 stacks = make(map[uint64][]*Frame) 259 batches := make(map[int][]*Event) // events by P 260 for _, raw := range rawEvents { 261 desc := EventDescriptions[raw.typ] 262 if desc.Name == "" { 263 err = fmt.Errorf("missing description for event type %v", raw.typ) 264 return 265 } 266 narg := argNum(raw, ver) 267 if len(raw.args) != narg { 268 err = fmt.Errorf("%v has wrong number of arguments at offset 0x%x: want %v, got %v", 269 desc.Name, raw.off, narg, len(raw.args)) 270 return 271 } 272 switch raw.typ { 273 case EvBatch: 274 lastGs[lastP] = lastG 275 lastP = int(raw.args[0]) 276 lastG = lastGs[lastP] 277 if ver < 1007 { 278 lastSeq = int64(raw.args[1]) 279 lastTs = int64(raw.args[2]) 280 } else { 281 lastTs = int64(raw.args[1]) 282 } 283 case EvFrequency: 284 ticksPerSec = int64(raw.args[0]) 285 if ticksPerSec <= 0 { 286 // The most likely cause for this is tick skew on different CPUs. 287 // For example, solaris/amd64 seems to have wildly different 288 // ticks on different CPUs. 289 err = ErrTimeOrder 290 return 291 } 292 case EvTimerGoroutine: 293 timerGoid = raw.args[0] 294 case EvStack: 295 if len(raw.args) < 2 { 296 err = fmt.Errorf("EvStack has wrong number of arguments at offset 0x%x: want at least 2, got %v", 297 raw.off, len(raw.args)) 298 return 299 } 300 size := raw.args[1] 301 if size > 1000 { 302 err = fmt.Errorf("EvStack has bad number of frames at offset 0x%x: %v", 303 raw.off, size) 304 return 305 } 306 want := 2 + 4*size 307 if ver < 1007 { 308 want = 2 + size 309 } 310 if uint64(len(raw.args)) != want { 311 err = fmt.Errorf("EvStack has wrong number of arguments at offset 0x%x: want %v, got %v", 312 raw.off, want, len(raw.args)) 313 return 314 } 315 id := raw.args[0] 316 if id != 0 && size > 0 { 317 stk := make([]*Frame, size) 318 for i := 0; i < int(size); i++ { 319 if ver < 1007 { 320 stk[i] = &Frame{PC: raw.args[2+i]} 321 } else { 322 pc := raw.args[2+i*4+0] 323 fn := raw.args[2+i*4+1] 324 file := raw.args[2+i*4+2] 325 line := raw.args[2+i*4+3] 326 stk[i] = &Frame{PC: pc, Fn: strings[fn], File: strings[file], Line: int(line)} 327 } 328 } 329 stacks[id] = stk 330 } 331 default: 332 e := &Event{Off: raw.off, Type: raw.typ, P: lastP, G: lastG} 333 var argOffset int 334 if ver < 1007 { 335 e.seq = lastSeq + int64(raw.args[0]) 336 e.Ts = lastTs + int64(raw.args[1]) 337 lastSeq = e.seq 338 argOffset = 2 339 } else { 340 e.Ts = lastTs + int64(raw.args[0]) 341 argOffset = 1 342 } 343 lastTs = e.Ts 344 for i := argOffset; i < narg; i++ { 345 if i == narg-1 && desc.Stack { 346 e.StkID = raw.args[i] 347 } else { 348 e.Args[i-argOffset] = raw.args[i] 349 } 350 } 351 switch raw.typ { 352 case EvGoStart, EvGoStartLocal: 353 lastG = e.Args[0] 354 e.G = lastG 355 case EvGCStart, EvGCDone, EvGCScanStart, EvGCScanDone: 356 e.G = 0 357 case EvGoEnd, EvGoStop, EvGoSched, EvGoPreempt, 358 EvGoSleep, EvGoBlock, EvGoBlockSend, EvGoBlockRecv, 359 EvGoBlockSelect, EvGoBlockSync, EvGoBlockCond, EvGoBlockNet, 360 EvGoSysBlock: 361 lastG = 0 362 case EvGoSysExit, EvGoWaiting, EvGoInSyscall: 363 e.G = e.Args[0] 364 } 365 batches[lastP] = append(batches[lastP], e) 366 } 367 } 368 if len(batches) == 0 { 369 err = fmt.Errorf("trace is empty") 370 return 371 } 372 if ticksPerSec == 0 { 373 err = fmt.Errorf("no EvFrequency event") 374 return 375 } 376 if BreakTimestampsForTesting { 377 var batchArr [][]*Event 378 for _, batch := range batches { 379 batchArr = append(batchArr, batch) 380 } 381 for i := 0; i < 5; i++ { 382 batch := batchArr[rand.Intn(len(batchArr))] 383 batch[rand.Intn(len(batch))].Ts += int64(rand.Intn(2000) - 1000) 384 } 385 } 386 if ver < 1007 { 387 events, err = order1005(batches) 388 } else { 389 events, err = order1007(batches) 390 } 391 if err != nil { 392 return 393 } 394 395 // Translate cpu ticks to real time. 396 minTs := events[0].Ts 397 // Use floating point to avoid integer overflows. 398 freq := 1e9 / float64(ticksPerSec) 399 for _, ev := range events { 400 ev.Ts = int64(float64(ev.Ts-minTs) * freq) 401 // Move timers and syscalls to separate fake Ps. 402 if timerGoid != 0 && ev.G == timerGoid && ev.Type == EvGoUnblock { 403 ev.P = TimerP 404 } 405 if ev.Type == EvGoSysExit { 406 ev.P = SyscallP 407 } 408 } 409 410 return 411 } 412 413 // removeFutile removes all constituents of futile wakeups (block, unblock, start). 414 // For example, a goroutine was unblocked on a mutex, but another goroutine got 415 // ahead and acquired the mutex before the first goroutine is scheduled, 416 // so the first goroutine has to block again. Such wakeups happen on buffered 417 // channels and sync.Mutex, but are generally not interesting for end user. 418 func removeFutile(events []*Event) ([]*Event, error) { 419 // Two non-trivial aspects: 420 // 1. A goroutine can be preempted during a futile wakeup and migrate to another P. 421 // We want to remove all of that. 422 // 2. Tracing can start in the middle of a futile wakeup. 423 // That is, we can see a futile wakeup event w/o the actual wakeup before it. 424 // postProcessTrace runs after us and ensures that we leave the trace in a consistent state. 425 426 // Phase 1: determine futile wakeup sequences. 427 type G struct { 428 futile bool 429 wakeup []*Event // wakeup sequence (subject for removal) 430 } 431 gs := make(map[uint64]G) 432 futile := make(map[*Event]bool) 433 for _, ev := range events { 434 switch ev.Type { 435 case EvGoUnblock: 436 g := gs[ev.Args[0]] 437 g.wakeup = []*Event{ev} 438 gs[ev.Args[0]] = g 439 case EvGoStart, EvGoPreempt, EvFutileWakeup: 440 g := gs[ev.G] 441 g.wakeup = append(g.wakeup, ev) 442 if ev.Type == EvFutileWakeup { 443 g.futile = true 444 } 445 gs[ev.G] = g 446 case EvGoBlock, EvGoBlockSend, EvGoBlockRecv, EvGoBlockSelect, EvGoBlockSync, EvGoBlockCond: 447 g := gs[ev.G] 448 if g.futile { 449 futile[ev] = true 450 for _, ev1 := range g.wakeup { 451 futile[ev1] = true 452 } 453 } 454 delete(gs, ev.G) 455 } 456 } 457 458 // Phase 2: remove futile wakeup sequences. 459 newEvents := events[:0] // overwrite the original slice 460 for _, ev := range events { 461 if !futile[ev] { 462 newEvents = append(newEvents, ev) 463 } 464 } 465 return newEvents, nil 466 } 467 468 // ErrTimeOrder is returned by Parse when the trace contains 469 // time stamps that do not respect actual event ordering. 470 var ErrTimeOrder = fmt.Errorf("time stamps out of order") 471 472 // postProcessTrace does inter-event verification and information restoration. 473 // The resulting trace is guaranteed to be consistent 474 // (for example, a P does not run two Gs at the same time, or a G is indeed 475 // blocked before an unblock event). 476 func postProcessTrace(ver int, events []*Event) error { 477 const ( 478 gDead = iota 479 gRunnable 480 gRunning 481 gWaiting 482 ) 483 type gdesc struct { 484 state int 485 ev *Event 486 evStart *Event 487 evCreate *Event 488 } 489 type pdesc struct { 490 running bool 491 g uint64 492 evScan *Event 493 evSweep *Event 494 } 495 496 gs := make(map[uint64]gdesc) 497 ps := make(map[int]pdesc) 498 gs[0] = gdesc{state: gRunning} 499 var evGC *Event 500 501 checkRunning := func(p pdesc, g gdesc, ev *Event, allowG0 bool) error { 502 name := EventDescriptions[ev.Type].Name 503 if g.state != gRunning { 504 return fmt.Errorf("g %v is not running while %v (offset %v, time %v)", ev.G, name, ev.Off, ev.Ts) 505 } 506 if p.g != ev.G { 507 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) 508 } 509 if !allowG0 && ev.G == 0 { 510 return fmt.Errorf("g 0 did %v (offset %v, time %v)", EventDescriptions[ev.Type].Name, ev.Off, ev.Ts) 511 } 512 return nil 513 } 514 515 for _, ev := range events { 516 g := gs[ev.G] 517 p := ps[ev.P] 518 519 switch ev.Type { 520 case EvProcStart: 521 if p.running { 522 return fmt.Errorf("p %v is running before start (offset %v, time %v)", ev.P, ev.Off, ev.Ts) 523 } 524 p.running = true 525 case EvProcStop: 526 if !p.running { 527 return fmt.Errorf("p %v is not running before stop (offset %v, time %v)", ev.P, ev.Off, ev.Ts) 528 } 529 if p.g != 0 { 530 return fmt.Errorf("p %v is running a goroutine %v during stop (offset %v, time %v)", ev.P, p.g, ev.Off, ev.Ts) 531 } 532 p.running = false 533 case EvGCStart: 534 if evGC != nil { 535 return fmt.Errorf("previous GC is not ended before a new one (offset %v, time %v)", ev.Off, ev.Ts) 536 } 537 evGC = ev 538 case EvGCDone: 539 if evGC == nil { 540 return fmt.Errorf("bogus GC end (offset %v, time %v)", ev.Off, ev.Ts) 541 } 542 evGC.Link = ev 543 evGC = nil 544 case EvGCScanStart: 545 if p.evScan != nil { 546 return fmt.Errorf("previous scanning is not ended before a new one (offset %v, time %v)", ev.Off, ev.Ts) 547 } 548 p.evScan = ev 549 case EvGCScanDone: 550 if p.evScan == nil { 551 return fmt.Errorf("bogus scanning end (offset %v, time %v)", ev.Off, ev.Ts) 552 } 553 p.evScan.Link = ev 554 p.evScan = nil 555 case EvGCSweepStart: 556 if p.evSweep != nil { 557 return fmt.Errorf("previous sweeping is not ended before a new one (offset %v, time %v)", ev.Off, ev.Ts) 558 } 559 p.evSweep = ev 560 case EvGCSweepDone: 561 if p.evSweep == nil { 562 return fmt.Errorf("bogus sweeping end (offset %v, time %v)", ev.Off, ev.Ts) 563 } 564 p.evSweep.Link = ev 565 p.evSweep = nil 566 case EvGoWaiting: 567 if g.state != gRunnable { 568 return fmt.Errorf("g %v is not runnable before EvGoWaiting (offset %v, time %v)", ev.G, ev.Off, ev.Ts) 569 } 570 g.state = gWaiting 571 case EvGoInSyscall: 572 if g.state != gRunnable { 573 return fmt.Errorf("g %v is not runnable before EvGoInSyscall (offset %v, time %v)", ev.G, ev.Off, ev.Ts) 574 } 575 g.state = gWaiting 576 case EvGoCreate: 577 if err := checkRunning(p, g, ev, true); err != nil { 578 return err 579 } 580 if _, ok := gs[ev.Args[0]]; ok { 581 return fmt.Errorf("g %v already exists (offset %v, time %v)", ev.Args[0], ev.Off, ev.Ts) 582 } 583 gs[ev.Args[0]] = gdesc{state: gRunnable, ev: ev, evCreate: ev} 584 case EvGoStart: 585 if g.state != gRunnable { 586 return fmt.Errorf("g %v is not runnable before start (offset %v, time %v)", ev.G, ev.Off, ev.Ts) 587 } 588 if p.g != 0 { 589 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) 590 } 591 g.state = gRunning 592 g.evStart = ev 593 p.g = ev.G 594 if g.evCreate != nil { 595 if ver < 1007 { 596 // +1 because symbolizer expects return pc. 597 ev.Stk = []*Frame{{PC: g.evCreate.Args[1] + 1}} 598 } else { 599 ev.StkID = g.evCreate.Args[1] 600 } 601 g.evCreate = nil 602 } 603 604 if g.ev != nil { 605 g.ev.Link = ev 606 g.ev = nil 607 } 608 case EvGoEnd, EvGoStop: 609 if err := checkRunning(p, g, ev, false); err != nil { 610 return err 611 } 612 g.evStart.Link = ev 613 g.evStart = nil 614 g.state = gDead 615 p.g = 0 616 case EvGoSched, EvGoPreempt: 617 if err := checkRunning(p, g, ev, false); err != nil { 618 return err 619 } 620 g.state = gRunnable 621 g.evStart.Link = ev 622 g.evStart = nil 623 p.g = 0 624 g.ev = ev 625 case EvGoUnblock: 626 if g.state != gRunning { 627 return fmt.Errorf("g %v is not running while unpark (offset %v, time %v)", ev.G, ev.Off, ev.Ts) 628 } 629 if ev.P != TimerP && p.g != ev.G { 630 return fmt.Errorf("p %v is not running g %v while unpark (offset %v, time %v)", ev.P, ev.G, ev.Off, ev.Ts) 631 } 632 g1 := gs[ev.Args[0]] 633 if g1.state != gWaiting { 634 return fmt.Errorf("g %v is not waiting before unpark (offset %v, time %v)", ev.Args[0], ev.Off, ev.Ts) 635 } 636 if g1.ev != nil && g1.ev.Type == EvGoBlockNet && ev.P != TimerP { 637 ev.P = NetpollP 638 } 639 if g1.ev != nil { 640 g1.ev.Link = ev 641 } 642 g1.state = gRunnable 643 g1.ev = ev 644 gs[ev.Args[0]] = g1 645 case EvGoSysCall: 646 if err := checkRunning(p, g, ev, false); err != nil { 647 return err 648 } 649 g.ev = ev 650 case EvGoSysBlock: 651 if err := checkRunning(p, g, ev, false); err != nil { 652 return err 653 } 654 g.state = gWaiting 655 g.evStart.Link = ev 656 g.evStart = nil 657 p.g = 0 658 case EvGoSysExit: 659 if g.state != gWaiting { 660 return fmt.Errorf("g %v is not waiting during syscall exit (offset %v, time %v)", ev.G, ev.Off, ev.Ts) 661 } 662 if g.ev != nil && g.ev.Type == EvGoSysCall { 663 g.ev.Link = ev 664 } 665 g.state = gRunnable 666 g.ev = ev 667 case EvGoSleep, EvGoBlock, EvGoBlockSend, EvGoBlockRecv, 668 EvGoBlockSelect, EvGoBlockSync, EvGoBlockCond, EvGoBlockNet: 669 if err := checkRunning(p, g, ev, false); err != nil { 670 return err 671 } 672 g.state = gWaiting 673 g.ev = ev 674 g.evStart.Link = ev 675 g.evStart = nil 676 p.g = 0 677 } 678 679 gs[ev.G] = g 680 ps[ev.P] = p 681 } 682 683 // TODO(dvyukov): restore stacks for EvGoStart events. 684 // TODO(dvyukov): test that all EvGoStart events has non-nil Link. 685 686 return nil 687 } 688 689 // symbolize attaches func/file/line info to stack traces. 690 func symbolize(events []*Event, bin string) error { 691 // First, collect and dedup all pcs. 692 pcs := make(map[uint64]*Frame) 693 for _, ev := range events { 694 for _, f := range ev.Stk { 695 pcs[f.PC] = nil 696 } 697 } 698 699 // Start addr2line. 700 cmd := exec.Command("go", "tool", "addr2line", bin) 701 in, err := cmd.StdinPipe() 702 if err != nil { 703 return fmt.Errorf("failed to pipe addr2line stdin: %v", err) 704 } 705 cmd.Stderr = os.Stderr 706 out, err := cmd.StdoutPipe() 707 if err != nil { 708 return fmt.Errorf("failed to pipe addr2line stdout: %v", err) 709 } 710 err = cmd.Start() 711 if err != nil { 712 return fmt.Errorf("failed to start addr2line: %v", err) 713 } 714 outb := bufio.NewReader(out) 715 716 // Write all pcs to addr2line. 717 // Need to copy pcs to an array, because map iteration order is non-deterministic. 718 var pcArray []uint64 719 for pc := range pcs { 720 pcArray = append(pcArray, pc) 721 _, err := fmt.Fprintf(in, "0x%x\n", pc-1) 722 if err != nil { 723 return fmt.Errorf("failed to write to addr2line: %v", err) 724 } 725 } 726 in.Close() 727 728 // Read in answers. 729 for _, pc := range pcArray { 730 fn, err := outb.ReadString('\n') 731 if err != nil { 732 return fmt.Errorf("failed to read from addr2line: %v", err) 733 } 734 file, err := outb.ReadString('\n') 735 if err != nil { 736 return fmt.Errorf("failed to read from addr2line: %v", err) 737 } 738 f := &Frame{PC: pc} 739 f.Fn = fn[:len(fn)-1] 740 f.File = file[:len(file)-1] 741 if colon := strings.LastIndex(f.File, ":"); colon != -1 { 742 ln, err := strconv.Atoi(f.File[colon+1:]) 743 if err == nil { 744 f.File = f.File[:colon] 745 f.Line = ln 746 } 747 } 748 pcs[pc] = f 749 } 750 cmd.Wait() 751 752 // Replace frames in events array. 753 for _, ev := range events { 754 for i, f := range ev.Stk { 755 ev.Stk[i] = pcs[f.PC] 756 } 757 } 758 759 return nil 760 } 761 762 // readVal reads unsigned base-128 value from r. 763 func readVal(r io.Reader, off0 int) (v uint64, off int, err error) { 764 off = off0 765 for i := 0; i < 10; i++ { 766 var buf [1]byte 767 var n int 768 n, err = r.Read(buf[:]) 769 if err != nil || n != 1 { 770 return 0, 0, fmt.Errorf("failed to read trace at offset %d: read %v, error %v", off0, n, err) 771 } 772 off++ 773 v |= uint64(buf[0]&0x7f) << (uint(i) * 7) 774 if buf[0]&0x80 == 0 { 775 return 776 } 777 } 778 return 0, 0, fmt.Errorf("bad value at offset 0x%x", off0) 779 } 780 781 // Print dumps events to stdout. For debugging. 782 func Print(events []*Event) { 783 for _, ev := range events { 784 PrintEvent(ev) 785 } 786 } 787 788 // PrintEvent dumps the event to stdout. For debugging. 789 func PrintEvent(ev *Event) { 790 desc := EventDescriptions[ev.Type] 791 fmt.Printf("%v %v p=%v g=%v off=%v", ev.Ts, desc.Name, ev.P, ev.G, ev.Off) 792 for i, a := range desc.Args { 793 fmt.Printf(" %v=%v", a, ev.Args[i]) 794 } 795 fmt.Printf("\n") 796 } 797 798 // argNum returns total number of args for the event accounting for timestamps, 799 // sequence numbers and differences between trace format versions. 800 func argNum(raw rawEvent, ver int) int { 801 desc := EventDescriptions[raw.typ] 802 if raw.typ == EvStack { 803 return len(raw.args) 804 } 805 narg := len(desc.Args) 806 if desc.Stack { 807 narg++ 808 } 809 switch raw.typ { 810 case EvBatch, EvFrequency, EvTimerGoroutine: 811 if ver < 1007 { 812 narg++ // there was an unused arg before 1.7 813 } 814 case EvGCStart, EvGoStart, EvGoUnblock: 815 if ver < 1007 { 816 narg-- // 1.7 added an additional seq arg 817 } 818 fallthrough 819 default: 820 narg++ // timestamp 821 if ver < 1007 { 822 narg++ // sequence 823 } 824 } 825 return narg 826 } 827 828 // BreakTimestampsForTesting causes the parser to randomly alter timestamps (for testing of broken cputicks). 829 var BreakTimestampsForTesting bool 830 831 // Event types in the trace. 832 // Verbatim copy from src/runtime/trace.go. 833 const ( 834 EvNone = 0 // unused 835 EvBatch = 1 // start of per-P batch of events [pid, timestamp] 836 EvFrequency = 2 // contains tracer timer frequency [frequency (ticks per second)] 837 EvStack = 3 // stack [stack id, number of PCs, array of {PC, func string ID, file string ID, line}] 838 EvGomaxprocs = 4 // current value of GOMAXPROCS [timestamp, GOMAXPROCS, stack id] 839 EvProcStart = 5 // start of P [timestamp, thread id] 840 EvProcStop = 6 // stop of P [timestamp] 841 EvGCStart = 7 // GC start [timestamp, seq, stack id] 842 EvGCDone = 8 // GC done [timestamp] 843 EvGCScanStart = 9 // GC scan start [timestamp] 844 EvGCScanDone = 10 // GC scan done [timestamp] 845 EvGCSweepStart = 11 // GC sweep start [timestamp, stack id] 846 EvGCSweepDone = 12 // GC sweep done [timestamp] 847 EvGoCreate = 13 // goroutine creation [timestamp, new goroutine id, new stack id, stack id] 848 EvGoStart = 14 // goroutine starts running [timestamp, goroutine id, seq] 849 EvGoEnd = 15 // goroutine ends [timestamp] 850 EvGoStop = 16 // goroutine stops (like in select{}) [timestamp, stack] 851 EvGoSched = 17 // goroutine calls Gosched [timestamp, stack] 852 EvGoPreempt = 18 // goroutine is preempted [timestamp, stack] 853 EvGoSleep = 19 // goroutine calls Sleep [timestamp, stack] 854 EvGoBlock = 20 // goroutine blocks [timestamp, stack] 855 EvGoUnblock = 21 // goroutine is unblocked [timestamp, goroutine id, seq, stack] 856 EvGoBlockSend = 22 // goroutine blocks on chan send [timestamp, stack] 857 EvGoBlockRecv = 23 // goroutine blocks on chan recv [timestamp, stack] 858 EvGoBlockSelect = 24 // goroutine blocks on select [timestamp, stack] 859 EvGoBlockSync = 25 // goroutine blocks on Mutex/RWMutex [timestamp, stack] 860 EvGoBlockCond = 26 // goroutine blocks on Cond [timestamp, stack] 861 EvGoBlockNet = 27 // goroutine blocks on network [timestamp, stack] 862 EvGoSysCall = 28 // syscall enter [timestamp, stack] 863 EvGoSysExit = 29 // syscall exit [timestamp, goroutine id, seq, real timestamp] 864 EvGoSysBlock = 30 // syscall blocks [timestamp] 865 EvGoWaiting = 31 // denotes that goroutine is blocked when tracing starts [timestamp, goroutine id] 866 EvGoInSyscall = 32 // denotes that goroutine is in syscall when tracing starts [timestamp, goroutine id] 867 EvHeapAlloc = 33 // memstats.heap_live change [timestamp, heap_alloc] 868 EvNextGC = 34 // memstats.next_gc change [timestamp, next_gc] 869 EvTimerGoroutine = 35 // denotes timer goroutine [timer goroutine id] 870 EvFutileWakeup = 36 // denotes that the previous wakeup of this goroutine was futile [timestamp] 871 EvString = 37 // string dictionary entry [ID, length, string] 872 EvGoStartLocal = 38 // goroutine starts running on the same P as the last event [timestamp, goroutine id] 873 EvGoUnblockLocal = 39 // goroutine is unblocked on the same P as the last event [timestamp, goroutine id, stack] 874 EvGoSysExitLocal = 40 // syscall exit on the same P as the last event [timestamp, goroutine id, real timestamp] 875 EvCount = 41 876 ) 877 878 var EventDescriptions = [EvCount]struct { 879 Name string 880 minVersion int 881 Stack bool 882 Args []string 883 }{ 884 EvNone: {"None", 1005, false, []string{}}, 885 EvBatch: {"Batch", 1005, false, []string{"p", "ticks"}}, // in 1.5 format it was {"p", "seq", "ticks"} 886 EvFrequency: {"Frequency", 1005, false, []string{"freq"}}, // in 1.5 format it was {"freq", "unused"} 887 EvStack: {"Stack", 1005, false, []string{"id", "siz"}}, 888 EvGomaxprocs: {"Gomaxprocs", 1005, true, []string{"procs"}}, 889 EvProcStart: {"ProcStart", 1005, false, []string{"thread"}}, 890 EvProcStop: {"ProcStop", 1005, false, []string{}}, 891 EvGCStart: {"GCStart", 1005, true, []string{"seq"}}, // in 1.5 format it was {} 892 EvGCDone: {"GCDone", 1005, false, []string{}}, 893 EvGCScanStart: {"GCScanStart", 1005, false, []string{}}, 894 EvGCScanDone: {"GCScanDone", 1005, false, []string{}}, 895 EvGCSweepStart: {"GCSweepStart", 1005, true, []string{}}, 896 EvGCSweepDone: {"GCSweepDone", 1005, false, []string{}}, 897 EvGoCreate: {"GoCreate", 1005, true, []string{"g", "stack"}}, 898 EvGoStart: {"GoStart", 1005, false, []string{"g", "seq"}}, // in 1.5 format it was {"g"} 899 EvGoEnd: {"GoEnd", 1005, false, []string{}}, 900 EvGoStop: {"GoStop", 1005, true, []string{}}, 901 EvGoSched: {"GoSched", 1005, true, []string{}}, 902 EvGoPreempt: {"GoPreempt", 1005, true, []string{}}, 903 EvGoSleep: {"GoSleep", 1005, true, []string{}}, 904 EvGoBlock: {"GoBlock", 1005, true, []string{}}, 905 EvGoUnblock: {"GoUnblock", 1005, true, []string{"g", "seq"}}, // in 1.5 format it was {"g"} 906 EvGoBlockSend: {"GoBlockSend", 1005, true, []string{}}, 907 EvGoBlockRecv: {"GoBlockRecv", 1005, true, []string{}}, 908 EvGoBlockSelect: {"GoBlockSelect", 1005, true, []string{}}, 909 EvGoBlockSync: {"GoBlockSync", 1005, true, []string{}}, 910 EvGoBlockCond: {"GoBlockCond", 1005, true, []string{}}, 911 EvGoBlockNet: {"GoBlockNet", 1005, true, []string{}}, 912 EvGoSysCall: {"GoSysCall", 1005, true, []string{}}, 913 EvGoSysExit: {"GoSysExit", 1005, false, []string{"g", "seq", "ts"}}, 914 EvGoSysBlock: {"GoSysBlock", 1005, false, []string{}}, 915 EvGoWaiting: {"GoWaiting", 1005, false, []string{"g"}}, 916 EvGoInSyscall: {"GoInSyscall", 1005, false, []string{"g"}}, 917 EvHeapAlloc: {"HeapAlloc", 1005, false, []string{"mem"}}, 918 EvNextGC: {"NextGC", 1005, false, []string{"mem"}}, 919 EvTimerGoroutine: {"TimerGoroutine", 1005, false, []string{"g"}}, // in 1.5 format it was {"g", "unused"} 920 EvFutileWakeup: {"FutileWakeup", 1005, false, []string{}}, 921 EvString: {"String", 1007, false, []string{}}, 922 EvGoStartLocal: {"GoStartLocal", 1007, false, []string{"g"}}, 923 EvGoUnblockLocal: {"GoUnblockLocal", 1007, true, []string{"g"}}, 924 EvGoSysExitLocal: {"GoSysExitLocal", 1007, false, []string{"g", "ts"}}, 925 }