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