package trace
import (
+ "bufio"
"bytes"
"fmt"
"io"
+ "os"
+ "os/exec"
"sort"
+ "strconv"
+ "strings"
)
// Event describes one event in the trace.
type Event struct {
Off int // offset in input file (for debugging and error reporting)
Type byte // one of Ev*
- Seq int64 // sequence number
+ seq int64 // sequence number
Ts int64 // timestamp in nanoseconds
P int // P on which the event happened (can be one of TimerP, NetpollP, SyscallP)
G uint64 // G on which the event happened
)
// Parse parses, post-processes and verifies the trace.
-func Parse(r io.Reader) ([]*Event, error) {
- rawEvents, strings, err := readTrace(r)
+func Parse(r io.Reader, bin string) ([]*Event, error) {
+ ver, rawEvents, strings, err := readTrace(r)
if err != nil {
return nil, err
}
- events, stacks, err := parseEvents(rawEvents, strings)
+ events, stacks, err := parseEvents(ver, rawEvents, strings)
if err != nil {
return nil, err
}
if err != nil {
return nil, err
}
- err = postProcessTrace(events)
+ err = postProcessTrace(ver, events)
if err != nil {
return nil, err
}
ev.Stk = stacks[ev.StkID]
}
}
+ if ver < 1007 && bin != "" {
+ if err := symbolize(events, bin); err != nil {
+ return nil, err
+ }
+ }
return events, nil
}
// readTrace does wire-format parsing and verification.
// It does not care about specific event types and argument meaning.
-func readTrace(r io.Reader) ([]rawEvent, map[uint64]string, error) {
+func readTrace(r io.Reader) (ver int, events []rawEvent, strings map[uint64]string, err error) {
// Read and validate trace header.
var buf [16]byte
- off, err := r.Read(buf[:])
- if off != 16 || err != nil {
- return nil, nil, fmt.Errorf("failed to read header: read %v, err %v", off, err)
+ off, err := io.ReadFull(r, buf[:])
+ if err != nil {
+ err = fmt.Errorf("failed to read header: read %v, err %v", off, err)
+ return
}
- if !bytes.Equal(buf[:], []byte("go 1.5 trace\x00\x00\x00\x00")) {
- return nil, nil, fmt.Errorf("not a trace file")
+ ver, err = parseHeader(buf[:])
+ if err != nil {
+ return
+ }
+ switch ver {
+ case 1005, 1007:
+ break
+ default:
+ err = fmt.Errorf("unsupported trace file version %v.%v (update Go toolchain) %v", ver/1000, ver%1000, ver)
+ return
}
// Read events.
- var events []rawEvent
- strings := make(map[uint64]string)
+ strings = make(map[uint64]string)
for {
// Read event type and number of arguments (1 byte).
off0 := off
- n, err := r.Read(buf[:1])
+ var n int
+ n, err = r.Read(buf[:1])
if err == io.EOF {
+ err = nil
break
}
if err != nil || n != 1 {
- return nil, nil, fmt.Errorf("failed to read trace at offset 0x%x: n=%v err=%v", off0, n, err)
+ err = fmt.Errorf("failed to read trace at offset 0x%x: n=%v err=%v", off0, n, err)
+ return
}
off += n
typ := buf[0] << 2 >> 2
narg := buf[0] >> 6
+ if typ == EvNone || typ >= EvCount || EventDescriptions[typ].minVersion > ver {
+ err = fmt.Errorf("unknown event type %v at offset 0x%x", typ, off0)
+ return
+ }
if typ == EvString {
// String dictionary entry [ID, length, string].
var id uint64
id, off, err = readVal(r, off)
if err != nil {
- return nil, nil, err
+ return
}
if id == 0 {
- return nil, nil, fmt.Errorf("string at offset %d has invalid id 0", off)
+ err = fmt.Errorf("string at offset %d has invalid id 0", off)
+ return
}
if strings[id] != "" {
- return nil, nil, fmt.Errorf("string at offset %d has duplicate id %v", off, id)
+ err = fmt.Errorf("string at offset %d has duplicate id %v", off, id)
+ return
}
var ln uint64
ln, off, err = readVal(r, off)
if err != nil {
- return nil, nil, err
+ return
}
if ln == 0 {
- return nil, nil, fmt.Errorf("string at offset %d has invalid length 0", off)
+ err = fmt.Errorf("string at offset %d has invalid length 0", off)
+ return
}
if ln > 1e6 {
- return nil, nil, fmt.Errorf("string at offset %d has too large length %v", off, ln)
+ err = fmt.Errorf("string at offset %d has too large length %v", off, ln)
+ return
}
buf := make([]byte, ln)
- n, err := io.ReadFull(r, buf)
+ var n int
+ n, err = io.ReadFull(r, buf)
if err != nil {
- return nil, nil, fmt.Errorf("failed to read trace at offset %d: read %v, want %v, error %v", off, n, ln, err)
+ err = fmt.Errorf("failed to read trace at offset %d: read %v, want %v, error %v", off, n, ln, err)
+ return
}
off += n
strings[id] = string(buf)
var v uint64
v, off, err = readVal(r, off)
if err != nil {
- return nil, nil, err
+ err = fmt.Errorf("failed to read event %v argument at offset %v (%v)", typ, off, err)
+ return
}
ev.args = append(ev.args, v)
}
var v uint64
v, off, err = readVal(r, off)
if err != nil {
- return nil, nil, err
+ err = fmt.Errorf("failed to read event %v argument at offset %v (%v)", typ, off, err)
+ return
}
evLen := v
off1 := off
for evLen > uint64(off-off1) {
v, off, err = readVal(r, off)
if err != nil {
- return nil, nil, err
+ err = fmt.Errorf("failed to read event %v argument at offset %v (%v)", typ, off, err)
+ return
}
ev.args = append(ev.args, v)
}
if evLen != uint64(off-off1) {
- return nil, nil, fmt.Errorf("event has wrong length at offset 0x%x: want %v, got %v", off0, evLen, off-off1)
+ err = fmt.Errorf("event has wrong length at offset 0x%x: want %v, got %v", off0, evLen, off-off1)
+ return
}
}
events = append(events, ev)
}
- return events, strings, nil
+ return
+}
+
+// parseHeader parses trace header of the form "go 1.7 trace\x00\x00\x00\x00"
+// and returns parsed version as 1007.
+func parseHeader(buf []byte) (int, error) {
+ if len(buf) != 16 {
+ return 0, fmt.Errorf("bad header length")
+ }
+ if buf[0] != 'g' || buf[1] != 'o' || buf[2] != ' ' ||
+ buf[3] < '1' || buf[3] > '9' ||
+ buf[4] != '.' ||
+ buf[5] < '1' || buf[5] > '9' {
+ return 0, fmt.Errorf("not a trace file")
+ }
+ ver := int(buf[5] - '0')
+ i := 0
+ for ; buf[6+i] >= '0' && buf[6+i] <= '9' && i < 2; i++ {
+ ver = ver*10 + int(buf[6+i]-'0')
+ }
+ ver += int(buf[3]-'0') * 1000
+ if !bytes.Equal(buf[6+i:], []byte(" trace\x00\x00\x00\x00")[:10-i]) {
+ return 0, fmt.Errorf("not a trace file")
+ }
+ return ver, nil
}
// Parse events transforms raw events into events.
// It does analyze and verify per-event-type arguments.
-func parseEvents(rawEvents []rawEvent, strings map[uint64]string) (events []*Event, stacks map[uint64][]*Frame, err error) {
+func parseEvents(ver int, rawEvents []rawEvent, strings map[uint64]string) (events []*Event, stacks map[uint64][]*Frame, err error) {
var ticksPerSec, lastSeq, lastTs int64
var lastG, timerGoid uint64
var lastP int
lastGs := make(map[int]uint64) // last goroutine running on P
stacks = make(map[uint64][]*Frame)
for _, raw := range rawEvents {
- if raw.typ == EvNone || raw.typ >= EvCount {
- err = fmt.Errorf("unknown event type %v at offset 0x%x", raw.typ, raw.off)
- return
- }
desc := EventDescriptions[raw.typ]
if desc.Name == "" {
err = fmt.Errorf("missing description for event type %v", raw.typ)
raw.off, size)
return
}
- if want := 2 + 4*size; uint64(len(raw.args)) != want {
+ want := 2 + 4*size
+ if ver < 1007 {
+ want = 2 + size
+ }
+ if uint64(len(raw.args)) != want {
err = fmt.Errorf("EvStack has wrong number of arguments at offset 0x%x: want %v, got %v",
raw.off, want, len(raw.args))
return
if id != 0 && size > 0 {
stk := make([]*Frame, size)
for i := 0; i < int(size); i++ {
- pc := raw.args[2+i*4+0]
- fn := raw.args[2+i*4+1]
- file := raw.args[2+i*4+2]
- line := raw.args[2+i*4+3]
- stk[i] = &Frame{PC: pc, Fn: strings[fn], File: strings[file], Line: int(line)}
+ if ver < 1007 {
+ stk[i] = &Frame{PC: raw.args[2+i]}
+ } else {
+ pc := raw.args[2+i*4+0]
+ fn := raw.args[2+i*4+1]
+ file := raw.args[2+i*4+2]
+ line := raw.args[2+i*4+3]
+ stk[i] = &Frame{PC: pc, Fn: strings[fn], File: strings[file], Line: int(line)}
+ }
}
stacks[id] = stk
}
default:
e := &Event{Off: raw.off, Type: raw.typ, P: lastP, G: lastG}
- e.Seq = lastSeq + int64(raw.args[0])
+ e.seq = lastSeq + int64(raw.args[0])
e.Ts = lastTs + int64(raw.args[1])
- lastSeq = e.Seq
+ lastSeq = e.seq
lastTs = e.Ts
for i := range desc.Args {
e.Args[i] = raw.args[i+2]
case EvGoSysExit:
// EvGoSysExit emission is delayed until the thread has a P.
// Give it the real sequence number and time stamp.
- e.Seq = int64(e.Args[1])
+ e.seq = int64(e.Args[1])
if e.Args[2] != 0 {
e.Ts = int64(e.Args[2])
}
// The resulting trace is guaranteed to be consistent
// (for example, a P does not run two Gs at the same time, or a G is indeed
// blocked before an unblock event).
-func postProcessTrace(events []*Event) error {
+func postProcessTrace(ver int, events []*Event) error {
const (
gDead = iota
gRunnable
g.evStart = ev
p.g = ev.G
if g.evCreate != nil {
- ev.StkID = g.evCreate.Args[1]
+ if ver < 1007 {
+ // +1 because symbolizer expects return pc.
+ ev.Stk = []*Frame{{PC: g.evCreate.Args[1] + 1}}
+ } else {
+ ev.StkID = g.evCreate.Args[1]
+ }
g.evCreate = nil
}
return nil
}
+// symbolize attaches func/file/line info to stack traces.
+func symbolize(events []*Event, bin string) error {
+ // First, collect and dedup all pcs.
+ pcs := make(map[uint64]*Frame)
+ for _, ev := range events {
+ for _, f := range ev.Stk {
+ pcs[f.PC] = nil
+ }
+ }
+
+ // Start addr2line.
+ cmd := exec.Command("go", "tool", "addr2line", bin)
+ in, err := cmd.StdinPipe()
+ if err != nil {
+ return fmt.Errorf("failed to pipe addr2line stdin: %v", err)
+ }
+ cmd.Stderr = os.Stderr
+ out, err := cmd.StdoutPipe()
+ if err != nil {
+ return fmt.Errorf("failed to pipe addr2line stdout: %v", err)
+ }
+ err = cmd.Start()
+ if err != nil {
+ return fmt.Errorf("failed to start addr2line: %v", err)
+ }
+ outb := bufio.NewReader(out)
+
+ // Write all pcs to addr2line.
+ // Need to copy pcs to an array, because map iteration order is non-deterministic.
+ var pcArray []uint64
+ for pc := range pcs {
+ pcArray = append(pcArray, pc)
+ _, err := fmt.Fprintf(in, "0x%x\n", pc-1)
+ if err != nil {
+ return fmt.Errorf("failed to write to addr2line: %v", err)
+ }
+ }
+ in.Close()
+
+ // Read in answers.
+ for _, pc := range pcArray {
+ fn, err := outb.ReadString('\n')
+ if err != nil {
+ return fmt.Errorf("failed to read from addr2line: %v", err)
+ }
+ file, err := outb.ReadString('\n')
+ if err != nil {
+ return fmt.Errorf("failed to read from addr2line: %v", err)
+ }
+ f := &Frame{PC: pc}
+ f.Fn = fn[:len(fn)-1]
+ f.File = file[:len(file)-1]
+ if colon := strings.LastIndex(f.File, ":"); colon != -1 {
+ ln, err := strconv.Atoi(f.File[colon+1:])
+ if err == nil {
+ f.File = f.File[:colon]
+ f.Line = ln
+ }
+ }
+ pcs[pc] = f
+ }
+ cmd.Wait()
+
+ // Replace frames in events array.
+ for _, ev := range events {
+ for i, f := range ev.Stk {
+ ev.Stk[i] = pcs[f.PC]
+ }
+ }
+
+ return nil
+}
+
// readVal reads unsigned base-128 value from r.
func readVal(r io.Reader, off0 int) (v uint64, off int, err error) {
off = off0
}
func (l eventList) Less(i, j int) bool {
- return l[i].Seq < l[j].Seq
+ return l[i].seq < l[j].seq
}
func (l eventList) Swap(i, j int) {
)
var EventDescriptions = [EvCount]struct {
- Name string
- Stack bool
- Args []string
+ Name string
+ minVersion int
+ Stack bool
+ Args []string
}{
- EvNone: {"None", false, []string{}},
- EvBatch: {"Batch", false, []string{"p", "seq", "ticks"}},
- EvFrequency: {"Frequency", false, []string{"freq", "unused"}},
- EvStack: {"Stack", false, []string{"id", "siz"}},
- EvGomaxprocs: {"Gomaxprocs", true, []string{"procs"}},
- EvProcStart: {"ProcStart", false, []string{"thread"}},
- EvProcStop: {"ProcStop", false, []string{}},
- EvGCStart: {"GCStart", true, []string{}},
- EvGCDone: {"GCDone", false, []string{}},
- EvGCScanStart: {"GCScanStart", false, []string{}},
- EvGCScanDone: {"GCScanDone", false, []string{}},
- EvGCSweepStart: {"GCSweepStart", true, []string{}},
- EvGCSweepDone: {"GCSweepDone", false, []string{}},
- EvGoCreate: {"GoCreate", true, []string{"g", "stack"}},
- EvGoStart: {"GoStart", false, []string{"g"}},
- EvGoEnd: {"GoEnd", false, []string{}},
- EvGoStop: {"GoStop", true, []string{}},
- EvGoSched: {"GoSched", true, []string{}},
- EvGoPreempt: {"GoPreempt", true, []string{}},
- EvGoSleep: {"GoSleep", true, []string{}},
- EvGoBlock: {"GoBlock", true, []string{}},
- EvGoUnblock: {"GoUnblock", true, []string{"g"}},
- EvGoBlockSend: {"GoBlockSend", true, []string{}},
- EvGoBlockRecv: {"GoBlockRecv", true, []string{}},
- EvGoBlockSelect: {"GoBlockSelect", true, []string{}},
- EvGoBlockSync: {"GoBlockSync", true, []string{}},
- EvGoBlockCond: {"GoBlockCond", true, []string{}},
- EvGoBlockNet: {"GoBlockNet", true, []string{}},
- EvGoSysCall: {"GoSysCall", true, []string{}},
- EvGoSysExit: {"GoSysExit", false, []string{"g", "seq", "ts"}},
- EvGoSysBlock: {"GoSysBlock", false, []string{}},
- EvGoWaiting: {"GoWaiting", false, []string{"g"}},
- EvGoInSyscall: {"GoInSyscall", false, []string{"g"}},
- EvHeapAlloc: {"HeapAlloc", false, []string{"mem"}},
- EvNextGC: {"NextGC", false, []string{"mem"}},
- EvTimerGoroutine: {"TimerGoroutine", false, []string{"g", "unused"}},
- EvFutileWakeup: {"FutileWakeup", false, []string{}},
- EvString: {"String", false, []string{}},
+ EvNone: {"None", 1005, false, []string{}},
+ EvBatch: {"Batch", 1005, false, []string{"p", "seq", "ticks"}},
+ EvFrequency: {"Frequency", 1005, false, []string{"freq", "unused"}},
+ EvStack: {"Stack", 1005, false, []string{"id", "siz"}},
+ EvGomaxprocs: {"Gomaxprocs", 1005, true, []string{"procs"}},
+ EvProcStart: {"ProcStart", 1005, false, []string{"thread"}},
+ EvProcStop: {"ProcStop", 1005, false, []string{}},
+ EvGCStart: {"GCStart", 1005, true, []string{}},
+ EvGCDone: {"GCDone", 1005, false, []string{}},
+ EvGCScanStart: {"GCScanStart", 1005, false, []string{}},
+ EvGCScanDone: {"GCScanDone", 1005, false, []string{}},
+ EvGCSweepStart: {"GCSweepStart", 1005, true, []string{}},
+ EvGCSweepDone: {"GCSweepDone", 1005, false, []string{}},
+ EvGoCreate: {"GoCreate", 1005, true, []string{"g", "stack"}},
+ EvGoStart: {"GoStart", 1005, false, []string{"g"}},
+ EvGoEnd: {"GoEnd", 1005, false, []string{}},
+ EvGoStop: {"GoStop", 1005, true, []string{}},
+ EvGoSched: {"GoSched", 1005, true, []string{}},
+ EvGoPreempt: {"GoPreempt", 1005, true, []string{}},
+ EvGoSleep: {"GoSleep", 1005, true, []string{}},
+ EvGoBlock: {"GoBlock", 1005, true, []string{}},
+ EvGoUnblock: {"GoUnblock", 1005, true, []string{"g"}},
+ EvGoBlockSend: {"GoBlockSend", 1005, true, []string{}},
+ EvGoBlockRecv: {"GoBlockRecv", 1005, true, []string{}},
+ EvGoBlockSelect: {"GoBlockSelect", 1005, true, []string{}},
+ EvGoBlockSync: {"GoBlockSync", 1005, true, []string{}},
+ EvGoBlockCond: {"GoBlockCond", 1005, true, []string{}},
+ EvGoBlockNet: {"GoBlockNet", 1005, true, []string{}},
+ EvGoSysCall: {"GoSysCall", 1005, true, []string{}},
+ EvGoSysExit: {"GoSysExit", 1005, false, []string{"g", "seq", "ts"}},
+ EvGoSysBlock: {"GoSysBlock", 1005, false, []string{}},
+ EvGoWaiting: {"GoWaiting", 1005, false, []string{"g"}},
+ EvGoInSyscall: {"GoInSyscall", 1005, false, []string{"g"}},
+ EvHeapAlloc: {"HeapAlloc", 1005, false, []string{"mem"}},
+ EvNextGC: {"NextGC", 1005, false, []string{"mem"}},
+ EvTimerGoroutine: {"TimerGoroutine", 1005, false, []string{"g", "unused"}},
+ EvFutileWakeup: {"FutileWakeup", 1005, false, []string{}},
+ EvString: {"String", 1007, false, []string{}},
}