// 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" "math/rand" "os" "os/exec" "path/filepath" "runtime" "strconv" "strings" _ "unsafe" ) func goCmd() string { var exeSuffix string if runtime.GOOS == "windows" { exeSuffix = ".exe" } path := filepath.Join(runtime.GOROOT(), "bin", "go"+exeSuffix) if _, err := os.Stat(path); err == nil { return path } return "go" } // 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 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 [3]uint64 // event-type-specific arguments SArgs []string // event-type-specific string args // linked event (can be nil), depends on event type: // for GCStart: the GCStop // for GCSTWStart: the GCSTWDone // for GCSweepStart: the GCSweepDone // for GoCreate: first GoStart of the created goroutine // for GoStart/GoStartLabel: 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 // for GCMarkAssistStart: the associated GCMarkAssistDone // for UserTaskCreate: the UserTaskEnd // for UserRegion: if the start region, the corresponding UserRegion end event 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 GCP // depicts GC state ProfileP // depicts recording of CPU profile samples ) // ParseResult is the result of Parse. type ParseResult struct { // Events is the sorted list of Events in the trace. Events []*Event // Stacks is the stack traces keyed by stack IDs from the trace. Stacks map[uint64][]*Frame } // Parse parses, post-processes and verifies the trace. func Parse(r io.Reader, bin string) (ParseResult, error) { ver, res, err := parse(r, bin) if err != nil { return ParseResult{}, err } if ver < 1007 && bin == "" { return ParseResult{}, fmt.Errorf("for traces produced by go 1.6 or below, the binary argument must be provided") } return res, nil } // parse parses, post-processes and verifies the trace. It returns the // trace version and the list of events. func parse(r io.Reader, bin string) (int, ParseResult, error) { ver, rawEvents, strings, err := readTrace(r) if err != nil { return 0, ParseResult{}, err } events, stacks, err := parseEvents(ver, rawEvents, strings) if err != nil { return 0, ParseResult{}, err } events = removeFutile(events) err = postProcessTrace(ver, events) if err != nil { return 0, ParseResult{}, err } // Attach stack traces. for _, ev := range events { if ev.StkID != 0 { ev.Stk = stacks[ev.StkID] } } if ver < 1007 && bin != "" { if err := symbolize(events, bin); err != nil { return 0, ParseResult{}, err } } return ver, ParseResult{Events: events, Stacks: stacks}, nil } // rawEvent is a helper type used during parsing. type rawEvent struct { off int typ byte args []uint64 sargs []string } func ReadVersion(r io.Reader) (ver int, off int, err error) { // Read and validate trace header. var buf [16]byte off, err = io.ReadFull(r, buf[:]) if err != nil { err = fmt.Errorf("failed to read header: read %v, err %v", off, err) return } ver, err = parseHeader(buf[:]) return } // readTrace does wire-format parsing and verification. // It does not care about specific event types and argument meaning. func readTrace(r io.Reader) (ver int, events []rawEvent, strings map[uint64]string, err error) { var off int ver, off, err = ReadVersion(r) if err != nil { return } switch ver { case 1005, 1007, 1008, 1009, 1010, 1011, 1019, 1021: // Note: When adding a new version, confirm that canned traces from the // old version are part of the test suite. Add them using mkcanned.bash. break default: err = fmt.Errorf("unsupported trace file version %v.%v (update Go toolchain) %v", ver/1000, ver%1000, ver) return } // Read events. var buf [16]byte strings = make(map[uint64]string) for { // Read event type and number of arguments (1 byte). off0 := off var n int n, err = r.Read(buf[:1]) if err == io.EOF { err = nil break } if err != nil || n != 1 { 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 + 1 inlineArgs := byte(4) if ver < 1007 { narg++ inlineArgs++ } 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 } if id == 0 { err = fmt.Errorf("string at offset %d has invalid id 0", off) return } if strings[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 } if ln == 0 { err = fmt.Errorf("string at offset %d has invalid length 0", off) return } if ln > 1e6 { err = fmt.Errorf("string at offset %d has too large length %v", off, ln) return } buf := make([]byte, ln) var n int n, err = io.ReadFull(r, buf) if err != nil { 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) continue } ev := rawEvent{typ: typ, off: off0} 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 } ev.args = append(ev.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 } 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 } ev.args = append(ev.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 } } switch ev.typ { case EvUserLog: // EvUserLog records are followed by a value string of length ev.args[len(ev.args)-1] var s string s, off, err = readStr(r, off) ev.sargs = append(ev.sargs, s) } events = append(events, ev) } return } 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 } // 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(ver int, rawEvents []rawEvent, strings map[uint64]string) (events []*Event, stacks map[uint64][]*Frame, err error) { var ticksPerSec, lastSeq, lastTs int64 var lastG uint64 var lastP int timerGoids := make(map[uint64]bool) lastGs := make(map[int]uint64) // last goroutine running on P stacks = make(map[uint64][]*Frame) batches := make(map[int][]*Event) // events by P for _, raw := range rawEvents { desc := EventDescriptions[raw.typ] if desc.Name == "" { err = fmt.Errorf("missing description for event type %v", raw.typ) return } narg := argNum(raw, ver) 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] if ver < 1007 { lastSeq = int64(raw.args[1]) lastTs = int64(raw.args[2]) } else { lastTs = int64(raw.args[1]) } case EvFrequency: ticksPerSec = int64(raw.args[0]) if ticksPerSec <= 0 { // The most likely cause for this is tick skew on different CPUs. // For example, solaris/amd64 seems to have wildly different // ticks on different CPUs. err = ErrTimeOrder return } case EvTimerGoroutine: timerGoids[raw.args[0]] = true 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 } 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 } id := raw.args[0] if id != 0 && size > 0 { stk := make([]*Frame, size) for i := 0; i < int(size); i++ { 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} var argOffset int if ver < 1007 { e.seq = lastSeq + int64(raw.args[0]) e.Ts = lastTs + int64(raw.args[1]) lastSeq = e.seq argOffset = 2 } else { e.Ts = lastTs + int64(raw.args[0]) argOffset = 1 } lastTs = e.Ts for i := argOffset; i < narg; i++ { if i == narg-1 && desc.Stack { e.StkID = raw.args[i] } else { e.Args[i-argOffset] = raw.args[i] } } switch raw.typ { case EvGoStart, EvGoStartLocal, EvGoStartLabel: lastG = e.Args[0] e.G = lastG if raw.typ == EvGoStartLabel { e.SArgs = []string{strings[e.Args[2]]} } case EvSTWStart: e.G = 0 if ver < 1021 { switch e.Args[0] { case 0: e.SArgs = []string{"mark termination"} case 1: e.SArgs = []string{"sweep termination"} default: err = fmt.Errorf("unknown STW kind %d", e.Args[0]) return } } else if ver == 1021 { if kind := e.Args[0]; kind < uint64(len(stwReasonStringsGo121)) { e.SArgs = []string{stwReasonStringsGo121[kind]} } else { e.SArgs = []string{"unknown"} } } else { // Can't make any assumptions. e.SArgs = []string{"unknown"} } case EvGCStart, EvGCDone, EvSTWDone: e.G = 0 case EvGoEnd, EvGoStop, EvGoSched, EvGoPreempt, EvGoSleep, EvGoBlock, EvGoBlockSend, EvGoBlockRecv, EvGoBlockSelect, EvGoBlockSync, EvGoBlockCond, EvGoBlockNet, EvGoSysBlock, EvGoBlockGC: lastG = 0 case EvGoSysExit, EvGoWaiting, EvGoInSyscall: e.G = e.Args[0] case EvUserTaskCreate: // e.Args 0: taskID, 1:parentID, 2:nameID e.SArgs = []string{strings[e.Args[2]]} case EvUserRegion: // e.Args 0: taskID, 1: mode, 2:nameID e.SArgs = []string{strings[e.Args[2]]} case EvUserLog: // e.Args 0: taskID, 1:keyID, 2: stackID e.SArgs = []string{strings[e.Args[1]], raw.sargs[0]} case EvCPUSample: e.Ts = int64(e.Args[0]) e.P = int(e.Args[1]) e.G = e.Args[2] e.Args[0] = 0 } switch raw.typ { default: batches[lastP] = append(batches[lastP], e) case EvCPUSample: // Most events are written out by the active P at the exact // moment they describe. CPU profile samples are different // because they're written to the tracing log after some delay, // by a separate worker goroutine, into a separate buffer. // // We keep these in their own batch until all of the batches are // merged in timestamp order. We also (right before the merge) // re-sort these events by the timestamp captured in the // profiling signal handler. batches[ProfileP] = append(batches[ProfileP], e) } } } if len(batches) == 0 { err = fmt.Errorf("trace is empty") return } if ticksPerSec == 0 { err = fmt.Errorf("no EvFrequency event") return } if BreakTimestampsForTesting { var batchArr [][]*Event for _, batch := range batches { batchArr = append(batchArr, batch) } for i := 0; i < 5; i++ { batch := batchArr[rand.Intn(len(batchArr))] batch[rand.Intn(len(batch))].Ts += int64(rand.Intn(2000) - 1000) } } if ver < 1007 { events, err = order1005(batches) } else { events, err = order1007(batches) } if err != nil { return } // Translate cpu ticks to real time. minTs := events[0].Ts // Use floating point to avoid integer overflows. freq := 1e9 / float64(ticksPerSec) for _, ev := range events { ev.Ts = int64(float64(ev.Ts-minTs) * freq) // Move timers and syscalls to separate fake Ps. if timerGoids[ev.G] && ev.Type == EvGoUnblock { ev.P = TimerP } if ev.Type == EvGoSysExit { ev.P = SyscallP } } return } // removeFutile removes all constituents of futile wakeups (block, unblock, start). // For example, a goroutine was unblocked on a mutex, but another goroutine got // ahead and acquired the mutex before the first goroutine is scheduled, // so the first goroutine has to block again. Such wakeups happen on buffered // channels and sync.Mutex, but are generally not interesting for end user. func removeFutile(events []*Event) []*Event { // Two non-trivial aspects: // 1. A goroutine can be preempted during a futile wakeup and migrate to another P. // We want to remove all of that. // 2. Tracing can start in the middle of a futile wakeup. // That is, we can see a futile wakeup event w/o the actual wakeup before it. // postProcessTrace runs after us and ensures that we leave the trace in a consistent state. // Phase 1: determine futile wakeup sequences. type G struct { futile bool wakeup []*Event // wakeup sequence (subject for removal) } gs := make(map[uint64]G) futile := make(map[*Event]bool) for _, ev := range events { switch ev.Type { case EvGoUnblock: g := gs[ev.Args[0]] g.wakeup = []*Event{ev} gs[ev.Args[0]] = g case EvGoStart, EvGoPreempt, EvFutileWakeup: g := gs[ev.G] g.wakeup = append(g.wakeup, ev) if ev.Type == EvFutileWakeup { g.futile = true } gs[ev.G] = g case EvGoBlock, EvGoBlockSend, EvGoBlockRecv, EvGoBlockSelect, EvGoBlockSync, EvGoBlockCond: g := gs[ev.G] if g.futile { futile[ev] = true for _, ev1 := range g.wakeup { futile[ev1] = true } } delete(gs, ev.G) } } // Phase 2: remove futile wakeup sequences. newEvents := events[:0] // overwrite the original slice for _, ev := range events { if !futile[ev] { newEvents = append(newEvents, ev) } } return newEvents } // ErrTimeOrder is returned by Parse when the trace contains // time stamps that do not respect actual event ordering. var ErrTimeOrder = fmt.Errorf("time stamps out of order") // 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(ver int, events []*Event) error { const ( gDead = iota gRunnable gRunning gWaiting ) type gdesc struct { state int ev *Event evStart *Event evCreate *Event evMarkAssist *Event } type pdesc struct { running bool g uint64 evSTW *Event evSweep *Event } gs := make(map[uint64]gdesc) ps := make(map[int]pdesc) tasks := make(map[uint64]*Event) // task id to task creation events activeRegions := make(map[uint64][]*Event) // goroutine id to stack of regions gs[0] = gdesc{state: gRunning} var evGC, evSTW *Event checkRunning := func(p pdesc, g gdesc, ev *Event, allowG0 bool) 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) } if !allowG0 && ev.G == 0 { return fmt.Errorf("g 0 did %v (offset %v, time %v)", EventDescriptions[ev.Type].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 evGC != nil { return fmt.Errorf("previous GC is not ended before a new one (offset %v, time %v)", ev.Off, ev.Ts) } evGC = ev // Attribute this to the global GC state. ev.P = GCP case EvGCDone: if evGC == nil { return fmt.Errorf("bogus GC end (offset %v, time %v)", ev.Off, ev.Ts) } evGC.Link = ev evGC = nil case EvSTWStart: evp := &evSTW if ver < 1010 { // Before 1.10, EvSTWStart was per-P. evp = &p.evSTW } if *evp != nil { return fmt.Errorf("previous STW is not ended before a new one (offset %v, time %v)", ev.Off, ev.Ts) } *evp = ev case EvSTWDone: evp := &evSTW if ver < 1010 { // Before 1.10, EvSTWDone was per-P. evp = &p.evSTW } if *evp == nil { return fmt.Errorf("bogus STW end (offset %v, time %v)", ev.Off, ev.Ts) } (*evp).Link = ev *evp = 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 EvGCMarkAssistStart: if g.evMarkAssist != nil { return fmt.Errorf("previous mark assist is not ended before a new one (offset %v, time %v)", ev.Off, ev.Ts) } g.evMarkAssist = ev case EvGCMarkAssistDone: // Unlike most events, mark assists can be in progress when a // goroutine starts tracing, so we can't report an error here. if g.evMarkAssist != nil { g.evMarkAssist.Link = ev g.evMarkAssist = nil } 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: if g.state != gRunnable { return fmt.Errorf("g %v is not runnable before EvGoWaiting (offset %v, time %v)", ev.G, ev.Off, ev.Ts) } g.state = gWaiting g.ev = ev case EvGoInSyscall: if g.state != gRunnable { return fmt.Errorf("g %v is not runnable before EvGoInSyscall (offset %v, time %v)", ev.G, ev.Off, ev.Ts) } g.state = gWaiting g.ev = ev case EvGoCreate: if err := checkRunning(p, g, ev, true); 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, evCreate: ev} case EvGoStart, EvGoStartLabel: 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.evCreate != nil { 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 } if g.ev != nil { g.ev.Link = ev g.ev = nil } case EvGoEnd, EvGoStop: if err := checkRunning(p, g, ev, false); err != nil { return err } g.evStart.Link = ev g.evStart = nil g.state = gDead p.g = 0 if ev.Type == EvGoEnd { // flush all active regions regions := activeRegions[ev.G] for _, s := range regions { s.Link = ev } delete(activeRegions, ev.G) } case EvGoSched, EvGoPreempt: if err := checkRunning(p, g, ev, false); 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, false); err != nil { return err } g.ev = ev case EvGoSysBlock: if err := checkRunning(p, g, ev, false); err != nil { return err } g.state = gWaiting g.evStart.Link = ev g.evStart = nil p.g = 0 case EvGoSysExit: if g.state != gWaiting { return fmt.Errorf("g %v is not waiting 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.state = gRunnable g.ev = ev case EvGoSleep, EvGoBlock, EvGoBlockSend, EvGoBlockRecv, EvGoBlockSelect, EvGoBlockSync, EvGoBlockCond, EvGoBlockNet, EvGoBlockGC: if err := checkRunning(p, g, ev, false); err != nil { return err } g.state = gWaiting g.ev = ev g.evStart.Link = ev g.evStart = nil p.g = 0 case EvUserTaskCreate: taskid := ev.Args[0] if prevEv, ok := tasks[taskid]; ok { return fmt.Errorf("task id conflicts (id:%d), %q vs %q", taskid, ev, prevEv) } tasks[ev.Args[0]] = ev case EvUserTaskEnd: taskid := ev.Args[0] if taskCreateEv, ok := tasks[taskid]; ok { taskCreateEv.Link = ev delete(tasks, taskid) } case EvUserRegion: mode := ev.Args[1] regions := activeRegions[ev.G] if mode == 0 { // region start activeRegions[ev.G] = append(regions, ev) // push } else if mode == 1 { // region end n := len(regions) if n > 0 { // matching region start event is in the trace. s := regions[n-1] if s.Args[0] != ev.Args[0] || s.SArgs[0] != ev.SArgs[0] { // task id, region name mismatch 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) } // Link region start event with span end event s.Link = ev if n > 1 { activeRegions[ev.G] = regions[:n-1] } else { delete(activeRegions, ev.G) } } } else { return fmt.Errorf("invalid user region mode: %q", ev) } } 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 } // 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(goCmd(), "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 %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) } // Print dumps events to stdout. For debugging. func Print(events []*Event) { for _, ev := range events { PrintEvent(ev) } } // PrintEvent dumps the event to stdout. For debugging. func PrintEvent(ev *Event) { fmt.Printf("%s\n", ev) } func (ev *Event) String() string { desc := EventDescriptions[ev.Type] w := new(strings.Builder) fmt.Fprintf(w, "%v %v p=%v g=%v off=%v", ev.Ts, desc.Name, ev.P, ev.G, ev.Off) for i, a := range desc.Args { fmt.Fprintf(w, " %v=%v", a, ev.Args[i]) } for i, a := range desc.SArgs { fmt.Fprintf(w, " %v=%v", a, ev.SArgs[i]) } return w.String() } // argNum returns total number of args for the event accounting for timestamps, // sequence numbers and differences between trace format versions. func argNum(raw rawEvent, ver int) int { desc := EventDescriptions[raw.typ] if raw.typ == EvStack { return len(raw.args) } narg := len(desc.Args) if desc.Stack { narg++ } switch raw.typ { case EvBatch, EvFrequency, EvTimerGoroutine: if ver < 1007 { narg++ // there was an unused arg before 1.7 } return narg } narg++ // timestamp if ver < 1007 { narg++ // sequence } switch raw.typ { case EvGCSweepDone: if ver < 1009 { narg -= 2 // 1.9 added two arguments } case EvGCStart, EvGoStart, EvGoUnblock: if ver < 1007 { narg-- // 1.7 added an additional seq arg } case EvSTWStart: if ver < 1010 { narg-- // 1.10 added an argument } } return narg } // BreakTimestampsForTesting causes the parser to randomly alter timestamps (for testing of broken cputicks). var BreakTimestampsForTesting bool // 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] EvSTWStart = 9 // GC mark termination start [timestamp, kind] EvSTWDone = 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 // gcController.heapLive change [timestamp, heap live bytes] EvHeapGoal = 34 // gcController.heapGoal change [timestamp, heap goal bytes] 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.NewTask [timestamp, internal task id, internal parent id, name string, stack] EvUserTaskEnd = 46 // end of task [timestamp, internal task id, stack] EvUserRegion = 47 // trace.WithRegion [timestamp, internal task id, mode(0:start, 1:end), name string, stack] EvUserLog = 48 // trace.Log [timestamp, internal id, key string id, stack, value string] EvCPUSample = 49 // CPU profiling sample [timestamp, real timestamp, real P id (-1 when absent), goroutine id, stack] EvCount = 50 ) 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}, EvSTWStart: {"STWStart", 1005, false, []string{"kindid"}, []string{"kind"}}, // <= 1.9, args was {} (implicitly {0}) EvSTWDone: {"STWDone", 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}, EvHeapGoal: {"HeapGoal", 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"}}, EvCPUSample: {"CPUSample", 1019, true, []string{"ts", "p", "g"}, nil}, } // Copied from src/runtime/proc.go:stwReasonStrings in Go 1.21. var stwReasonStringsGo121 = [...]string{ "unknown", "GC mark termination", "GC sweep termination", "write heap dump", "goroutine profile", "goroutine profile cleanup", "all goroutines stack trace", "read mem stats", "AllThreadsSyscall", "GOMAXPROCS", "start trace", "stop trace", "CountPagesInUse (test)", "ReadMetricsSlow (test)", "ReadMemStatsSlow (test)", "PageCachePagesLeaked (test)", "ResetDebugLog (test)", }