github.com/gocuntian/go@v0.0.0-20160610041250-fee02d270bf8/src/internal/trace/parser.go (about)

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