github.com/hlts2/go@v0.0.0-20170904000733-812b34efaed8/src/internal/trace/parser.go (about)

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