aboutsummaryrefslogtreecommitdiff
path: root/src/internal
diff options
context:
space:
mode:
Diffstat (limited to 'src/internal')
-rw-r--r--src/internal/testenv/testenv.go9
-rw-r--r--src/internal/trace/order.go278
-rw-r--r--src/internal/trace/parser.go487
-rw-r--r--src/internal/trace/parser_test.go113
-rw-r--r--src/internal/trace/testdata/http_1_5_goodbin0 -> 42218 bytes
-rw-r--r--src/internal/trace/testdata/stress_1_5_goodbin0 -> 7446 bytes
-rw-r--r--src/internal/trace/testdata/stress_1_5_unorderedbin0 -> 8194 bytes
-rw-r--r--src/internal/trace/testdata/stress_start_stop_1_5_goodbin0 -> 6997 bytes
8 files changed, 711 insertions, 176 deletions
diff --git a/src/internal/testenv/testenv.go b/src/internal/testenv/testenv.go
index e751e0cf11..9e684e3034 100644
--- a/src/internal/testenv/testenv.go
+++ b/src/internal/testenv/testenv.go
@@ -11,6 +11,7 @@
package testenv
import (
+ "flag"
"os"
"os/exec"
"path/filepath"
@@ -124,3 +125,11 @@ func MustHaveExternalNetwork(t *testing.T) {
t.Skipf("skipping test: no external network in -short mode")
}
}
+
+var flaky = flag.Bool("flaky", false, "run known-flaky tests too")
+
+func SkipFlaky(t *testing.T, issue int) {
+ if !*flaky {
+ t.Skipf("skipping known flaky test without the -flaky flag; see golang.org/issue/%d", issue)
+ }
+}
diff --git a/src/internal/trace/order.go b/src/internal/trace/order.go
new file mode 100644
index 0000000000..8ca2da52aa
--- /dev/null
+++ b/src/internal/trace/order.go
@@ -0,0 +1,278 @@
+// 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
+ 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:
+ 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:
+ 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]
+}
diff --git a/src/internal/trace/parser.go b/src/internal/trace/parser.go
index e325678733..843d0eaf63 100644
--- a/src/internal/trace/parser.go
+++ b/src/internal/trace/parser.go
@@ -9,18 +9,19 @@ import (
"bytes"
"fmt"
"io"
+ "math/rand"
"os"
"os/exec"
- "sort"
"strconv"
"strings"
+ _ "unsafe"
)
// Event describes one event in the trace.
type Event struct {
Off int // offset in input file (for debugging and error reporting)
Type byte // one of Ev*
- Seq int64 // sequence number
+ seq int64 // sequence number
Ts int64 // timestamp in nanoseconds
P int // P on which the event happened (can be one of TimerP, NetpollP, SyscallP)
G uint64 // G on which the event happened
@@ -58,12 +59,12 @@ const (
)
// Parse parses, post-processes and verifies the trace.
-func Parse(r io.Reader) ([]*Event, error) {
- rawEvents, err := readTrace(r)
+func Parse(r io.Reader, bin string) ([]*Event, error) {
+ ver, rawEvents, strings, err := readTrace(r)
if err != nil {
return nil, err
}
- events, err := parseEvents(rawEvents)
+ events, stacks, err := parseEvents(ver, rawEvents, strings)
if err != nil {
return nil, err
}
@@ -71,10 +72,21 @@ func Parse(r io.Reader) ([]*Event, error) {
if err != nil {
return nil, err
}
- err = postProcessTrace(events)
+ err = postProcessTrace(ver, events)
if err != nil {
return nil, 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 nil, err
+ }
+ }
return events, nil
}
@@ -87,107 +99,187 @@ type rawEvent struct {
// readTrace does wire-format parsing and verification.
// It does not care about specific event types and argument meaning.
-func readTrace(r io.Reader) ([]rawEvent, error) {
+func readTrace(r io.Reader) (ver int, events []rawEvent, strings map[uint64]string, err error) {
// Read and validate trace header.
var buf [16]byte
- off, err := r.Read(buf[:])
- if off != 16 || err != nil {
- return nil, fmt.Errorf("failed to read header: read %v, err %v", off, err)
+ off, err := io.ReadFull(r, buf[:])
+ if err != nil {
+ err = fmt.Errorf("failed to read header: read %v, err %v", off, err)
+ return
}
- if !bytes.Equal(buf[:], []byte("go 1.5 trace\x00\x00\x00\x00")) {
- return nil, fmt.Errorf("not a trace file")
+ ver, err = parseHeader(buf[:])
+ if err != nil {
+ return
+ }
+ switch ver {
+ case 1005, 1007:
+ break
+ default:
+ err = fmt.Errorf("unsupported trace file version %v.%v (update Go toolchain) %v", ver/1000, ver%1000, ver)
+ return
}
// Read events.
- var events []rawEvent
+ strings = make(map[uint64]string)
for {
// Read event type and number of arguments (1 byte).
off0 := off
- n, err := r.Read(buf[:1])
+ var n int
+ n, err = r.Read(buf[:1])
if err == io.EOF {
+ err = nil
break
}
if err != nil || n != 1 {
- return nil, fmt.Errorf("failed to read trace at offset 0x%x: n=%v err=%v", off0, n, err)
+ err = fmt.Errorf("failed to read trace at offset 0x%x: n=%v err=%v", off0, n, err)
+ return
}
off += n
typ := buf[0] << 2 >> 2
- narg := buf[0] >> 6
+ 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 < 3 {
- for i := 0; i < int(narg)+2; i++ { // sequence number and time stamp are present but not counted in narg
+ if narg < inlineArgs {
+ for i := 0; i < int(narg); i++ {
var v uint64
v, off, err = readVal(r, off)
if err != nil {
- return nil, err
+ err = fmt.Errorf("failed to read event %v argument at offset %v (%v)", typ, off, err)
+ return
}
ev.args = append(ev.args, v)
}
} else {
- // If narg == 3, the first value is length of the event in bytes.
+ // 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 {
- return nil, err
+ err = fmt.Errorf("failed to read event %v argument at offset %v (%v)", typ, off, err)
+ return
}
evLen := v
off1 := off
for evLen > uint64(off-off1) {
v, off, err = readVal(r, off)
if err != nil {
- return nil, err
+ err = fmt.Errorf("failed to read event %v argument at offset %v (%v)", typ, off, err)
+ return
}
ev.args = append(ev.args, v)
}
if evLen != uint64(off-off1) {
- return nil, fmt.Errorf("event has wrong length at offset 0x%x: want %v, got %v", off0, evLen, off-off1)
+ err = fmt.Errorf("event has wrong length at offset 0x%x: want %v, got %v", off0, evLen, off-off1)
+ return
}
}
events = append(events, ev)
}
- return events, nil
+ return
+}
+
+// parseHeader parses trace header of the form "go 1.7 trace\x00\x00\x00\x00"
+// and returns parsed version as 1007.
+func parseHeader(buf []byte) (int, error) {
+ if len(buf) != 16 {
+ return 0, fmt.Errorf("bad header length")
+ }
+ if buf[0] != 'g' || buf[1] != 'o' || buf[2] != ' ' ||
+ buf[3] < '1' || buf[3] > '9' ||
+ buf[4] != '.' ||
+ buf[5] < '1' || buf[5] > '9' {
+ return 0, fmt.Errorf("not a trace file")
+ }
+ ver := int(buf[5] - '0')
+ i := 0
+ for ; buf[6+i] >= '0' && buf[6+i] <= '9' && i < 2; i++ {
+ ver = ver*10 + int(buf[6+i]-'0')
+ }
+ ver += int(buf[3]-'0') * 1000
+ if !bytes.Equal(buf[6+i:], []byte(" trace\x00\x00\x00\x00")[:10-i]) {
+ return 0, fmt.Errorf("not a trace file")
+ }
+ return ver, nil
}
// Parse events transforms raw events into events.
// It does analyze and verify per-event-type arguments.
-func parseEvents(rawEvents []rawEvent) (events []*Event, err error) {
+func parseEvents(ver int, rawEvents []rawEvent, strings map[uint64]string) (events []*Event, stacks map[uint64][]*Frame, err error) {
var ticksPerSec, lastSeq, lastTs int64
var lastG, timerGoid uint64
var lastP int
lastGs := make(map[int]uint64) // last goroutine running on P
- stacks := make(map[uint64][]*Frame)
+ stacks = make(map[uint64][]*Frame)
+ batches := make(map[int][]*Event) // events by P
for _, raw := range rawEvents {
- if raw.typ == EvNone || raw.typ >= EvCount {
- err = fmt.Errorf("unknown event type %v at offset 0x%x", raw.typ, raw.off)
- return
- }
desc := EventDescriptions[raw.typ]
if desc.Name == "" {
err = fmt.Errorf("missing description for event type %v", raw.typ)
return
}
- if raw.typ != EvStack {
- narg := len(desc.Args)
- if desc.Stack {
- narg++
- }
- if raw.typ != EvBatch && raw.typ != EvFrequency && raw.typ != EvTimerGoroutine {
- narg++ // sequence number
- narg++ // timestamp
- }
- if len(raw.args) != narg {
- err = fmt.Errorf("%v has wrong number of arguments at offset 0x%x: want %v, got %v",
- desc.Name, raw.off, narg, len(raw.args))
- return
- }
+ 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]
- lastSeq = int64(raw.args[1])
- lastTs = int64(raw.args[2])
+ 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 {
@@ -211,33 +303,53 @@ func parseEvents(rawEvents []rawEvent) (events []*Event, err error) {
raw.off, size)
return
}
- if uint64(len(raw.args)) != size+2 {
+ 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, size+2, len(raw.args))
+ 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++ {
- stk[i] = &Frame{PC: raw.args[i+2]}
+ if ver < 1007 {
+ stk[i] = &Frame{PC: raw.args[2+i]}
+ } else {
+ pc := raw.args[2+i*4+0]
+ fn := raw.args[2+i*4+1]
+ file := raw.args[2+i*4+2]
+ line := raw.args[2+i*4+3]
+ stk[i] = &Frame{PC: pc, Fn: strings[fn], File: strings[file], Line: int(line)}
+ }
}
stacks[id] = stk
}
default:
e := &Event{Off: raw.off, Type: raw.typ, P: lastP, G: lastG}
- e.Seq = lastSeq + int64(raw.args[0])
- e.Ts = lastTs + int64(raw.args[1])
- lastSeq = e.Seq
- lastTs = e.Ts
- for i := range desc.Args {
- e.Args[i] = raw.args[i+2]
+ 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
}
- if desc.Stack {
- e.StkID = raw.args[len(desc.Args)+2]
+ 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:
+ case EvGoStart, EvGoStartLocal:
lastG = e.Args[0]
e.G = lastG
case EvGCStart, EvGCDone, EvGCScanStart, EvGCScanDone:
@@ -247,45 +359,51 @@ func parseEvents(rawEvents []rawEvent) (events []*Event, err error) {
EvGoBlockSelect, EvGoBlockSync, EvGoBlockCond, EvGoBlockNet,
EvGoSysBlock:
lastG = 0
- case EvGoSysExit:
- // EvGoSysExit emission is delayed until the thread has a P.
- // Give it the real sequence number and time stamp.
- e.Seq = int64(e.Args[1])
- if e.Args[2] != 0 {
- e.Ts = int64(e.Args[2])
- }
+ case EvGoSysExit, EvGoWaiting, EvGoInSyscall:
+ e.G = e.Args[0]
}
- events = append(events, e)
+ batches[lastP] = append(batches[lastP], e)
}
}
- if len(events) == 0 {
+ if len(batches) == 0 {
err = fmt.Errorf("trace is empty")
return
}
-
- // Attach stack traces.
- for _, ev := range events {
- if ev.StkID != 0 {
- ev.Stk = stacks[ev.StkID]
- }
- }
-
- // Sort by sequence number and translate cpu ticks to real time.
- sort.Sort(eventList(events))
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 = (ev.Ts - minTs) * 1e9 / ticksPerSec
+ ev.Ts = int64(float64(ev.Ts-minTs) * freq)
// Move timers and syscalls to separate fake Ps.
if timerGoid != 0 && ev.G == timerGoid && ev.Type == EvGoUnblock {
ev.P = TimerP
}
if ev.Type == EvGoSysExit {
ev.P = SyscallP
- ev.G = ev.Args[0]
}
}
@@ -355,7 +473,7 @@ var ErrTimeOrder = fmt.Errorf("time stamps out of order")
// The resulting trace is guaranteed to be consistent
// (for example, a P does not run two Gs at the same time, or a G is indeed
// blocked before an unblock event).
-func postProcessTrace(events []*Event) error {
+func postProcessTrace(ver int, events []*Event) error {
const (
gDead = iota
gRunnable
@@ -446,19 +564,15 @@ func postProcessTrace(events []*Event) error {
p.evSweep.Link = ev
p.evSweep = nil
case EvGoWaiting:
- g1 := gs[ev.Args[0]]
- if g1.state != gRunnable {
- return fmt.Errorf("g %v is not runnable before EvGoWaiting (offset %v, time %v)", ev.Args[0], ev.Off, ev.Ts)
+ if g.state != gRunnable {
+ return fmt.Errorf("g %v is not runnable before EvGoWaiting (offset %v, time %v)", ev.G, ev.Off, ev.Ts)
}
- g1.state = gWaiting
- gs[ev.Args[0]] = g1
+ g.state = gWaiting
case EvGoInSyscall:
- g1 := gs[ev.Args[0]]
- if g1.state != gRunnable {
- return fmt.Errorf("g %v is not runnable before EvGoInSyscall (offset %v, time %v)", ev.Args[0], ev.Off, ev.Ts)
+ if g.state != gRunnable {
+ return fmt.Errorf("g %v is not runnable before EvGoInSyscall (offset %v, time %v)", ev.G, ev.Off, ev.Ts)
}
- g1.state = gWaiting
- gs[ev.Args[0]] = g1
+ g.state = gWaiting
case EvGoCreate:
if err := checkRunning(p, g, ev, true); err != nil {
return err
@@ -478,8 +592,12 @@ func postProcessTrace(events []*Event) error {
g.evStart = ev
p.g = ev.G
if g.evCreate != nil {
- // +1 because symbolizer expects return pc.
- ev.Stk = []*Frame{{PC: g.evCreate.Args[1] + 1}}
+ if ver < 1007 {
+ // +1 because symbolizer expects return pc.
+ ev.Stk = []*Frame{{PC: g.evCreate.Args[1] + 1}}
+ } else {
+ ev.StkID = g.evCreate.Args[1]
+ }
g.evCreate = nil
}
@@ -565,23 +683,11 @@ func postProcessTrace(events []*Event) error {
// TODO(dvyukov): restore stacks for EvGoStart events.
// TODO(dvyukov): test that all EvGoStart events has non-nil Link.
- // Last, after all the other consistency checks,
- // make sure time stamps respect sequence numbers.
- // The tests will skip (not fail) the test case if they see this error,
- // so check everything else that could possibly be wrong first.
- lastTs := int64(0)
- for _, ev := range events {
- if ev.Ts < lastTs {
- return ErrTimeOrder
- }
- lastTs = ev.Ts
- }
-
return nil
}
-// symbolizeTrace attaches func/file/line info to stack traces.
-func Symbolize(events []*Event, bin string) error {
+// 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 {
@@ -672,57 +778,81 @@ func readVal(r io.Reader, off0 int) (v uint64, off int, err error) {
return 0, 0, fmt.Errorf("bad value at offset 0x%x", off0)
}
-type eventList []*Event
-
-func (l eventList) Len() int {
- return len(l)
-}
-
-func (l eventList) Less(i, j int) bool {
- return l[i].Seq < l[j].Seq
+// Print dumps events to stdout. For debugging.
+func Print(events []*Event) {
+ for _, ev := range events {
+ PrintEvent(ev)
+ }
}
-func (l eventList) Swap(i, j int) {
- l[i], l[j] = l[j], l[i]
+// PrintEvent dumps the event to stdout. For debugging.
+func PrintEvent(ev *Event) {
+ desc := EventDescriptions[ev.Type]
+ fmt.Printf("%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.Printf(" %v=%v", a, ev.Args[i])
+ }
+ fmt.Printf("\n")
}
-// Print dumps events to stdout. For debugging.
-func Print(events []*Event) {
- for _, ev := range events {
- desc := EventDescriptions[ev.Type]
- fmt.Printf("%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.Printf(" %v=%v", a, ev.Args[i])
+// 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
+ }
+ case EvGCStart, EvGoStart, EvGoUnblock:
+ if ver < 1007 {
+ narg-- // 1.7 added an additional seq arg
+ }
+ fallthrough
+ default:
+ narg++ // timestamp
+ if ver < 1007 {
+ narg++ // sequence
}
- fmt.Printf("\n")
}
+ 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.
const (
EvNone = 0 // unused
EvBatch = 1 // start of per-P batch of events [pid, timestamp]
EvFrequency = 2 // contains tracer timer frequency [frequency (ticks per second)]
- EvStack = 3 // stack [stack id, number of PCs, array of PCs]
+ 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, stack id]
+ EvGCStart = 7 // GC start [timestamp, seq, stack id]
EvGCDone = 8 // GC done [timestamp]
EvGCScanStart = 9 // GC scan start [timestamp]
EvGCScanDone = 10 // GC scan done [timestamp]
EvGCSweepStart = 11 // GC sweep start [timestamp, stack id]
EvGCSweepDone = 12 // GC sweep done [timestamp]
- EvGoCreate = 13 // goroutine creation [timestamp, new goroutine id, start PC, stack id]
- EvGoStart = 14 // goroutine starts running [timestamp, goroutine id]
+ 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, 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]
@@ -730,57 +860,66 @@ const (
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, real timestamp]
+ 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 [goroutine id]
- EvGoInSyscall = 32 // denotes that goroutine is in syscall when tracing starts [goroutine id]
- EvHeapAlloc = 33 // memstats.heap_alloc change [timestamp, heap_alloc]
+ 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]
- EvCount = 37
+ 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]
+ EvCount = 41
)
var EventDescriptions = [EvCount]struct {
- Name string
- Stack bool
- Args []string
+ Name string
+ minVersion int
+ Stack bool
+ Args []string
}{
- EvNone: {"None", false, []string{}},
- EvBatch: {"Batch", false, []string{"p", "seq", "ticks"}},
- EvFrequency: {"Frequency", false, []string{"freq", "unused"}},
- EvStack: {"Stack", false, []string{"id", "siz"}},
- EvGomaxprocs: {"Gomaxprocs", true, []string{"procs"}},
- EvProcStart: {"ProcStart", false, []string{"thread"}},
- EvProcStop: {"ProcStop", false, []string{}},
- EvGCStart: {"GCStart", true, []string{}},
- EvGCDone: {"GCDone", false, []string{}},
- EvGCScanStart: {"GCScanStart", false, []string{}},
- EvGCScanDone: {"GCScanDone", false, []string{}},
- EvGCSweepStart: {"GCSweepStart", true, []string{}},
- EvGCSweepDone: {"GCSweepDone", false, []string{}},
- EvGoCreate: {"GoCreate", true, []string{"g", "pc"}},
- EvGoStart: {"GoStart", false, []string{"g"}},
- EvGoEnd: {"GoEnd", false, []string{}},
- EvGoStop: {"GoStop", true, []string{}},
- EvGoSched: {"GoSched", true, []string{}},
- EvGoPreempt: {"GoPreempt", true, []string{}},
- EvGoSleep: {"GoSleep", true, []string{}},
- EvGoBlock: {"GoBlock", true, []string{}},
- EvGoUnblock: {"GoUnblock", true, []string{"g"}},
- EvGoBlockSend: {"GoBlockSend", true, []string{}},
- EvGoBlockRecv: {"GoBlockRecv", true, []string{}},
- EvGoBlockSelect: {"GoBlockSelect", true, []string{}},
- EvGoBlockSync: {"GoBlockSync", true, []string{}},
- EvGoBlockCond: {"GoBlockCond", true, []string{}},
- EvGoBlockNet: {"GoBlockNet", true, []string{}},
- EvGoSysCall: {"GoSysCall", true, []string{}},
- EvGoSysExit: {"GoSysExit", false, []string{"g", "seq", "ts"}},
- EvGoSysBlock: {"GoSysBlock", false, []string{}},
- EvGoWaiting: {"GoWaiting", false, []string{"g"}},
- EvGoInSyscall: {"GoInSyscall", false, []string{"g"}},
- EvHeapAlloc: {"HeapAlloc", false, []string{"mem"}},
- EvNextGC: {"NextGC", false, []string{"mem"}},
- EvTimerGoroutine: {"TimerGoroutine", false, []string{"g", "unused"}},
- EvFutileWakeup: {"FutileWakeup", false, []string{}},
+ EvNone: {"None", 1005, false, []string{}},
+ EvBatch: {"Batch", 1005, false, []string{"p", "ticks"}}, // in 1.5 format it was {"p", "seq", "ticks"}
+ EvFrequency: {"Frequency", 1005, false, []string{"freq"}}, // in 1.5 format it was {"freq", "unused"}
+ EvStack: {"Stack", 1005, false, []string{"id", "siz"}},
+ EvGomaxprocs: {"Gomaxprocs", 1005, true, []string{"procs"}},
+ EvProcStart: {"ProcStart", 1005, false, []string{"thread"}},
+ EvProcStop: {"ProcStop", 1005, false, []string{}},
+ EvGCStart: {"GCStart", 1005, true, []string{"seq"}}, // in 1.5 format it was {}
+ EvGCDone: {"GCDone", 1005, false, []string{}},
+ EvGCScanStart: {"GCScanStart", 1005, false, []string{}},
+ EvGCScanDone: {"GCScanDone", 1005, false, []string{}},
+ EvGCSweepStart: {"GCSweepStart", 1005, true, []string{}},
+ EvGCSweepDone: {"GCSweepDone", 1005, false, []string{}},
+ EvGoCreate: {"GoCreate", 1005, true, []string{"g", "stack"}},
+ EvGoStart: {"GoStart", 1005, false, []string{"g", "seq"}}, // in 1.5 format it was {"g"}
+ EvGoEnd: {"GoEnd", 1005, false, []string{}},
+ EvGoStop: {"GoStop", 1005, true, []string{}},
+ EvGoSched: {"GoSched", 1005, true, []string{}},
+ EvGoPreempt: {"GoPreempt", 1005, true, []string{}},
+ EvGoSleep: {"GoSleep", 1005, true, []string{}},
+ EvGoBlock: {"GoBlock", 1005, true, []string{}},
+ EvGoUnblock: {"GoUnblock", 1005, true, []string{"g", "seq"}}, // in 1.5 format it was {"g"}
+ EvGoBlockSend: {"GoBlockSend", 1005, true, []string{}},
+ EvGoBlockRecv: {"GoBlockRecv", 1005, true, []string{}},
+ EvGoBlockSelect: {"GoBlockSelect", 1005, true, []string{}},
+ EvGoBlockSync: {"GoBlockSync", 1005, true, []string{}},
+ EvGoBlockCond: {"GoBlockCond", 1005, true, []string{}},
+ EvGoBlockNet: {"GoBlockNet", 1005, true, []string{}},
+ EvGoSysCall: {"GoSysCall", 1005, true, []string{}},
+ EvGoSysExit: {"GoSysExit", 1005, false, []string{"g", "seq", "ts"}},
+ EvGoSysBlock: {"GoSysBlock", 1005, false, []string{}},
+ EvGoWaiting: {"GoWaiting", 1005, false, []string{"g"}},
+ EvGoInSyscall: {"GoInSyscall", 1005, false, []string{"g"}},
+ EvHeapAlloc: {"HeapAlloc", 1005, false, []string{"mem"}},
+ EvNextGC: {"NextGC", 1005, false, []string{"mem"}},
+ EvTimerGoroutine: {"TimerGoroutine", 1005, false, []string{"g"}}, // in 1.5 format it was {"g", "unused"}
+ EvFutileWakeup: {"FutileWakeup", 1005, false, []string{}},
+ EvString: {"String", 1007, false, []string{}},
+ EvGoStartLocal: {"GoStartLocal", 1007, false, []string{"g"}},
+ EvGoUnblockLocal: {"GoUnblockLocal", 1007, true, []string{"g"}},
+ EvGoSysExitLocal: {"GoSysExitLocal", 1007, false, []string{"g", "ts"}},
}
diff --git a/src/internal/trace/parser_test.go b/src/internal/trace/parser_test.go
index fecefc4053..340f106484 100644
--- a/src/internal/trace/parser_test.go
+++ b/src/internal/trace/parser_test.go
@@ -5,6 +5,9 @@
package trace
import (
+ "bytes"
+ "io/ioutil"
+ "path/filepath"
"strings"
"testing"
)
@@ -22,9 +25,115 @@ func TestCorruptedInputs(t *testing.T) {
"go 1.5 trace\x00\x00\x00\x00\xc3\x0200",
}
for _, data := range tests {
- events, err := Parse(strings.NewReader(data))
+ events, err := Parse(strings.NewReader(data), "")
if err == nil || events != nil {
- t.Fatalf("no error on input: %q\n", data)
+ t.Fatalf("no error on input: %q", data)
}
}
}
+
+func TestParseCanned(t *testing.T) {
+ files, err := ioutil.ReadDir("./testdata")
+ if err != nil {
+ t.Fatalf("failed to read ./testdata: %v", err)
+ }
+ for _, f := range files {
+ data, err := ioutil.ReadFile(filepath.Join("./testdata", f.Name()))
+ if err != nil {
+ t.Fatalf("failed to read input file: %v", err)
+ }
+ _, err = Parse(bytes.NewReader(data), "")
+ switch {
+ case strings.HasSuffix(f.Name(), "_good"):
+ if err != nil {
+ t.Errorf("failed to parse good trace %v: %v", f.Name(), err)
+ }
+ case strings.HasSuffix(f.Name(), "_unordered"):
+ if err != ErrTimeOrder {
+ t.Errorf("unordered trace is not detected %v: %v", f.Name(), err)
+ }
+ default:
+ t.Errorf("unknown input file suffix: %v", f.Name())
+ }
+ }
+}
+
+func TestParseVersion(t *testing.T) {
+ tests := map[string]int{
+ "go 1.5 trace\x00\x00\x00\x00": 1005,
+ "go 1.7 trace\x00\x00\x00\x00": 1007,
+ "go 1.10 trace\x00\x00\x00": 1010,
+ "go 1.25 trace\x00\x00\x00": 1025,
+ "go 1.234 trace\x00\x00": 1234,
+ "go 1.2345 trace\x00": -1,
+ "go 0.0 trace\x00\x00\x00\x00": -1,
+ "go a.b trace\x00\x00\x00\x00": -1,
+ }
+ for header, ver := range tests {
+ ver1, err := parseHeader([]byte(header))
+ if ver == -1 {
+ if err == nil {
+ t.Fatalf("no error on input: %q, version %v", header, ver1)
+ }
+ } else {
+ if err != nil {
+ t.Fatalf("failed to parse: %q (%v)", header, err)
+ }
+ if ver != ver1 {
+ t.Fatalf("wrong version: %v, want %v, input: %q", ver1, ver, header)
+ }
+ }
+ }
+}
+
+func TestTimestampOverflow(t *testing.T) {
+ // Test that parser correctly handles large timestamps (long tracing).
+ w := newWriter()
+ w.emit(EvBatch, 0, 0)
+ w.emit(EvFrequency, 1e9)
+ for ts := uint64(1); ts < 1e16; ts *= 2 {
+ w.emit(EvGoCreate, ts, ts, 0, 0)
+ }
+ if _, err := Parse(w, ""); err != nil {
+ t.Fatalf("failed to parse: %v", err)
+ }
+}
+
+type writer struct {
+ bytes.Buffer
+}
+
+func newWriter() *writer {
+ w := new(writer)
+ w.Write([]byte("go 1.7 trace\x00\x00\x00\x00"))
+ return w
+}
+
+func (w *writer) emit(typ byte, args ...uint64) {
+ nargs := byte(len(args)) - 1
+ if nargs > 3 {
+ nargs = 3
+ }
+ buf := []byte{typ | nargs<<6}
+ if nargs == 3 {
+ buf = append(buf, 0)
+ }
+ for _, a := range args {
+ buf = appendVarint(buf, a)
+ }
+ if nargs == 3 {
+ buf[1] = byte(len(buf) - 2)
+ }
+ n, err := w.Write(buf)
+ if n != len(buf) || err != nil {
+ panic("failed to write")
+ }
+}
+
+func appendVarint(buf []byte, v uint64) []byte {
+ for ; v >= 0x80; v >>= 7 {
+ buf = append(buf, 0x80|byte(v))
+ }
+ buf = append(buf, byte(v))
+ return buf
+}
diff --git a/src/internal/trace/testdata/http_1_5_good b/src/internal/trace/testdata/http_1_5_good
new file mode 100644
index 0000000000..0736cae674
--- /dev/null
+++ b/src/internal/trace/testdata/http_1_5_good
Binary files differ
diff --git a/src/internal/trace/testdata/stress_1_5_good b/src/internal/trace/testdata/stress_1_5_good
new file mode 100644
index 0000000000..c5055ebd19
--- /dev/null
+++ b/src/internal/trace/testdata/stress_1_5_good
Binary files differ
diff --git a/src/internal/trace/testdata/stress_1_5_unordered b/src/internal/trace/testdata/stress_1_5_unordered
new file mode 100644
index 0000000000..11f7d745ca
--- /dev/null
+++ b/src/internal/trace/testdata/stress_1_5_unordered
Binary files differ
diff --git a/src/internal/trace/testdata/stress_start_stop_1_5_good b/src/internal/trace/testdata/stress_start_stop_1_5_good
new file mode 100644
index 0000000000..72a887b844
--- /dev/null
+++ b/src/internal/trace/testdata/stress_start_stop_1_5_good
Binary files differ
generated by cgit v1.3 (git 2.53.0) at 2026-04-16 11:55:09 +0000