github.com/d4l3k/go@v0.0.0-20151015000803-65fc379daeda/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  	"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{{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  }