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