// Copyright 2018 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 traceparser parses the trace files produced by runtime.StartTrace package traceparser import ( "fmt" "internal/traceparser/filebuf" "io" "strings" ) // Parsed is the result of parsing a trace file type Parsed struct { // Set by New Name string // File's name Size int64 // File's size Count int64 // approximate number of all events MaxTs int64 // range of all events, in nanoseconds Strings map[uint64]string Stacks map[uint32][]*Frame Version int // version of the trace file from header TicksPerSec int64 // from EvFrequency in trailer minticks, maxticks int64 // from Init r filebuf.Buf // implements io.Seek and io.Read batches []batch // location of each Batch and time of start timerGoids map[uint64]bool // the following are per Parse MinWant, MaxWant int64 // range wanted, from the arguments to Parse() Err error // set by internal functions to stop further processing Events []*Event // after Parse, the events from MinWant to MaxWant Preflen int // how long a prefix we added Ignored int // how many events we elided Added int // how many events we added, not including the prefix // internal processing variables seenArgs map[uint64]*[]uint64 byproc map[int][]*Event lastGs map[int]uint64 lastG uint64 lastP int lastTs int64 } func (p *Parsed) String() string { ans := []string{} ans = append(ans, fmt.Sprintf("%s Sz:%d Count:%d MaxTs:%d #strs:%d #stks:%d", p.Name, p.Size, p.Count, p.MaxTs, len(p.Strings), len(p.Stacks))) ans = append(ans, fmt.Sprintf("%d clock:%d ticks:(%d,%d) #b:%d", p.Version, p.TicksPerSec, p.minticks, p.maxticks, len(p.batches))) return strings.Join(ans, "\n\t") } // clean up after previous call to Parse func (p *Parsed) clean() { // some of these are redundant p.Err = nil p.Events = nil p.Preflen = 0 p.Ignored = 0 p.Added = 0 p.seenArgs = nil // redundant, but safe p.byproc = nil p.lastGs = nil p.lastG = 0 p.lastTs = 0 } // Frame is a frame in a stack traces type Frame struct { PC uint64 Fn string File string Line int } // An Event is the parsed form of a single trace event type Event struct { Type byte P int32 Ts int64 G uint64 StkID uint32 // key to Parsed.Stacks Args [3]uint64 SArgs []string // EvUserLog has 2. Others are 1 or none Link *Event } // Batch remembers the EvBatch events. PJW: keep an index of User events? type batch struct { Off int P int64 Cycles int64 // as read from EvBatch Nano int64 // start time of batch, set in commonInit() raws []rawEvent // filled in during Parse() for those batches that overlap the desired interval } // rawEvent is a raw event parsed from batches that overlap the time interval type rawEvent struct { // about 75 bytes // the choice of what to share (args) and what to make unique per rawEvent // (arg0, sarg) was done by measuring the space impact of various choices. off uint32 // offset in batch (at batch.Off + off in file) typ byte arg0 uint64 args *[]uint64 // remainder of the args (frequently nil), shared sarg string } func (r rawEvent) String() string { if r.args != nil && len(*r.args) > 0 { return fmt.Sprintf("[%s %d %v %s]", evname(r.typ), r.arg0, *r.args, r.sarg) } return fmt.Sprintf("[%s, %d, [], %s]", evname(r.typ), r.arg0, r.sarg) } // New scans the trace file, finding the number of events, the earliest and latest // timestamps, and the stacks and strings referenced in the file. func New(fname string) (*Parsed, error) { fd, err := filebuf.New(fname) if err != nil { return nil, err } return commonInit(fd, fname) } // ParseError may be returned by New() or ParseBuffer() to make available // some information in the case that the raw trace file seems to contain // negative time stamps. (In P, Name, Size, count, Strings, Stacks, Versions are valid, // and MaxTs or TicksPerSec is negative.) type ParseError struct { P *Parsed Err error } func (pe ParseError) Error() string { return pe.Err.Error() } func commonInit(fd filebuf.Buf, fname string) (*Parsed, error) { ans := &Parsed{Name: fname, minticks: 1 << 62} // minticks can only decrease var err error defer func() { if err != nil { fd.Close() // try to clean up after error } }() ans.Size = fd.Size() ans.r = fd // parseRaw here for header, trailer: clock, stacks, strings, if err = ans.parseHeader(); err != nil { return nil, err } if err = ans.scanFile(); err != nil { return nil, err } // done with seenArgs ans.seenArgs = nil // convert the clicks in batches to nanoseconds ans.toNanoseconds() if ans.MaxTs <= 0 || ans.TicksPerSec <= 0 { err := ParseError{ P: ans, Err: fmt.Errorf("corrupt trace file: negative time: (max TS=%d, ticks per sec=%d", ans.MaxTs, ans.TicksPerSec), } return nil, err } return ans, nil } // Parse parses the events in the interval: start <= ts <= start+length. // f, if not nil, will be called at various stages of the parse, each identified by the string // argument. It could report on elapsed time, or memory usage, or whatever the user wants. // The number of times it is called and the contents of the string argument are both // changeable details of the implementation. Parse is not safe for concurrent use. func (p *Parsed) Parse(start, length int64, f func(string)) error { p.clean() if f == nil { f = func(string) {} // avoid any further testing for nil } p.MinWant = start p.MaxWant = start + length // arrange the slice of batches by P byp := map[int64][]*batch{} // PJW: keep track of the order the Ps occur and use that for batchify for i, b := range p.batches { byp[b.P] = append(byp[b.P], &p.batches[i]) p.batches[i].raws = nil // reset from last call to Parse } // batchify the ones that overlap the time range for _, v := range byp { for i := 0; i < len(v); i++ { b := v[i] var bnext *batch if i < len(v)-1 { bnext = v[i+1] } if b.Nano >= p.MaxWant { // starts too late continue } else if b.Nano <= p.MinWant && (bnext != nil && bnext.Nano <= p.MinWant) { // entirely too early continue } err := p.batchify(b) if err != nil { return err } } } f("batchify done") return p.createEvents(f) } // ParseBuffer treats its argument as a trace file, and returns the // result of parsing it func ParseBuffer(rd io.Reader) (*Parsed, error) { pr, err := filebuf.FromReader(rd) if err != nil { return nil, err } p, err := commonInit(pr, "") if err != nil { return nil, err } // need the version and the initial scan err = p.Parse(0, 1<<62, nil) if err != nil { return nil, err } return p, nil } // called from commonInit to compute the nanosecond when batches start func (p *Parsed) toNanoseconds() { minCycles := p.minticks freq := 1e9 / float64(p.TicksPerSec) // Batches, and more to come. Don't call this twice! for i, ex := range p.batches { p.batches[i].Nano = int64(float64(ex.Cycles-minCycles) * freq) } p.MaxTs = int64(float64(p.maxticks-minCycles) * freq) } // argsAt returns the args of an event in the file and the offset for the next event. // // For EvString it returns off, nil, nil, and // for EvUserLog it ignores the string argument, which must be read by the // caller. func (p *Parsed) argsAt(off int, check byte) (int, []uint64, error) { off0 := off r := p.r loc, err := r.Seek(int64(off), 0) if err != nil { panic(err) } var buf [1]byte n, err := r.Read(buf[:]) if err != nil || n != 1 { return 0, nil, fmt.Errorf("read failed at 0x%x, %d %v, loc=%d", off, n, err, loc) } off += n typ := buf[0] << 2 >> 2 narg := buf[0]>>6 + 1 inlineArgs := byte(4) if typ == EvNone || typ >= EvCount || EventDescriptions[typ].MinVersion > p.Version { return 0, nil, fmt.Errorf("unk type %v at offset 0x%x", typ, off0) } if typ == EvString { // skip, wihtout error checking _, off, err = readVal(r, off) var ln uint64 ln, off, err = readVal(r, off) off += int(ln) return off, nil, nil } args := []uint64{} if narg < inlineArgs { for i := 0; i < int(narg); i++ { var v uint64 v, off, err = readVal(r, off) if err != nil { err = fmt.Errorf("failed to read event %v argument at offset %v (%v)", typ, off, err) return 0, nil, err } args = append(args, v) } } else { // More than inlineArgs args, the first value is length of the event in bytes. var v uint64 v, off, err = readVal(r, off) if err != nil { err = fmt.Errorf("failed to read event %v argument at offset %v (%v)", typ, off, err) return 0, nil, err } evLen := v off1 := off for evLen > uint64(off-off1) { v, off, err = readVal(r, off) if err != nil { err = fmt.Errorf("failed to read event %v argument at offset %v (%v)", typ, off, err) return 0, nil, err } args = append(args, v) } if evLen != uint64(off-off1) { err = fmt.Errorf("event has wrong length at offset 0x%x: want %v, got %v", off0, evLen, off-off1) return 0, nil, err } } // This routine does not read the string argument. Callers must tread EvUserLog specially. return off, args, nil } // read a string from r func readStr(r io.Reader, off0 int) (s string, off int, err error) { var sz uint64 sz, off, err = readVal(r, off0) if err != nil || sz == 0 { return "", off, err } if sz > 1e6 { return "", off, fmt.Errorf("string at offset %d is too large (len=%d)", off, sz) } buf := make([]byte, sz) n, err := io.ReadFull(r, buf) if err != nil || sz != uint64(n) { return "", off + n, fmt.Errorf("failed to read trace at offset %d: read %v, want %v, error %v", off, n, sz, err) } return string(buf), off + n, 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 %d: 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) } // OSStats reports on the underlying i/o. If p was created by New, // the fields report filesystem activity. If p was created by ParseBuffer, // only Size is set. func (p *Parsed) OSStats() filebuf.Stat { return p.r.Stats() } func (ev *Event) String() string { var tslink int64 if ev.Link != nil { tslink = ev.Link.Ts } return fmt.Sprintf("[g:%d p:%d %s/%d %v %v %x ->%x]", ev.G, ev.P, evname(ev.Type), ev.Type, ev.Args, ev.SArgs, ev.Ts, tslink) } func evname(t byte) string { if t >= EvCount || t < 0 { return fmt.Sprintf("typ%d?", t) } return EventDescriptions[t].Name } // Close the underlying file. func (p *Parsed) Close() error { return p.r.Close() } // Event types in the trace. // Verbatim copy from src/runtime/trace.go with the "trace" prefix removed. 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 {PC, func string ID, file string ID, line}] EvGomaxprocs = 4 // current value of GOMAXPROCS [timestamp, GOMAXPROCS, stack id] EvProcStart = 5 // start of P [timestamp, thread id] EvProcStop = 6 // stop of P [timestamp] EvGCStart = 7 // GC start [timestamp, seq, stack id] EvGCDone = 8 // GC done [timestamp] EvGCSTWStart = 9 // GC mark termination start [timestamp, kind] EvGCSTWDone = 10 // GC mark termination done [timestamp] EvGCSweepStart = 11 // GC sweep start [timestamp, stack id] EvGCSweepDone = 12 // GC sweep done [timestamp, swept, reclaimed] EvGoCreate = 13 // goroutine creation [timestamp, new goroutine id, new stack id, stack id] EvGoStart = 14 // goroutine starts running [timestamp, goroutine id, seq] 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, seq, 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, seq, real timestamp] EvGoSysBlock = 30 // syscall blocks [timestamp] EvGoWaiting = 31 // denotes that goroutine is blocked when tracing starts [timestamp, goroutine id] EvGoInSyscall = 32 // denotes that goroutine is in syscall when tracing starts [timestamp, goroutine id] EvHeapAlloc = 33 // memstats.heap_live change [timestamp, heap_alloc] EvNextGC = 34 // memstats.next_gc change [timestamp, next_gc] EvTimerGoroutine = 35 // denotes timer goroutine [timer goroutine id] EvFutileWakeup = 36 // denotes that the previous wakeup of this goroutine was futile [timestamp] EvString = 37 // string dictionary entry [ID, length, string] EvGoStartLocal = 38 // goroutine starts running on the same P as the last event [timestamp, goroutine id] EvGoUnblockLocal = 39 // goroutine is unblocked on the same P as the last event [timestamp, goroutine id, stack] EvGoSysExitLocal = 40 // syscall exit on the same P as the last event [timestamp, goroutine id, real timestamp] EvGoStartLabel = 41 // goroutine starts running with label [timestamp, goroutine id, seq, label string id] EvGoBlockGC = 42 // goroutine blocks on GC assist [timestamp, stack] EvGCMarkAssistStart = 43 // GC mark assist start [timestamp, stack] EvGCMarkAssistDone = 44 // GC mark assist done [timestamp] EvUserTaskCreate = 45 // trace.NewContext [timestamp, internal task id, internal parent id, stack, name string] EvUserTaskEnd = 46 // end of task [timestamp, internal task id, stack] EvUserRegion = 47 // trace.WithSpan [timestamp, internal task id, mode(0:start, 1:end), stack, name string] EvUserLog = 48 // trace.Log [timestamp, internal id, key string id, stack, value string] EvCount = 49 ) // EventDescriptions describe the Events var EventDescriptions = [EvCount]struct { Name string MinVersion int Stack bool Args []string SArgs []string // string arguments }{ EvNone: {"None", 1005, false, []string{}, nil}, EvBatch: {"Batch", 1005, false, []string{"p", "ticks"}, nil}, // in 1.5 format it was {"p", "seq", "ticks"} EvFrequency: {"Frequency", 1005, false, []string{"freq"}, nil}, // in 1.5 format it was {"freq", "unused"} EvStack: {"Stack", 1005, false, []string{"id", "siz"}, nil}, EvGomaxprocs: {"Gomaxprocs", 1005, true, []string{"procs"}, nil}, EvProcStart: {"ProcStart", 1005, false, []string{"thread"}, nil}, EvProcStop: {"ProcStop", 1005, false, []string{}, nil}, EvGCStart: {"GCStart", 1005, true, []string{"seq"}, nil}, // in 1.5 format it was {} EvGCDone: {"GCDone", 1005, false, []string{}, nil}, EvGCSTWStart: {"GCSTWStart", 1005, false, []string{"kindid"}, []string{"kind"}}, // <= 1.9, args was {} (implicitly {0}) EvGCSTWDone: {"GCSTWDone", 1005, false, []string{}, nil}, EvGCSweepStart: {"GCSweepStart", 1005, true, []string{}, nil}, EvGCSweepDone: {"GCSweepDone", 1005, false, []string{"swept", "reclaimed"}, nil}, // before 1.9, format was {} EvGoCreate: {"GoCreate", 1005, true, []string{"g", "stack"}, nil}, EvGoStart: {"GoStart", 1005, false, []string{"g", "seq"}, nil}, // in 1.5 format it was {"g"} EvGoEnd: {"GoEnd", 1005, false, []string{}, nil}, EvGoStop: {"GoStop", 1005, true, []string{}, nil}, EvGoSched: {"GoSched", 1005, true, []string{}, nil}, EvGoPreempt: {"GoPreempt", 1005, true, []string{}, nil}, EvGoSleep: {"GoSleep", 1005, true, []string{}, nil}, EvGoBlock: {"GoBlock", 1005, true, []string{}, nil}, EvGoUnblock: {"GoUnblock", 1005, true, []string{"g", "seq"}, nil}, // in 1.5 format it was {"g"} EvGoBlockSend: {"GoBlockSend", 1005, true, []string{}, nil}, EvGoBlockRecv: {"GoBlockRecv", 1005, true, []string{}, nil}, EvGoBlockSelect: {"GoBlockSelect", 1005, true, []string{}, nil}, EvGoBlockSync: {"GoBlockSync", 1005, true, []string{}, nil}, EvGoBlockCond: {"GoBlockCond", 1005, true, []string{}, nil}, EvGoBlockNet: {"GoBlockNet", 1005, true, []string{}, nil}, EvGoSysCall: {"GoSysCall", 1005, true, []string{}, nil}, EvGoSysExit: {"GoSysExit", 1005, false, []string{"g", "seq", "ts"}, nil}, EvGoSysBlock: {"GoSysBlock", 1005, false, []string{}, nil}, EvGoWaiting: {"GoWaiting", 1005, false, []string{"g"}, nil}, EvGoInSyscall: {"GoInSyscall", 1005, false, []string{"g"}, nil}, EvHeapAlloc: {"HeapAlloc", 1005, false, []string{"mem"}, nil}, EvNextGC: {"NextGC", 1005, false, []string{"mem"}, nil}, EvTimerGoroutine: {"TimerGoroutine", 1005, false, []string{"g"}, nil}, // in 1.5 format it was {"g", "unused"} EvFutileWakeup: {"FutileWakeup", 1005, false, []string{}, nil}, EvString: {"String", 1007, false, []string{}, nil}, EvGoStartLocal: {"GoStartLocal", 1007, false, []string{"g"}, nil}, EvGoUnblockLocal: {"GoUnblockLocal", 1007, true, []string{"g"}, nil}, EvGoSysExitLocal: {"GoSysExitLocal", 1007, false, []string{"g", "ts"}, nil}, EvGoStartLabel: {"GoStartLabel", 1008, false, []string{"g", "seq", "labelid"}, []string{"label"}}, EvGoBlockGC: {"GoBlockGC", 1008, true, []string{}, nil}, EvGCMarkAssistStart: {"GCMarkAssistStart", 1009, true, []string{}, nil}, EvGCMarkAssistDone: {"GCMarkAssistDone", 1009, false, []string{}, nil}, EvUserTaskCreate: {"UserTaskCreate", 1011, true, []string{"taskid", "pid", "typeid"}, []string{"name"}}, EvUserTaskEnd: {"UserTaskEnd", 1011, true, []string{"taskid"}, nil}, EvUserRegion: {"UserRegion", 1011, true, []string{"taskid", "mode", "typeid"}, []string{"name"}}, EvUserLog: {"UserLog", 1011, true, []string{"id", "keyid"}, []string{"category", "message"}}, }