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