Source file src/pkg/internal/trace/parser.go

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

View as plain text