diff options
Diffstat (limited to 'src/internal/trace/parser.go')
-rw-r--r-- | src/internal/trace/parser.go | 662 |
1 files changed, 662 insertions, 0 deletions
diff --git a/src/internal/trace/parser.go b/src/internal/trace/parser.go new file mode 100644 index 0000000000..62d063c5d8 --- /dev/null +++ b/src/internal/trace/parser.go @@ -0,0 +1,662 @@ +// Copyright 2014 The Go Authors. All rights reserved. +// Use of this source code is governed by a BSD-style +// license that can be found in the LICENSE file. + +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* + 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 + StkID uint64 // unique stack ID + Stk []*Frame // stack trace (can be empty) + Args [2]uint64 // event-type-specific arguments + // linked event (can be nil), depends on event type: + // for GCStart: the GCStop + // for GCScanStart: the GCScanDone + // for GCSweepStart: the GCSweepDone + // for GoCreate: first GoStart of the created goroutine + // for GoStart: the associated GoEnd, GoBlock or other blocking event + // for GoSched/GoPreempt: the next GoStart + // for GoBlock and other blocking events: the unblock event + // for GoUnblock: the associated GoStart + // for blocking GoSysCall: the associated GoSysExit + // for GoSysExit: the next GoStart + Link *Event +} + +// Frame is a frame in stack traces. +type Frame struct { + PC uint64 + Fn string + File string + Line int +} + +const ( + // Special P identifiers: + FakeP = 1000000 + iota + TimerP // depicts timer unblocks + NetpollP // depicts network unblocks + SyscallP // depicts returns from syscalls +) + +// parseTrace parses, post-processes and verifies the trace. +func Parse(r io.Reader) ([]*Event, error) { + rawEvents, err := readTrace(r) + if err != nil { + return nil, err + } + events, err := parseEvents(rawEvents) + if err != nil { + return nil, err + } + err = postProcessTrace(events) + if err != nil { + return nil, err + } + return events, nil +} + +// rawEvent is a helper type used during parsing. +type rawEvent struct { + off int + typ byte + args []uint64 +} + +// readTrace does wire-format parsing and verification. +// It does not care about specific event types and argument meaning. +func readTrace(r io.Reader) ([]rawEvent, error) { + // Read and validate trace header. + var buf [8]byte + off, err := r.Read(buf[:]) + if off != 8 || err != nil { + return nil, fmt.Errorf("failed to read header: read %v, err %v", off, err) + } + if bytes.Compare(buf[:], []byte("gotrace\x00")) != 0 { + return nil, fmt.Errorf("not a trace file") + } + + // Read events. + var events []rawEvent + for { + // Read event type and number of arguments (1 byte). + off0 := off + n, err := r.Read(buf[:1]) + if err == io.EOF { + break + } + if err != nil || n != 1 { + return nil, fmt.Errorf("failed to read trace at offset 0x%x: n=%v err=%v", off0, n, err) + } + off += n + typ := buf[0] << 2 >> 2 + narg := buf[0]>>6 + 1 + ev := rawEvent{typ: typ, off: off0} + if narg <= 3 { + for i := 0; i < int(narg); i++ { + var v uint64 + v, off, err = readVal(r, off) + if err != nil { + return nil, err + } + ev.args = append(ev.args, v) + } + } else { + // If narg == 4, the first value is length of the event in bytes. + var v uint64 + v, off, err = readVal(r, off) + if err != nil { + return nil, err + } + evLen := v + off1 := off + for evLen > uint64(off-off1) { + v, off, err = readVal(r, off) + if err != nil { + return nil, err + } + ev.args = append(ev.args, v) + } + if evLen != uint64(off-off1) { + return nil, fmt.Errorf("event has wrong length at offset 0x%x: want %v, got %v", off0, evLen, off-off1) + } + } + events = append(events, ev) + } + return events, nil +} + +// Parse events transforms raw events into events. +// It does analyze and verify per-event-type arguments. +func parseEvents(rawEvents []rawEvent) (events []*Event, err error) { + var ticksPerSec, 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) + return + } + if raw.typ != EvStack { + narg := len(desc.Args) + if desc.Stack { + narg++ + } + if raw.typ != EvBatch && raw.typ != EvFrequency && raw.typ != EvTimerGoroutine { + narg++ // timestamp + } + if len(raw.args) != narg { + err = fmt.Errorf("%v has wrong number of arguments at offset 0x%x: want %v, got %v", + desc.Name, raw.off, narg, len(raw.args)) + return + } + } + switch raw.typ { + case EvBatch: + lastGs[lastP] = lastG + lastP = int(raw.args[0]) + lastG = lastGs[lastP] + lastTs = int64(raw.args[1]) + case EvFrequency: + ticksPerSec = int64(raw.args[0]) + if ticksPerSec <= 0 { + err = fmt.Errorf("EvFrequency contains invalid frequency %v at offset 0x%x", + ticksPerSec, raw.off) + return + } + case EvTimerGoroutine: + timerGoid = raw.args[0] + case EvStack: + if len(raw.args) < 2 { + err = fmt.Errorf("EvStack has wrong number of arguments at offset 0x%x: want at least 2, got %v", + raw.off, len(raw.args)) + return + } + size := raw.args[1] + if size > 1000 { + err = fmt.Errorf("EvStack has bad number of frames at offset 0x%x: %v", + raw.off, size) + return + } + id := raw.args[0] + if id != 0 && size > 0 { + stk := make([]*Frame, size) + for i := 0; i < int(size); i++ { + stk[i] = &Frame{PC: raw.args[i+2]} + } + stacks[id] = stk + } + default: + e := &Event{Off: raw.off, Type: raw.typ, P: lastP, G: lastG} + e.Ts = lastTs + int64(raw.args[0]) + lastTs = e.Ts + for i := range desc.Args { + e.Args[i] = raw.args[i+1] + } + if desc.Stack { + e.StkID = raw.args[len(desc.Args)+1] + } + switch raw.typ { + case EvGoStart: + lastG = e.Args[0] + e.G = lastG + case EvGCStart, EvGCDone, EvGCScanStart, EvGCScanDone: + e.G = 0 + case EvGoEnd, EvGoStop, EvGoSched, EvGoPreempt, + EvGoSleep, EvGoBlock, EvGoBlockSend, EvGoBlockRecv, + EvGoBlockSelect, EvGoBlockSync, EvGoBlockCond, EvGoBlockNet, + EvGoSysBlock: + lastG = 0 + } + events = append(events, e) + } + } + + // Attach stack traces. + for _, ev := range events { + if ev.StkID != 0 { + ev.Stk = stacks[ev.StkID] + } + } + + // Sort by time and translate cpu ticks to real time. + sort.Sort(eventList(events)) + if ticksPerSec == 0 { + err = fmt.Errorf("no EvFrequency event") + return + } + minTs := events[0].Ts + for _, ev := range events { + ev.Ts = (ev.Ts - minTs) * 1e9 / ticksPerSec + // Move timers and syscalls to separate fake Ps. + if timerGoid != 0 && ev.G == timerGoid && ev.Type == EvGoUnblock { + ev.P = TimerP + } + if ev.Type == EvGoSysExit { + ev.P = SyscallP + ev.G = ev.Args[0] + } + } + + return +} + +// postProcessTrace does inter-event verification and information restoration. +// 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 { + const ( + gDead = iota + gRunnable + gRunning + gWaiting + ) + type gdesc struct { + state int + ev *Event + evStart *Event + } + type pdesc struct { + running bool + g uint64 + evGC *Event + evScan *Event + evSweep *Event + } + + gs := make(map[uint64]gdesc) + ps := make(map[int]pdesc) + gs[0] = gdesc{state: gRunning} + + checkRunning := func(p pdesc, g gdesc, ev *Event) error { + name := EventDescriptions[ev.Type].Name + if g.state != gRunning { + return fmt.Errorf("g %v is not running while %v (offset %v, time %v)", ev.G, name, ev.Off, ev.Ts) + } + if p.g != ev.G { + 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) + } + return nil + } + + for _, ev := range events { + g := gs[ev.G] + p := ps[ev.P] + + switch ev.Type { + case EvProcStart: + if p.running { + return fmt.Errorf("p %v is running before start (offset %v, time %v)", ev.P, ev.Off, ev.Ts) + } + p.running = true + case EvProcStop: + if !p.running { + return fmt.Errorf("p %v is not running before stop (offset %v, time %v)", ev.P, ev.Off, ev.Ts) + } + if p.g != 0 { + return fmt.Errorf("p %v is running a goroutine %v during stop (offset %v, time %v)", ev.P, p.g, ev.Off, ev.Ts) + } + p.running = false + case EvGCStart: + if p.evGC != nil { + return fmt.Errorf("previous GC is not ended before a new one (offset %v, time %v)", ev.Off, ev.Ts) + } + p.evGC = ev + case EvGCDone: + if p.evGC == nil { + return fmt.Errorf("bogus GC end (offset %v, time %v)", ev.Off, ev.Ts) + } + p.evGC.Link = ev + p.evGC = nil + case EvGCScanStart: + if p.evScan != nil { + return fmt.Errorf("previous scanning is not ended before a new one (offset %v, time %v)", ev.Off, ev.Ts) + } + p.evScan = ev + case EvGCScanDone: + if p.evScan == nil { + return fmt.Errorf("bogus scanning end (offset %v, time %v)", ev.Off, ev.Ts) + } + p.evScan.Link = ev + p.evScan = nil + case EvGCSweepStart: + if p.evSweep != nil { + return fmt.Errorf("previous sweeping is not ended before a new one (offset %v, time %v)", ev.Off, ev.Ts) + } + p.evSweep = ev + case EvGCSweepDone: + if p.evSweep == nil { + return fmt.Errorf("bogus sweeping end (offset %v, time %v)", ev.Off, ev.Ts) + } + p.evSweep.Link = ev + p.evSweep = nil + case EvGoWaiting: + g1 := gs[ev.Args[0]] + if g1.state != gRunnable { + return fmt.Errorf("g %v is not runnable before EvGoWaiting (offset %v, time %v)", ev.Args[0], ev.Off, ev.Ts) + } + g1.state = gWaiting + gs[ev.Args[0]] = g1 + case EvGoInSyscall: + // this case is intentionally left blank + case EvGoCreate: + if err := checkRunning(p, g, ev); err != nil { + return err + } + if _, ok := gs[ev.Args[0]]; ok { + return fmt.Errorf("g %v already exists (offset %v, time %v)", ev.Args[0], ev.Off, ev.Ts) + } + gs[ev.Args[0]] = gdesc{state: gRunnable, ev: ev} + case EvGoStart: + if g.state != gRunnable { + return fmt.Errorf("g %v is not runnable before start (offset %v, time %v)", ev.G, ev.Off, ev.Ts) + } + if p.g != 0 { + 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) + } + g.state = gRunning + g.evStart = ev + p.g = ev.G + if g.ev != nil { + if g.ev.Type == EvGoCreate { + // +1 because symblizer expects return pc. + ev.Stk = []*Frame{&Frame{PC: g.ev.Args[1] + 1}} + } + g.ev.Link = ev + g.ev = nil + } + case EvGoEnd, EvGoStop: + if err := checkRunning(p, g, ev); err != nil { + return err + } + g.evStart.Link = ev + g.evStart = nil + g.state = gDead + p.g = 0 + case EvGoSched, EvGoPreempt: + if err := checkRunning(p, g, ev); err != nil { + return err + } + g.state = gRunnable + g.evStart.Link = ev + g.evStart = nil + p.g = 0 + g.ev = ev + case EvGoUnblock: + if g.state != gRunning { + return fmt.Errorf("g %v is not running while unpark (offset %v, time %v)", ev.G, ev.Off, ev.Ts) + } + if ev.P != TimerP && p.g != ev.G { + return fmt.Errorf("p %v is not running g %v while unpark (offset %v, time %v)", ev.P, ev.G, ev.Off, ev.Ts) + } + g1 := gs[ev.Args[0]] + if g1.state != gWaiting { + return fmt.Errorf("g %v is not waiting before unpark (offset %v, time %v)", ev.Args[0], ev.Off, ev.Ts) + } + if g1.ev != nil && g1.ev.Type == EvGoBlockNet && ev.P != TimerP { + ev.P = NetpollP + } + if g1.ev != nil { + g1.ev.Link = ev + } + g1.state = gRunnable + g1.ev = ev + gs[ev.Args[0]] = g1 + case EvGoSysCall: + if err := checkRunning(p, g, ev); err != nil { + return err + } + g.ev = ev + case EvGoSysBlock: + if err := checkRunning(p, g, ev); err != nil { + return err + } + g.state = gRunnable + g.evStart.Link = ev + g.evStart = nil + p.g = 0 + case EvGoSysExit: + if g.state != gRunnable { + return fmt.Errorf("g %v is not runnable during syscall exit (offset %v, time %v)", ev.G, ev.Off, ev.Ts) + } + if g.ev != nil && g.ev.Type == EvGoSysCall { + g.ev.Link = ev + } + g.ev = ev + case EvGoSleep, EvGoBlock, EvGoBlockSend, EvGoBlockRecv, + EvGoBlockSelect, EvGoBlockSync, EvGoBlockCond, EvGoBlockNet: + if err := checkRunning(p, g, ev); err != nil { + return err + } + g.state = gWaiting + g.ev = ev + g.evStart.Link = ev + g.evStart = nil + p.g = 0 + } + + gs[ev.G] = g + ps[ev.P] = p + } + + // TODO(dvyukov): restore stacks for EvGoStart events. + // TODO(dvyukov): test that all EvGoStart events has non-nil Link. + + return nil +} + +// symbolizeTrace 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 + for i := 0; i < 10; i++ { + var buf [1]byte + var n int + n, err = r.Read(buf[:]) + if err != nil || n != 1 { + return 0, 0, fmt.Errorf("failed to read trace at offset: read %v, error %v", off0, n, err) + } + off++ + v |= uint64(buf[0]&0x7f) << (uint(i) * 7) + if buf[0]&0x80 == 0 { + return + } + } + return 0, 0, fmt.Errorf("bad value at offset 0x%x", off0) +} + +type eventList []*Event + +func (l eventList) Len() int { + return len(l) +} + +func (l eventList) Less(i, j int) bool { + return l[i].Ts < l[j].Ts +} + +func (l eventList) Swap(i, j int) { + l[i], l[j] = l[j], l[i] +} + +// Event types in the trace. +// Verbatim copy from src/runtime/trace.go. +const ( + EvNone = 0 // unused + EvBatch = 1 // start of per-P batch of events [pid, timestamp] + EvFrequency = 2 // contains tracer timer frequency [frequency (ticks per second)] + EvStack = 3 // stack [stack id, number of PCs, array of PCs] + EvGomaxprocs = 4 // current value of GOMAXPROCS [timestamp, GOMAXPROCS, stack id] + EvProcStart = 5 // start of P [timestamp] + EvProcStop = 6 // stop of P [timestamp] + EvGCStart = 7 // GC start [timestamp, stack id] + EvGCDone = 8 // GC done [timestamp] + EvGCScanStart = 9 // GC scan start [timestamp] + EvGCScanDone = 10 // GC scan done [timestamp] + EvGCSweepStart = 11 // GC sweep start [timestamp, stack id] + EvGCSweepDone = 12 // GC sweep done [timestamp] + EvGoCreate = 13 // goroutine creation [timestamp, new goroutine id, start PC, stack id] + EvGoStart = 14 // goroutine starts running [timestamp, goroutine id] + EvGoEnd = 15 // goroutine ends [timestamp] + EvGoStop = 16 // goroutine stops (like in select{}) [timestamp, stack] + EvGoSched = 17 // goroutine calls Gosched [timestamp, stack] + EvGoPreempt = 18 // goroutine is preempted [timestamp, stack] + EvGoSleep = 19 // goroutine calls Sleep [timestamp, stack] + EvGoBlock = 20 // goroutine blocks [timestamp, stack] + EvGoUnblock = 21 // goroutine is unblocked [timestamp, goroutine id, stack] + EvGoBlockSend = 22 // goroutine blocks on chan send [timestamp, stack] + EvGoBlockRecv = 23 // goroutine blocks on chan recv [timestamp, stack] + EvGoBlockSelect = 24 // goroutine blocks on select [timestamp, stack] + EvGoBlockSync = 25 // goroutine blocks on Mutex/RWMutex [timestamp, stack] + EvGoBlockCond = 26 // goroutine blocks on Cond [timestamp, stack] + EvGoBlockNet = 27 // goroutine blocks on network [timestamp, stack] + EvGoSysCall = 28 // syscall enter [timestamp, stack] + EvGoSysExit = 29 // syscall exit [timestamp, goroutine id] + EvGoSysBlock = 30 // syscall blocks [timestamp, stack] + EvGoWaiting = 31 // denotes that goroutine is blocked when tracing starts [goroutine id] + EvGoInSyscall = 32 // denotes that goroutine is in syscall when tracing starts [goroutine id] + EvHeapAlloc = 33 // memstats.heap_alloc change [timestamp, heap_alloc] + EvNextGC = 34 // memstats.next_gc change [timestamp, next_gc] + EvTimerGoroutine = 35 // denotes timer goroutine [timer goroutine id] + EvCount = 36 +) + +var EventDescriptions = [EvCount]struct { + Name string + Stack bool + Args []string +}{ + EvNone: {"None", false, []string{}}, + EvBatch: {"Batch", false, []string{"p", "ticks"}}, + EvFrequency: {"Frequency", false, []string{"freq"}}, + EvStack: {"Stack", false, []string{"id", "siz"}}, + EvGomaxprocs: {"Gomaxprocs", true, []string{"procs"}}, + EvProcStart: {"ProcStart", false, []string{}}, + 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", "pc"}}, + 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"}}, + EvGoSysBlock: {"GoSysBlock", true, []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"}}, +} |