+++ /dev/null
-// 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 (
- "sort"
- "strings"
-)
-
-// GDesc contains statistics and execution details of a single goroutine.
-type GDesc struct {
- ID uint64
- Name string
- PC uint64
- CreationTime int64
- StartTime int64
- EndTime int64
-
- // List of regions in the goroutine, sorted based on the start time.
- Regions []*UserRegionDesc
-
- // Statistics of execution time during the goroutine execution.
- GExecutionStat
-
- *gdesc // private part.
-}
-
-// UserRegionDesc represents a region and goroutine execution stats
-// while the region was active.
-type UserRegionDesc struct {
- TaskID uint64
- Name string
-
- // Region start event. Normally EvUserRegion start event or nil,
- // but can be EvGoCreate event if the region is a synthetic
- // region representing task inheritance from the parent goroutine.
- Start *Event
-
- // Region end event. Normally EvUserRegion end event or nil,
- // but can be EvGoStop or EvGoEnd event if the goroutine
- // terminated without explicitly ending the region.
- End *Event
-
- GExecutionStat
-}
-
-// GExecutionStat contains statistics about a goroutine's execution
-// during a period of time.
-type GExecutionStat struct {
- ExecTime int64
- SchedWaitTime int64
- IOTime int64
- BlockTime int64
- SyscallTime int64
- GCTime int64
- SweepTime int64
- TotalTime int64
-}
-
-// sub returns the stats v-s.
-func (s GExecutionStat) sub(v GExecutionStat) (r GExecutionStat) {
- r = s
- r.ExecTime -= v.ExecTime
- r.SchedWaitTime -= v.SchedWaitTime
- r.IOTime -= v.IOTime
- r.BlockTime -= v.BlockTime
- r.SyscallTime -= v.SyscallTime
- r.GCTime -= v.GCTime
- r.SweepTime -= v.SweepTime
- r.TotalTime -= v.TotalTime
- return r
-}
-
-// snapshotStat returns the snapshot of the goroutine execution statistics.
-// This is called as we process the ordered trace event stream. lastTs and
-// activeGCStartTime are used to process pending statistics if this is called
-// before any goroutine end event.
-func (g *GDesc) snapshotStat(lastTs, activeGCStartTime int64) (ret GExecutionStat) {
- ret = g.GExecutionStat
-
- if g.gdesc == nil {
- return ret // finalized GDesc. No pending state.
- }
-
- if activeGCStartTime != 0 { // terminating while GC is active
- if g.CreationTime < activeGCStartTime {
- ret.GCTime += lastTs - activeGCStartTime
- } else {
- // The goroutine's lifetime completely overlaps
- // with a GC.
- ret.GCTime += lastTs - g.CreationTime
- }
- }
-
- if g.TotalTime == 0 {
- ret.TotalTime = lastTs - g.CreationTime
- }
-
- if g.lastStartTime != 0 {
- ret.ExecTime += lastTs - g.lastStartTime
- }
- if g.blockNetTime != 0 {
- ret.IOTime += lastTs - g.blockNetTime
- }
- if g.blockSyncTime != 0 {
- ret.BlockTime += lastTs - g.blockSyncTime
- }
- if g.blockSyscallTime != 0 {
- ret.SyscallTime += lastTs - g.blockSyscallTime
- }
- if g.blockSchedTime != 0 {
- ret.SchedWaitTime += lastTs - g.blockSchedTime
- }
- if g.blockSweepTime != 0 {
- ret.SweepTime += lastTs - g.blockSweepTime
- }
- return ret
-}
-
-// finalize is called when processing a goroutine end event or at
-// the end of trace processing. This finalizes the execution stat
-// and any active regions in the goroutine, in which case trigger is nil.
-func (g *GDesc) finalize(lastTs, activeGCStartTime int64, trigger *Event) {
- if trigger != nil {
- g.EndTime = trigger.Ts
- }
- finalStat := g.snapshotStat(lastTs, activeGCStartTime)
-
- g.GExecutionStat = finalStat
-
- // System goroutines are never part of regions, even though they
- // "inherit" a task due to creation (EvGoCreate) from within a region.
- // This may happen e.g. if the first GC is triggered within a region,
- // starting the GC worker goroutines.
- if !IsSystemGoroutine(g.Name) {
- for _, s := range g.activeRegions {
- s.End = trigger
- s.GExecutionStat = finalStat.sub(s.GExecutionStat)
- g.Regions = append(g.Regions, s)
- }
- }
- *(g.gdesc) = gdesc{}
-}
-
-// gdesc is a private part of GDesc that is required only during analysis.
-type gdesc struct {
- lastStartTime int64
- blockNetTime int64
- blockSyncTime int64
- blockSyscallTime int64
- blockSweepTime int64
- blockGCTime int64
- blockSchedTime int64
-
- activeRegions []*UserRegionDesc // stack of active regions
-}
-
-// GoroutineStats generates statistics for all goroutines in the trace.
-func GoroutineStats(events []*Event) map[uint64]*GDesc {
- gs := make(map[uint64]*GDesc)
- var lastTs int64
- var gcStartTime int64 // gcStartTime == 0 indicates gc is inactive.
- for _, ev := range events {
- lastTs = ev.Ts
- switch ev.Type {
- case EvGoCreate:
- g := &GDesc{ID: ev.Args[0], CreationTime: ev.Ts, gdesc: new(gdesc)}
- g.blockSchedTime = ev.Ts
- // When a goroutine is newly created, inherit the task
- // of the active region. For ease handling of this
- // case, we create a fake region description with the
- // task id. This isn't strictly necessary as this
- // goroutine may not be associated with the task, but
- // it can be convenient to see all children created
- // during a region.
- if creatorG := gs[ev.G]; creatorG != nil && len(creatorG.gdesc.activeRegions) > 0 {
- regions := creatorG.gdesc.activeRegions
- s := regions[len(regions)-1]
- if s.TaskID != 0 {
- g.gdesc.activeRegions = []*UserRegionDesc{
- {TaskID: s.TaskID, Start: ev},
- }
- }
- }
- gs[g.ID] = g
- case EvGoStart, EvGoStartLabel:
- g := gs[ev.G]
- if g.PC == 0 && len(ev.Stk) > 0 {
- g.PC = ev.Stk[0].PC
- g.Name = ev.Stk[0].Fn
- }
- g.lastStartTime = ev.Ts
- if g.StartTime == 0 {
- g.StartTime = ev.Ts
- }
- if g.blockSchedTime != 0 {
- g.SchedWaitTime += ev.Ts - g.blockSchedTime
- g.blockSchedTime = 0
- }
- case EvGoEnd, EvGoStop:
- g := gs[ev.G]
- g.finalize(ev.Ts, gcStartTime, ev)
- case EvGoBlockSend, EvGoBlockRecv, EvGoBlockSelect,
- EvGoBlockSync, EvGoBlockCond:
- g := gs[ev.G]
- g.ExecTime += ev.Ts - g.lastStartTime
- g.lastStartTime = 0
- g.blockSyncTime = ev.Ts
- case EvGoSched, EvGoPreempt:
- g := gs[ev.G]
- g.ExecTime += ev.Ts - g.lastStartTime
- g.lastStartTime = 0
- g.blockSchedTime = ev.Ts
- case EvGoSleep, EvGoBlock:
- g := gs[ev.G]
- g.ExecTime += ev.Ts - g.lastStartTime
- g.lastStartTime = 0
- case EvGoBlockNet:
- g := gs[ev.G]
- g.ExecTime += ev.Ts - g.lastStartTime
- g.lastStartTime = 0
- g.blockNetTime = ev.Ts
- case EvGoBlockGC:
- g := gs[ev.G]
- g.ExecTime += ev.Ts - g.lastStartTime
- g.lastStartTime = 0
- g.blockGCTime = ev.Ts
- case EvGoUnblock:
- g := gs[ev.Args[0]]
- if g.blockNetTime != 0 {
- g.IOTime += ev.Ts - g.blockNetTime
- g.blockNetTime = 0
- }
- if g.blockSyncTime != 0 {
- g.BlockTime += ev.Ts - g.blockSyncTime
- g.blockSyncTime = 0
- }
- g.blockSchedTime = ev.Ts
- case EvGoSysBlock:
- g := gs[ev.G]
- g.ExecTime += ev.Ts - g.lastStartTime
- g.lastStartTime = 0
- g.blockSyscallTime = ev.Ts
- case EvGoSysExit:
- g := gs[ev.G]
- if g.blockSyscallTime != 0 {
- g.SyscallTime += ev.Ts - g.blockSyscallTime
- g.blockSyscallTime = 0
- }
- g.blockSchedTime = ev.Ts
- case EvGCSweepStart:
- g := gs[ev.G]
- if g != nil {
- // Sweep can happen during GC on system goroutine.
- g.blockSweepTime = ev.Ts
- }
- case EvGCSweepDone:
- g := gs[ev.G]
- if g != nil && g.blockSweepTime != 0 {
- g.SweepTime += ev.Ts - g.blockSweepTime
- g.blockSweepTime = 0
- }
- case EvGCStart:
- gcStartTime = ev.Ts
- case EvGCDone:
- for _, g := range gs {
- if g.EndTime != 0 {
- continue
- }
- if gcStartTime < g.CreationTime {
- g.GCTime += ev.Ts - g.CreationTime
- } else {
- g.GCTime += ev.Ts - gcStartTime
- }
- }
- gcStartTime = 0 // indicates gc is inactive.
- case EvUserRegion:
- g := gs[ev.G]
- switch mode := ev.Args[1]; mode {
- case 0: // region start
- g.activeRegions = append(g.activeRegions, &UserRegionDesc{
- Name: ev.SArgs[0],
- TaskID: ev.Args[0],
- Start: ev,
- GExecutionStat: g.snapshotStat(lastTs, gcStartTime),
- })
- case 1: // region end
- var sd *UserRegionDesc
- if regionStk := g.activeRegions; len(regionStk) > 0 {
- n := len(regionStk)
- sd = regionStk[n-1]
- regionStk = regionStk[:n-1] // pop
- g.activeRegions = regionStk
- } else {
- sd = &UserRegionDesc{
- Name: ev.SArgs[0],
- TaskID: ev.Args[0],
- }
- }
- sd.GExecutionStat = g.snapshotStat(lastTs, gcStartTime).sub(sd.GExecutionStat)
- sd.End = ev
- g.Regions = append(g.Regions, sd)
- }
- }
- }
-
- for _, g := range gs {
- g.finalize(lastTs, gcStartTime, nil)
-
- // sort based on region start time
- sort.Slice(g.Regions, func(i, j int) bool {
- x := g.Regions[i].Start
- y := g.Regions[j].Start
- if x == nil {
- return true
- }
- if y == nil {
- return false
- }
- return x.Ts < y.Ts
- })
-
- g.gdesc = nil
- }
-
- return gs
-}
-
-// RelatedGoroutines finds a set of goroutines related to goroutine goid.
-func RelatedGoroutines(events []*Event, goid uint64) map[uint64]bool {
- // BFS of depth 2 over "unblock" edges
- // (what goroutines unblock goroutine goid?).
- gmap := make(map[uint64]bool)
- gmap[goid] = true
- for i := 0; i < 2; i++ {
- gmap1 := make(map[uint64]bool)
- for g := range gmap {
- gmap1[g] = true
- }
- for _, ev := range events {
- if ev.Type == EvGoUnblock && gmap[ev.Args[0]] {
- gmap1[ev.G] = true
- }
- }
- gmap = gmap1
- }
- gmap[0] = true // for GC events
- return gmap
-}
-
-func IsSystemGoroutine(entryFn string) bool {
- // This mimics runtime.isSystemGoroutine as closely as
- // possible.
- // Also, locked g in extra M (with empty entryFn) is system goroutine.
- return entryFn == "" || entryFn != "runtime.main" && strings.HasPrefix(entryFn, "runtime.")
-}
+++ /dev/null
-// Copyright 2016 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 (
- "fmt"
- "sort"
-)
-
-type eventBatch struct {
- events []*Event
- selected bool
-}
-
-type orderEvent struct {
- ev *Event
- batch int
- g uint64
- init gState
- next gState
-}
-
-type gStatus int
-
-type gState struct {
- seq uint64
- status gStatus
-}
-
-const (
- gDead gStatus = iota
- gRunnable
- gRunning
- gWaiting
-
- unordered = ^uint64(0)
- garbage = ^uint64(0) - 1
- noseq = ^uint64(0)
- seqinc = ^uint64(0) - 1
-)
-
-// order1007 merges a set of per-P event batches into a single, consistent stream.
-// The high level idea is as follows. Events within an individual batch are in
-// correct order, because they are emitted by a single P. So we need to produce
-// a correct interleaving of the batches. To do this we take first unmerged event
-// from each batch (frontier). Then choose subset that is "ready" to be merged,
-// that is, events for which all dependencies are already merged. Then we choose
-// event with the lowest timestamp from the subset, merge it and repeat.
-// This approach ensures that we form a consistent stream even if timestamps are
-// incorrect (condition observed on some machines).
-func order1007(m map[int][]*Event) (events []*Event, err error) {
- pending := 0
- // The ordering of CPU profile sample events in the data stream is based on
- // when each run of the signal handler was able to acquire the spinlock,
- // with original timestamps corresponding to when ReadTrace pulled the data
- // off of the profBuf queue. Re-sort them by the timestamp we captured
- // inside the signal handler.
- sort.Stable(eventList(m[ProfileP]))
- var batches []*eventBatch
- for _, v := range m {
- pending += len(v)
- batches = append(batches, &eventBatch{v, false})
- }
- gs := make(map[uint64]gState)
- var frontier []orderEvent
- for ; pending != 0; pending-- {
- for i, b := range batches {
- if b.selected || len(b.events) == 0 {
- continue
- }
- ev := b.events[0]
- g, init, next := stateTransition(ev)
- if !transitionReady(g, gs[g], init) {
- continue
- }
- frontier = append(frontier, orderEvent{ev, i, g, init, next})
- b.events = b.events[1:]
- b.selected = true
- // Get rid of "Local" events, they are intended merely for ordering.
- switch ev.Type {
- case EvGoStartLocal:
- ev.Type = EvGoStart
- case EvGoUnblockLocal:
- ev.Type = EvGoUnblock
- case EvGoSysExitLocal:
- ev.Type = EvGoSysExit
- }
- }
- if len(frontier) == 0 {
- return nil, fmt.Errorf("no consistent ordering of events possible")
- }
- sort.Sort(orderEventList(frontier))
- f := frontier[0]
- frontier[0] = frontier[len(frontier)-1]
- frontier = frontier[:len(frontier)-1]
- events = append(events, f.ev)
- transition(gs, f.g, f.init, f.next)
- if !batches[f.batch].selected {
- panic("frontier batch is not selected")
- }
- batches[f.batch].selected = false
- }
-
- // At this point we have a consistent stream of events.
- // Make sure time stamps respect the ordering.
- // The tests will skip (not fail) the test case if they see this error.
- if !sort.IsSorted(eventList(events)) {
- return nil, ErrTimeOrder
- }
-
- // The last part is giving correct timestamps to EvGoSysExit events.
- // The problem with EvGoSysExit is that actual syscall exit timestamp (ev.Args[2])
- // is potentially acquired long before event emission. So far we've used
- // timestamp of event emission (ev.Ts).
- // We could not set ev.Ts = ev.Args[2] earlier, because it would produce
- // seemingly broken timestamps (misplaced event).
- // We also can't simply update the timestamp and resort events, because
- // if timestamps are broken we will misplace the event and later report
- // logically broken trace (instead of reporting broken timestamps).
- lastSysBlock := make(map[uint64]int64)
- for _, ev := range events {
- switch ev.Type {
- case EvGoSysBlock, EvGoInSyscall:
- lastSysBlock[ev.G] = ev.Ts
- case EvGoSysExit:
- ts := int64(ev.Args[2])
- if ts == 0 {
- continue
- }
- block := lastSysBlock[ev.G]
- if block == 0 {
- return nil, fmt.Errorf("stray syscall exit")
- }
- if ts < block {
- return nil, ErrTimeOrder
- }
- ev.Ts = ts
- }
- }
- sort.Stable(eventList(events))
-
- return
-}
-
-// stateTransition returns goroutine state (sequence and status) when the event
-// becomes ready for merging (init) and the goroutine state after the event (next).
-func stateTransition(ev *Event) (g uint64, init, next gState) {
- switch ev.Type {
- case EvGoCreate:
- g = ev.Args[0]
- init = gState{0, gDead}
- next = gState{1, gRunnable}
- case EvGoWaiting, EvGoInSyscall:
- g = ev.G
- init = gState{1, gRunnable}
- next = gState{2, gWaiting}
- case EvGoStart, EvGoStartLabel:
- g = ev.G
- init = gState{ev.Args[1], gRunnable}
- next = gState{ev.Args[1] + 1, gRunning}
- case EvGoStartLocal:
- // noseq means that this event is ready for merging as soon as
- // frontier reaches it (EvGoStartLocal is emitted on the same P
- // as the corresponding EvGoCreate/EvGoUnblock, and thus the latter
- // is already merged).
- // seqinc is a stub for cases when event increments g sequence,
- // but since we don't know current seq we also don't know next seq.
- g = ev.G
- init = gState{noseq, gRunnable}
- next = gState{seqinc, gRunning}
- case EvGoBlock, EvGoBlockSend, EvGoBlockRecv, EvGoBlockSelect,
- EvGoBlockSync, EvGoBlockCond, EvGoBlockNet, EvGoSleep,
- EvGoSysBlock, EvGoBlockGC:
- g = ev.G
- init = gState{noseq, gRunning}
- next = gState{noseq, gWaiting}
- case EvGoSched, EvGoPreempt:
- g = ev.G
- init = gState{noseq, gRunning}
- next = gState{noseq, gRunnable}
- case EvGoUnblock, EvGoSysExit:
- g = ev.Args[0]
- init = gState{ev.Args[1], gWaiting}
- next = gState{ev.Args[1] + 1, gRunnable}
- case EvGoUnblockLocal, EvGoSysExitLocal:
- g = ev.Args[0]
- init = gState{noseq, gWaiting}
- next = gState{seqinc, gRunnable}
- case EvGCStart:
- g = garbage
- init = gState{ev.Args[0], gDead}
- next = gState{ev.Args[0] + 1, gDead}
- default:
- // no ordering requirements
- g = unordered
- }
- return
-}
-
-func transitionReady(g uint64, curr, init gState) bool {
- return g == unordered || (init.seq == noseq || init.seq == curr.seq) && init.status == curr.status
-}
-
-func transition(gs map[uint64]gState, g uint64, init, next gState) {
- if g == unordered {
- return
- }
- curr := gs[g]
- if !transitionReady(g, curr, init) {
- panic("event sequences are broken")
- }
- switch next.seq {
- case noseq:
- next.seq = curr.seq
- case seqinc:
- next.seq = curr.seq + 1
- }
- gs[g] = next
-}
-
-// order1005 merges a set of per-P event batches into a single, consistent stream.
-func order1005(m map[int][]*Event) (events []*Event, err error) {
- for _, batch := range m {
- events = append(events, batch...)
- }
- for _, ev := range events {
- if ev.Type == EvGoSysExit {
- // EvGoSysExit emission is delayed until the thread has a P.
- // Give it the real sequence number and time stamp.
- ev.seq = int64(ev.Args[1])
- if ev.Args[2] != 0 {
- ev.Ts = int64(ev.Args[2])
- }
- }
- }
- sort.Sort(eventSeqList(events))
- if !sort.IsSorted(eventList(events)) {
- return nil, ErrTimeOrder
- }
- return
-}
-
-type orderEventList []orderEvent
-
-func (l orderEventList) Len() int {
- return len(l)
-}
-
-func (l orderEventList) Less(i, j int) bool {
- return l[i].ev.Ts < l[j].ev.Ts
-}
-
-func (l orderEventList) Swap(i, j int) {
- l[i], l[j] = l[j], l[i]
-}
-
-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]
-}
-
-type eventSeqList []*Event
-
-func (l eventSeqList) Len() int {
- return len(l)
-}
-
-func (l eventSeqList) Less(i, j int) bool {
- return l[i].seq < l[j].seq
-}
-
-func (l eventSeqList) Swap(i, j int) {
- l[i], l[j] = l[j], l[i]
-}
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
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 (
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)",
-}