From 2cefd12a1bf7ee1d1aad03e17c4680d4b611d6da Mon Sep 17 00:00:00 2001 From: Brad Fitzpatrick Date: Wed, 6 Apr 2016 19:02:27 +0000 Subject: net, runtime: skip flaky tests on OpenBSD Flaky tests are a distraction and cover up real problems. File bugs instead and mark them as flaky. This moves the net/http flaky test flagging mechanism to internal/testenv. Updates #15156 Updates #15157 Updates #15158 Change-Id: I0e561cd2a09c0dec369cd4ed93bc5a2b40233dfe Reviewed-on: https://go-review.googlesource.com/21614 Reviewed-by: Matthew Dempsky Run-TryBot: Brad Fitzpatrick --- src/internal/testenv/testenv.go | 9 +++++++++ 1 file changed, 9 insertions(+) (limited to 'src/internal') 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) + } +} -- cgit v1.3 From 0fb7b4cccd02df10f239ed77d6d85566b6388b83 Mon Sep 17 00:00:00 2001 From: Dmitry Vyukov Date: Fri, 8 Apr 2016 15:14:37 +0200 Subject: runtime: emit file:line info into traces This makes traces self-contained and simplifies trace workflow in modern cloud environments where it is simpler to reach a service via HTTP than to obtain the binary. Change-Id: I6ff3ca694dc698270f1e29da37d5efaf4e843a0d Reviewed-on: https://go-review.googlesource.com/21732 Run-TryBot: Dmitry Vyukov TryBot-Result: Gobot Gobot Reviewed-by: Hyang-Ah Hana Kim --- src/cmd/trace/main.go | 5 - src/internal/trace/parser.go | 174 +++++++++++++--------------------- src/runtime/trace.go | 98 ++++++++++++++++--- src/runtime/trace/trace_stack_test.go | 7 +- 4 files changed, 156 insertions(+), 128 deletions(-) (limited to 'src/internal') diff --git a/src/cmd/trace/main.go b/src/cmd/trace/main.go index e493be91b7..12bf8c3c16 100644 --- a/src/cmd/trace/main.go +++ b/src/cmd/trace/main.go @@ -104,11 +104,6 @@ func parseEvents() ([]*trace.Event, error) { loader.err = fmt.Errorf("failed to parse trace: %v", err) return } - err = trace.Symbolize(events, programBinary) - if err != nil { - loader.err = fmt.Errorf("failed to symbolize trace: %v", err) - return - } loader.events = events }) return loader.events, loader.err diff --git a/src/internal/trace/parser.go b/src/internal/trace/parser.go index e325678733..5db3fc317e 100644 --- a/src/internal/trace/parser.go +++ b/src/internal/trace/parser.go @@ -5,15 +5,10 @@ package trace import ( - "bufio" "bytes" "fmt" "io" - "os" - "os/exec" "sort" - "strconv" - "strings" ) // Event describes one event in the trace. @@ -59,11 +54,11 @@ const ( // Parse parses, post-processes and verifies the trace. func Parse(r io.Reader) ([]*Event, error) { - rawEvents, err := readTrace(r) + rawEvents, strings, err := readTrace(r) if err != nil { return nil, err } - events, err := parseEvents(rawEvents) + events, stacks, err := parseEvents(rawEvents, strings) if err != nil { return nil, err } @@ -75,6 +70,12 @@ func Parse(r io.Reader) ([]*Event, error) { if err != nil { return nil, err } + // Attach stack traces. + for _, ev := range events { + if ev.StkID != 0 { + ev.Stk = stacks[ev.StkID] + } + } return events, nil } @@ -87,19 +88,20 @@ 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) ([]rawEvent, map[uint64]string, 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) + return nil, nil, fmt.Errorf("failed to read header: read %v, err %v", off, err) } if !bytes.Equal(buf[:], []byte("go 1.5 trace\x00\x00\x00\x00")) { - return nil, fmt.Errorf("not a trace file") + return nil, nil, fmt.Errorf("not a trace file") } // Read events. var events []rawEvent + strings := make(map[uint64]string) for { // Read event type and number of arguments (1 byte). off0 := off @@ -108,18 +110,51 @@ func readTrace(r io.Reader) ([]rawEvent, error) { 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) + return nil, nil, fmt.Errorf("failed to read trace at offset 0x%x: n=%v err=%v", off0, n, err) } off += n typ := buf[0] << 2 >> 2 narg := buf[0] >> 6 + if typ == EvString { + // String dictionary entry [ID, length, string]. + var id uint64 + id, off, err = readVal(r, off) + if err != nil { + return nil, nil, err + } + if id == 0 { + return nil, nil, fmt.Errorf("string at offset %d has invalid id 0", off) + } + if strings[id] != "" { + return nil, nil, fmt.Errorf("string at offset %d has duplicate id %v", off, id) + } + var ln uint64 + ln, off, err = readVal(r, off) + if err != nil { + return nil, nil, err + } + if ln == 0 { + return nil, nil, fmt.Errorf("string at offset %d has invalie length 0", off) + } + if ln > 1e6 { + return nil, nil, fmt.Errorf("string at offset %d has too large length %v", off, ln) + } + buf := make([]byte, ln) + n, err := io.ReadFull(r, buf) + if err != nil { + return nil, nil, fmt.Errorf("failed to read trace at offset %d: read %v, want %v, error %v", off, n, ln, err) + } + 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 var v uint64 v, off, err = readVal(r, off) if err != nil { - return nil, err + return nil, nil, err } ev.args = append(ev.args, v) } @@ -128,34 +163,34 @@ func readTrace(r io.Reader) ([]rawEvent, error) { var v uint64 v, off, err = readVal(r, off) if err != nil { - return nil, err + return nil, nil, err } evLen := v off1 := off for evLen > uint64(off-off1) { v, off, err = readVal(r, off) if err != nil { - return nil, err + return nil, nil, err } ev.args = append(ev.args, v) } if evLen != uint64(off-off1) { - return nil, fmt.Errorf("event has wrong length at offset 0x%x: want %v, got %v", off0, evLen, off-off1) + return nil, nil, fmt.Errorf("event has wrong length at offset 0x%x: want %v, got %v", off0, evLen, off-off1) } } events = append(events, ev) } - return events, nil + return events, strings, 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(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) 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) @@ -211,16 +246,20 @@ func parseEvents(rawEvents []rawEvent) (events []*Event, err error) { raw.off, size) return } - if uint64(len(raw.args)) != size+2 { + if want := 2 + 4*size; 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]} + 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 } @@ -263,13 +302,6 @@ func parseEvents(rawEvents []rawEvent) (events []*Event, err error) { 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 { @@ -478,8 +510,7 @@ 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}} + ev.StkID = g.evCreate.Args[1] g.evCreate = nil } @@ -580,79 +611,6 @@ func postProcessTrace(events []*Event) error { return nil } -// symbolizeTrace attaches func/file/line info to stack traces. -func Symbolize(events []*Event, bin string) error { - // First, collect and dedup all pcs. - pcs := make(map[uint64]*Frame) - for _, ev := range events { - for _, f := range ev.Stk { - pcs[f.PC] = nil - } - } - - // Start addr2line. - cmd := exec.Command("go", "tool", "addr2line", bin) - in, err := cmd.StdinPipe() - if err != nil { - return fmt.Errorf("failed to pipe addr2line stdin: %v", err) - } - cmd.Stderr = os.Stderr - out, err := cmd.StdoutPipe() - if err != nil { - return fmt.Errorf("failed to pipe addr2line stdout: %v", err) - } - err = cmd.Start() - if err != nil { - return fmt.Errorf("failed to start addr2line: %v", err) - } - outb := bufio.NewReader(out) - - // Write all pcs to addr2line. - // Need to copy pcs to an array, because map iteration order is non-deterministic. - var pcArray []uint64 - for pc := range pcs { - pcArray = append(pcArray, pc) - _, err := fmt.Fprintf(in, "0x%x\n", pc-1) - if err != nil { - return fmt.Errorf("failed to write to addr2line: %v", err) - } - } - in.Close() - - // Read in answers. - for _, pc := range pcArray { - fn, err := outb.ReadString('\n') - if err != nil { - return fmt.Errorf("failed to read from addr2line: %v", err) - } - file, err := outb.ReadString('\n') - if err != nil { - return fmt.Errorf("failed to read from addr2line: %v", err) - } - f := &Frame{PC: pc} - f.Fn = fn[:len(fn)-1] - f.File = file[:len(file)-1] - if colon := strings.LastIndex(f.File, ":"); colon != -1 { - ln, err := strconv.Atoi(f.File[colon+1:]) - if err == nil { - f.File = f.File[:colon] - f.Line = ln - } - } - pcs[pc] = f - } - cmd.Wait() - - // Replace frames in events array. - for _, ev := range events { - for i, f := range ev.Stk { - ev.Stk[i] = pcs[f.PC] - } - } - - return nil -} - // readVal reads unsigned base-128 value from r. func readVal(r io.Reader, off0 int) (v uint64, off int, err error) { off = off0 @@ -704,7 +662,7 @@ 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] @@ -714,7 +672,7 @@ const ( 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] + EvGoCreate = 13 // goroutine creation [timestamp, new goroutine id, new start id, stack id] EvGoStart = 14 // goroutine starts running [timestamp, goroutine id] EvGoEnd = 15 // goroutine ends [timestamp] EvGoStop = 16 // goroutine stops (like in select{}) [timestamp, stack] @@ -738,7 +696,8 @@ const ( 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] + EvCount = 38 ) var EventDescriptions = [EvCount]struct { @@ -759,7 +718,7 @@ var EventDescriptions = [EvCount]struct { EvGCScanDone: {"GCScanDone", false, []string{}}, EvGCSweepStart: {"GCSweepStart", true, []string{}}, EvGCSweepDone: {"GCSweepDone", false, []string{}}, - EvGoCreate: {"GoCreate", true, []string{"g", "pc"}}, + EvGoCreate: {"GoCreate", true, []string{"g", "stack"}}, EvGoStart: {"GoStart", false, []string{"g"}}, EvGoEnd: {"GoEnd", false, []string{}}, EvGoStop: {"GoStop", true, []string{}}, @@ -783,4 +742,5 @@ var EventDescriptions = [EvCount]struct { EvNextGC: {"NextGC", false, []string{"mem"}}, EvTimerGoroutine: {"TimerGoroutine", false, []string{"g", "unused"}}, EvFutileWakeup: {"FutileWakeup", false, []string{}}, + EvString: {"String", false, []string{}}, } diff --git a/src/runtime/trace.go b/src/runtime/trace.go index 805c34f483..f54e5e0a7e 100644 --- a/src/runtime/trace.go +++ b/src/runtime/trace.go @@ -23,7 +23,7 @@ const ( traceEvNone = 0 // unused traceEvBatch = 1 // start of per-P batch of events [pid, timestamp] traceEvFrequency = 2 // contains tracer timer frequency [frequency (ticks per second)] - traceEvStack = 3 // stack [stack id, number of PCs, array of PCs] + traceEvStack = 3 // stack [stack id, number of PCs, array of {PC, func string ID, file string ID, line}] traceEvGomaxprocs = 4 // current value of GOMAXPROCS [timestamp, GOMAXPROCS, stack id] traceEvProcStart = 5 // start of P [timestamp, thread id] traceEvProcStop = 6 // stop of P [timestamp] @@ -33,7 +33,7 @@ const ( traceEvGCScanDone = 10 // GC scan done [timestamp] traceEvGCSweepStart = 11 // GC sweep start [timestamp, stack id] traceEvGCSweepDone = 12 // GC sweep done [timestamp] - traceEvGoCreate = 13 // goroutine creation [timestamp, new goroutine id, start PC, stack id] + traceEvGoCreate = 13 // goroutine creation [timestamp, new goroutine id, new start id, stack id] traceEvGoStart = 14 // goroutine starts running [timestamp, goroutine id] traceEvGoEnd = 15 // goroutine ends [timestamp] traceEvGoStop = 16 // goroutine stops (like in select{}) [timestamp, stack] @@ -57,7 +57,8 @@ const ( traceEvNextGC = 34 // memstats.next_gc change [timestamp, next_gc] traceEvTimerGoroutine = 35 // denotes timer goroutine [timer goroutine id] traceEvFutileWakeup = 36 // denotes that the previous wakeup of this goroutine was futile [timestamp] - traceEvCount = 37 + traceEvString = 37 // string dictionary entry [ID, length, string] + traceEvCount = 38 ) const ( @@ -111,6 +112,12 @@ var trace struct { reader *g // goroutine that called ReadTrace, or nil stackTab traceStackTable // maps stack traces to unique ids + // Dictionary for traceEvString. + // Currently this is used only for func/file:line info after tracing session, + // so we assume single-threaded access. + strings map[string]uint64 + stringSeq uint64 + bufLock mutex // protects buf buf traceBufPtr // global trace buffer, used when running without a p } @@ -191,6 +198,8 @@ func StartTrace() error { trace.timeStart = nanotime() trace.headerWritten = false trace.footerWritten = false + trace.strings = make(map[string]uint64) + trace.stringSeq = 0 // Can't set trace.enabled yet. While the world is stopped, exitsyscall could // already emit a delayed event (see exitTicks in exitsyscall) if we set trace.enabled here. @@ -272,8 +281,6 @@ func StopTrace() { trace.enabled = false trace.shutdown = true - trace.stackTab.dump() - unlock(&trace.bufLock) startTheWorld() @@ -309,6 +316,7 @@ func StopTrace() { trace.empty = buf.ptr().link sysFree(unsafe.Pointer(buf), unsafe.Sizeof(*buf.ptr()), &memstats.other_sys) } + trace.strings = nil trace.shutdown = false unlock(&trace.lock) } @@ -380,6 +388,9 @@ func ReadTrace() []byte { data = traceAppend(data, uint64(timers.gp.goid)) data = traceAppend(data, 0) } + // This will emit a bunch of full buffers, we will pick them up + // on the next iteration. + trace.stackTab.dump() return data } // Done. @@ -603,6 +614,29 @@ func traceFlush(buf traceBufPtr) traceBufPtr { return buf } +func traceString(buf *traceBuf, s string) (uint64, *traceBuf) { + if s == "" { + return 0, buf + } + if id, ok := trace.strings[s]; ok { + return id, buf + } + + trace.stringSeq++ + id := trace.stringSeq + trace.strings[s] = id + + size := 1 + 2*traceBytesPerNumber + len(s) + if len(buf.arr)-buf.pos < size { + buf = traceFlush(traceBufPtrOf(buf)).ptr() + } + buf.byte(traceEvString) + buf.varint(id) + buf.varint(uint64(len(s))) + buf.pos += copy(buf.arr[buf.pos:], s) + return id, buf +} + // traceAppend appends v to buf in little-endian-base-128 encoding. func traceAppend(buf []byte, v uint64) []byte { for ; v >= 0x80; v >>= 7 { @@ -716,23 +750,28 @@ func (tab *traceStackTable) newStack(n int) *traceStack { // dump writes all previously cached stacks to trace buffers, // releases all memory and resets state. func (tab *traceStackTable) dump() { - var tmp [(2 + traceStackSize) * traceBytesPerNumber]byte + frames := make(map[uintptr]traceFrame) + var tmp [(2 + 4*traceStackSize) * traceBytesPerNumber]byte buf := traceFlush(0).ptr() for _, stk := range tab.tab { stk := stk.ptr() for ; stk != nil; stk = stk.link.ptr() { - maxSize := 1 + (3+stk.n)*traceBytesPerNumber - if len(buf.arr)-buf.pos < maxSize { - buf = traceFlush(traceBufPtrOf(buf)).ptr() - } - // Form the event in the temp buffer, we need to know the actual length. tmpbuf := tmp[:0] tmpbuf = traceAppend(tmpbuf, uint64(stk.id)) tmpbuf = traceAppend(tmpbuf, uint64(stk.n)) for _, pc := range stk.stack() { + var frame traceFrame + frame, buf = traceFrameForPC(buf, frames, pc) tmpbuf = traceAppend(tmpbuf, uint64(pc)) + tmpbuf = traceAppend(tmpbuf, uint64(frame.funcID)) + tmpbuf = traceAppend(tmpbuf, uint64(frame.fileID)) + tmpbuf = traceAppend(tmpbuf, uint64(frame.line)) } // Now copy to the buffer. + size := 1 + traceBytesPerNumber + len(tmpbuf) + if len(buf.arr)-buf.pos < size { + buf = traceFlush(traceBufPtrOf(buf)).ptr() + } buf.byte(traceEvStack | 3< maxLen { + fn = fn[len(fn)-maxLen:] + } + frame.funcID, buf = traceString(buf, fn) + file, line := funcline(f, pc-sys.PCQuantum) + frame.line = uint64(line) + if len(file) > maxLen { + file = file[len(file)-maxLen:] + } + frame.fileID, buf = traceString(buf, file) + return frame, buf +} + // traceAlloc is a non-thread-safe region allocator. // It holds a linked list of traceAllocBlock. type traceAlloc struct { @@ -844,7 +916,9 @@ func traceGCSweepDone() { } func traceGoCreate(newg *g, pc uintptr) { - traceEvent(traceEvGoCreate, 2, uint64(newg.goid), uint64(pc)) + // +PCQuantum because traceFrameForPC expects return PCs and subtracts PCQuantum. + id := trace.stackTab.put([]uintptr{pc + sys.PCQuantum}) + traceEvent(traceEvGoCreate, 2, uint64(newg.goid), uint64(id)) } func traceGoStart() { diff --git a/src/runtime/trace/trace_stack_test.go b/src/runtime/trace/trace_stack_test.go index b99ec687d5..c3fb0f6fee 100644 --- a/src/runtime/trace/trace_stack_test.go +++ b/src/runtime/trace/trace_stack_test.go @@ -129,10 +129,6 @@ func TestTraceSymbolize(t *testing.T) { if err != nil { t.Fatalf("failed to parse trace: %v", err) } - err = trace.Symbolize(events, os.Args[0]) - if err != nil { - t.Fatalf("failed to symbolize trace: %v", err) - } // Now check that the stacks are correct. type frame struct { @@ -149,6 +145,9 @@ func TestTraceSymbolize(t *testing.T) { {"runtime/trace_test.TestTraceSymbolize", 106}, {"testing.tRunner", 0}, }}, + {trace.EvGoStart, []frame{ + {"runtime/trace_test.TestTraceSymbolize.func1", 37}, + }}, {trace.EvGoSched, []frame{ {"runtime/trace_test.TestTraceSymbolize", 107}, {"testing.tRunner", 0}, -- cgit v1.3 From 527ffebb2c9fe432a0ef0aa0c2449d83cd8a23cb Mon Sep 17 00:00:00 2001 From: Dmitry Vyukov Date: Sun, 10 Apr 2016 12:49:40 +0200 Subject: internal/trace: fix a typo in error message Change-Id: Id79eaa6d49dae80c334c7243b0a5bbcdcb9397d3 Reviewed-on: https://go-review.googlesource.com/21758 Reviewed-by: Mikio Hara --- src/internal/trace/parser.go | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) (limited to 'src/internal') diff --git a/src/internal/trace/parser.go b/src/internal/trace/parser.go index 5db3fc317e..65530b15c3 100644 --- a/src/internal/trace/parser.go +++ b/src/internal/trace/parser.go @@ -134,7 +134,7 @@ func readTrace(r io.Reader) ([]rawEvent, map[uint64]string, error) { return nil, nil, err } if ln == 0 { - return nil, nil, fmt.Errorf("string at offset %d has invalie length 0", off) + return nil, nil, fmt.Errorf("string at offset %d has invalid length 0", off) } if ln > 1e6 { return nil, nil, fmt.Errorf("string at offset %d has too large length %v", off, ln) -- cgit v1.3 From 3fafe2e8888dadb6877fa1e7569f5bd1f688dd3a Mon Sep 17 00:00:00 2001 From: Dmitry Vyukov Date: Mon, 11 Apr 2016 08:57:52 +0200 Subject: internal/trace: support parsing of 1.5 traces 1. Parse out version from trace header. 2. Restore handling of 1.5 traces. 3. Restore optional symbolization of traces. 4. Add some canned 1.5 traces for regression testing (http benchmark trace, runtime/trace stress traces, plus one with broken timestamps). Change-Id: Idb18a001d03ded8e13c2730eeeb37c5836e31256 Reviewed-on: https://go-review.googlesource.com/21803 Run-TryBot: Dmitry Vyukov TryBot-Result: Gobot Gobot Reviewed-by: Austin Clements --- misc/nacl/testzip.proto | 4 + src/cmd/trace/main.go | 2 +- src/internal/trace/parser.go | 314 +++++++++++++++------ src/internal/trace/parser_test.go | 61 +++- src/internal/trace/testdata/http_1_5_good | Bin 0 -> 42218 bytes src/internal/trace/testdata/stress_1_5_good | Bin 0 -> 7446 bytes src/internal/trace/testdata/stress_1_5_unordered | Bin 0 -> 8194 bytes .../trace/testdata/stress_start_stop_1_5_good | Bin 0 -> 6997 bytes src/runtime/trace.go | 2 +- src/runtime/trace/trace_test.go | 4 +- 10 files changed, 295 insertions(+), 92 deletions(-) create mode 100644 src/internal/trace/testdata/http_1_5_good create mode 100644 src/internal/trace/testdata/stress_1_5_good create mode 100644 src/internal/trace/testdata/stress_1_5_unordered create mode 100644 src/internal/trace/testdata/stress_start_stop_1_5_good (limited to 'src/internal') diff --git a/misc/nacl/testzip.proto b/misc/nacl/testzip.proto index 42db92f327..8c14b87f0a 100644 --- a/misc/nacl/testzip.proto +++ b/misc/nacl/testzip.proto @@ -109,6 +109,10 @@ go src=.. png testdata + + internal + trace + testdata + + io + mime diff --git a/src/cmd/trace/main.go b/src/cmd/trace/main.go index 12bf8c3c16..cfd222e132 100644 --- a/src/cmd/trace/main.go +++ b/src/cmd/trace/main.go @@ -99,7 +99,7 @@ func parseEvents() ([]*trace.Event, error) { defer tracef.Close() // Parse and symbolize. - events, err := trace.Parse(bufio.NewReader(tracef)) + events, err := trace.Parse(bufio.NewReader(tracef), programBinary) if err != nil { loader.err = fmt.Errorf("failed to parse trace: %v", err) return diff --git a/src/internal/trace/parser.go b/src/internal/trace/parser.go index 65530b15c3..82ddb8b6c8 100644 --- a/src/internal/trace/parser.go +++ b/src/internal/trace/parser.go @@ -5,17 +5,22 @@ package trace import ( + "bufio" "bytes" "fmt" "io" + "os" + "os/exec" "sort" + "strconv" + "strings" ) // Event describes one event in the trace. type Event struct { Off int // offset in input file (for debugging and error reporting) Type byte // one of Ev* - 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 @@ -53,12 +58,12 @@ const ( ) // Parse parses, post-processes and verifies the trace. -func Parse(r io.Reader) ([]*Event, error) { - rawEvents, strings, 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, stacks, err := parseEvents(rawEvents, strings) + events, stacks, err := parseEvents(ver, rawEvents, strings) if err != nil { return nil, err } @@ -66,7 +71,7 @@ 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 } @@ -76,6 +81,11 @@ func Parse(r io.Reader) ([]*Event, error) { ev.Stk = stacks[ev.StkID] } } + if ver < 1007 && bin != "" { + if err := symbolize(events, bin); err != nil { + return nil, err + } + } return events, nil } @@ -88,61 +98,82 @@ 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, map[uint64]string, 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, 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, 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) + 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, 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 + 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 nil, nil, err + return } if id == 0 { - return nil, nil, fmt.Errorf("string at offset %d has invalid id 0", off) + err = fmt.Errorf("string at offset %d has invalid id 0", off) + return } if strings[id] != "" { - return nil, nil, fmt.Errorf("string at offset %d has duplicate id %v", off, 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 nil, nil, err + return } if ln == 0 { - return nil, nil, fmt.Errorf("string at offset %d has invalid length 0", off) + err = fmt.Errorf("string at offset %d has invalid length 0", off) + return } if ln > 1e6 { - return nil, nil, fmt.Errorf("string at offset %d has too large length %v", off, ln) + err = fmt.Errorf("string at offset %d has too large length %v", off, ln) + return } buf := make([]byte, ln) - n, err := io.ReadFull(r, buf) + var n int + n, err = io.ReadFull(r, buf) if err != nil { - return nil, nil, fmt.Errorf("failed to read trace at offset %d: read %v, want %v, error %v", off, n, ln, err) + 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) @@ -154,7 +185,8 @@ func readTrace(r io.Reader) ([]rawEvent, map[uint64]string, error) { var v uint64 v, off, err = readVal(r, off) if err != nil { - return nil, 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) } @@ -163,39 +195,62 @@ func readTrace(r io.Reader) ([]rawEvent, map[uint64]string, error) { var v uint64 v, off, err = readVal(r, off) if err != nil { - return nil, 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, 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, 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, strings, 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, strings map[uint64]string) (events []*Event, stacks map[uint64][]*Frame, 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) 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) @@ -246,7 +301,11 @@ func parseEvents(rawEvents []rawEvent, strings map[uint64]string) (events []*Eve raw.off, size) return } - if want := 2 + 4*size; uint64(len(raw.args)) != want { + 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 @@ -255,19 +314,23 @@ func parseEvents(rawEvents []rawEvent, strings map[uint64]string) (events []*Eve if id != 0 && size > 0 { stk := make([]*Frame, size) for i := 0; i < int(size); i++ { - 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)} + 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.seq = lastSeq + int64(raw.args[0]) e.Ts = lastTs + int64(raw.args[1]) - lastSeq = e.Seq + lastSeq = e.seq lastTs = e.Ts for i := range desc.Args { e.Args[i] = raw.args[i+2] @@ -289,7 +352,7 @@ func parseEvents(rawEvents []rawEvent, strings map[uint64]string) (events []*Eve 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]) + e.seq = int64(e.Args[1]) if e.Args[2] != 0 { e.Ts = int64(e.Args[2]) } @@ -387,7 +450,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 @@ -510,7 +573,12 @@ func postProcessTrace(events []*Event) error { g.evStart = ev p.g = ev.G if g.evCreate != nil { - ev.StkID = g.evCreate.Args[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 } @@ -611,6 +679,79 @@ func postProcessTrace(events []*Event) error { 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("go", "tool", "addr2line", bin) + in, err := cmd.StdinPipe() + if err != nil { + return fmt.Errorf("failed to pipe addr2line stdin: %v", err) + } + cmd.Stderr = os.Stderr + out, err := cmd.StdoutPipe() + if err != nil { + return fmt.Errorf("failed to pipe addr2line stdout: %v", err) + } + err = cmd.Start() + if err != nil { + return fmt.Errorf("failed to start addr2line: %v", err) + } + outb := bufio.NewReader(out) + + // Write all pcs to addr2line. + // Need to copy pcs to an array, because map iteration order is non-deterministic. + var pcArray []uint64 + for pc := range pcs { + pcArray = append(pcArray, pc) + _, err := fmt.Fprintf(in, "0x%x\n", pc-1) + if err != nil { + return fmt.Errorf("failed to write to addr2line: %v", err) + } + } + in.Close() + + // Read in answers. + for _, pc := range pcArray { + fn, err := outb.ReadString('\n') + if err != nil { + return fmt.Errorf("failed to read from addr2line: %v", err) + } + file, err := outb.ReadString('\n') + if err != nil { + return fmt.Errorf("failed to read from addr2line: %v", err) + } + f := &Frame{PC: pc} + f.Fn = fn[:len(fn)-1] + f.File = file[:len(file)-1] + if colon := strings.LastIndex(f.File, ":"); colon != -1 { + ln, err := strconv.Atoi(f.File[colon+1:]) + if err == nil { + f.File = f.File[:colon] + f.Line = ln + } + } + pcs[pc] = f + } + cmd.Wait() + + // Replace frames in events array. + for _, ev := range events { + for i, f := range ev.Stk { + ev.Stk[i] = pcs[f.PC] + } + } + + return nil +} + // readVal reads unsigned base-128 value from r. func readVal(r io.Reader, off0 int) (v uint64, off int, err error) { off = off0 @@ -637,7 +778,7 @@ func (l eventList) Len() int { } func (l eventList) Less(i, j int) bool { - return l[i].Seq < l[j].Seq + return l[i].seq < l[j].seq } func (l eventList) Swap(i, j int) { @@ -701,46 +842,47 @@ const ( ) 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", "stack"}}, - 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{}}, - EvString: {"String", false, []string{}}, + EvNone: {"None", 1005, false, []string{}}, + EvBatch: {"Batch", 1005, false, []string{"p", "seq", "ticks"}}, + EvFrequency: {"Frequency", 1005, false, []string{"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{}}, + 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"}}, + 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"}}, + 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", "unused"}}, + EvFutileWakeup: {"FutileWakeup", 1005, false, []string{}}, + EvString: {"String", 1007, false, []string{}}, } diff --git a/src/internal/trace/parser_test.go b/src/internal/trace/parser_test.go index fecefc4053..db8d2a30ce 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,63 @@ 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) + } } } } 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 Binary files /dev/null and b/src/internal/trace/testdata/http_1_5_good 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 Binary files /dev/null and b/src/internal/trace/testdata/stress_1_5_good 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 Binary files /dev/null and b/src/internal/trace/testdata/stress_1_5_unordered 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 Binary files /dev/null and b/src/internal/trace/testdata/stress_start_stop_1_5_good differ diff --git a/src/runtime/trace.go b/src/runtime/trace.go index f54e5e0a7e..dcf534549a 100644 --- a/src/runtime/trace.go +++ b/src/runtime/trace.go @@ -356,7 +356,7 @@ func ReadTrace() []byte { trace.headerWritten = true trace.lockOwner = nil unlock(&trace.lock) - return []byte("go 1.5 trace\x00\x00\x00\x00") + return []byte("go 1.7 trace\x00\x00\x00\x00") } // Wait for new data. if trace.fullHead == 0 && !trace.shutdown { diff --git a/src/runtime/trace/trace_test.go b/src/runtime/trace/trace_test.go index b787a2fc27..d10e928a66 100644 --- a/src/runtime/trace/trace_test.go +++ b/src/runtime/trace/trace_test.go @@ -52,7 +52,7 @@ func TestTrace(t *testing.T) { t.Fatalf("failed to start tracing: %v", err) } Stop() - _, err := trace.Parse(buf) + _, err := trace.Parse(buf, "") if err == trace.ErrTimeOrder { t.Skipf("skipping trace: %v", err) } @@ -62,7 +62,7 @@ func TestTrace(t *testing.T) { } func parseTrace(t *testing.T, r io.Reader) ([]*trace.Event, map[uint64]*trace.GDesc, error) { - events, err := trace.Parse(r) + events, err := trace.Parse(r, "") if err == trace.ErrTimeOrder { t.Skipf("skipping trace: %v", err) } -- cgit v1.3 From 944a0859b9a16a1951512b82870a31f371d1c417 Mon Sep 17 00:00:00 2001 From: Dmitry Vyukov Date: Fri, 8 Apr 2016 11:53:23 +0200 Subject: internal/trace: fix int overflow in timestamps Fixes #15102 Change-Id: I7fdb6464afd0b7af9b6652051416f0fddd34dc9a Reviewed-on: https://go-review.googlesource.com/21730 Reviewed-by: Austin Clements --- src/internal/trace/parser.go | 4 ++- src/internal/trace/parser_test.go | 52 +++++++++++++++++++++++++++++++++++++++ 2 files changed, 55 insertions(+), 1 deletion(-) (limited to 'src/internal') diff --git a/src/internal/trace/parser.go b/src/internal/trace/parser.go index 82ddb8b6c8..3099b0ffeb 100644 --- a/src/internal/trace/parser.go +++ b/src/internal/trace/parser.go @@ -372,8 +372,10 @@ func parseEvents(ver int, rawEvents []rawEvent, strings map[uint64]string) (even return } 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 diff --git a/src/internal/trace/parser_test.go b/src/internal/trace/parser_test.go index db8d2a30ce..337d5a85d7 100644 --- a/src/internal/trace/parser_test.go +++ b/src/internal/trace/parser_test.go @@ -85,3 +85,55 @@ func TestParseVersion(t *testing.T) { } } } + +func TestTimestampOverflow(t *testing.T) { + // Test that parser correctly handles large timestamps (long tracing). + w := newWriter() + w.emit(EvBatch, 0, 0, 0) + w.emit(EvFrequency, 1e9, 0) + for ts := uint64(1); ts < 1e16; ts *= 2 { + w.emit(EvGoCreate, 1, ts, ts, 1, 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)) - 2 + 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 +} -- cgit v1.3 From 2d342fba78d9cbddb4c8c71bfc0d1044b2e5c58a Mon Sep 17 00:00:00 2001 From: Dmitry Vyukov Date: Fri, 22 Apr 2016 22:48:11 +0200 Subject: runtime: fix description of trace events Change-Id: I037101b1921fe151695d32e9874b50dd64982298 Reviewed-on: https://go-review.googlesource.com/22314 Reviewed-by: Austin Clements --- src/internal/trace/parser.go | 8 ++++---- src/runtime/trace.go | 6 +++--- 2 files changed, 7 insertions(+), 7 deletions(-) (limited to 'src/internal') diff --git a/src/internal/trace/parser.go b/src/internal/trace/parser.go index 3099b0ffeb..d279ddeacf 100644 --- a/src/internal/trace/parser.go +++ b/src/internal/trace/parser.go @@ -815,7 +815,7 @@ const ( 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, new start id, stack id] + EvGoCreate = 13 // goroutine creation [timestamp, new goroutine id, new stack id, stack id] EvGoStart = 14 // goroutine starts running [timestamp, goroutine id] EvGoEnd = 15 // goroutine ends [timestamp] EvGoStop = 16 // goroutine stops (like in select{}) [timestamp, stack] @@ -833,9 +833,9 @@ const ( EvGoSysCall = 28 // syscall enter [timestamp, stack] EvGoSysExit = 29 // syscall exit [timestamp, goroutine id, 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] diff --git a/src/runtime/trace.go b/src/runtime/trace.go index dcf534549a..06fbdfac94 100644 --- a/src/runtime/trace.go +++ b/src/runtime/trace.go @@ -33,7 +33,7 @@ const ( traceEvGCScanDone = 10 // GC scan done [timestamp] traceEvGCSweepStart = 11 // GC sweep start [timestamp, stack id] traceEvGCSweepDone = 12 // GC sweep done [timestamp] - traceEvGoCreate = 13 // goroutine creation [timestamp, new goroutine id, new start id, stack id] + traceEvGoCreate = 13 // goroutine creation [timestamp, new goroutine id, new stack id, stack id] traceEvGoStart = 14 // goroutine starts running [timestamp, goroutine id] traceEvGoEnd = 15 // goroutine ends [timestamp] traceEvGoStop = 16 // goroutine stops (like in select{}) [timestamp, stack] @@ -51,8 +51,8 @@ const ( traceEvGoSysCall = 28 // syscall enter [timestamp, stack] traceEvGoSysExit = 29 // syscall exit [timestamp, goroutine id, real timestamp] traceEvGoSysBlock = 30 // syscall blocks [timestamp] - traceEvGoWaiting = 31 // denotes that goroutine is blocked when tracing starts [goroutine id] - traceEvGoInSyscall = 32 // denotes that goroutine is in syscall when tracing starts [goroutine id] + traceEvGoWaiting = 31 // denotes that goroutine is blocked when tracing starts [timestamp, goroutine id] + traceEvGoInSyscall = 32 // denotes that goroutine is in syscall when tracing starts [timestamp, goroutine id] traceEvHeapAlloc = 33 // memstats.heap_live change [timestamp, heap_alloc] traceEvNextGC = 34 // memstats.next_gc change [timestamp, next_gc] traceEvTimerGoroutine = 35 // denotes timer goroutine [timer goroutine id] -- cgit v1.3 From a3703618eadeb74b60f2cb9a23fabe178d4b141d Mon Sep 17 00:00:00 2001 From: Dmitry Vyukov Date: Tue, 5 Apr 2016 15:29:14 +0200 Subject: runtime: use per-goroutine sequence numbers in tracer Currently tracer uses global sequencer and it introduces significant slowdown on parallel machines (up to 10x). Replace the global sequencer with per-goroutine sequencer. If we assign per-goroutine sequence numbers to only 3 types of events (start, unblock and syscall exit), it is enough to restore consistent partial ordering of all events. Even these events don't need sequence numbers all the time (if goroutine starts on the same P where it was unblocked, then start does not need sequence number). The burden of restoring the order is put on trace parser. Details of the algorithm are described in the comments. On http benchmark with GOMAXPROCS=48: no tracing: 5026 ns/op tracing: 27803 ns/op (+453%) with this change: 6369 ns/op (+26%, mostly for traceback) Also trace size is reduced by ~22%. Average event size before: 4.63 bytes/event, after: 3.62 bytes/event. Besides running trace tests, I've also tested with manually broken cputicks (random skew for each event, per-P skew and episodic random skew). In all cases broken timestamps were detected and no test failures. Change-Id: I078bde421ccc386a66f6c2051ab207bcd5613efa Reviewed-on: https://go-review.googlesource.com/21512 Run-TryBot: Dmitry Vyukov Reviewed-by: Austin Clements TryBot-Result: Gobot Gobot --- src/internal/trace/order.go | 278 ++++++++++++++++++++++++++++++++++++++ src/internal/trace/parser.go | 208 +++++++++++++++------------- src/internal/trace/parser_test.go | 8 +- src/runtime/proc.go | 25 +--- src/runtime/runtime2.go | 21 +-- src/runtime/trace.go | 121 +++++++++-------- 6 files changed, 478 insertions(+), 183 deletions(-) create mode 100644 src/internal/trace/order.go (limited to 'src/internal') diff --git a/src/internal/trace/order.go b/src/internal/trace/order.go new file mode 100644 index 0000000000..f9ec44c745 --- /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.Sort(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 d279ddeacf..e6f29445c1 100644 --- a/src/internal/trace/parser.go +++ b/src/internal/trace/parser.go @@ -11,7 +11,6 @@ import ( "io" "os" "os/exec" - "sort" "strconv" "strings" ) @@ -135,7 +134,12 @@ func readTrace(r io.Reader) (ver int, events []rawEvent, strings map[uint64]stri } 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 @@ -180,8 +184,8 @@ func readTrace(r io.Reader) (ver int, events []rawEvent, strings map[uint64]stri 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 { @@ -191,7 +195,7 @@ func readTrace(r io.Reader) (ver int, events []rawEvent, strings map[uint64]stri 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 { @@ -250,34 +254,30 @@ func parseEvents(ver int, rawEvents []rawEvent, strings map[uint64]string) (even var lastP int 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 } - 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 { @@ -328,18 +328,26 @@ func parseEvents(ver int, rawEvents []rawEvent, strings map[uint64]string) (even } 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: @@ -349,28 +357,30 @@ func parseEvents(ver int, rawEvents []rawEvent, strings map[uint64]string) (even 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 } - - // 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 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) @@ -382,7 +392,6 @@ func parseEvents(ver int, rawEvents []rawEvent, strings map[uint64]string) (even } if ev.Type == EvGoSysExit { ev.P = SyscallP - ev.G = ev.Args[0] } } @@ -543,19 +552,15 @@ func postProcessTrace(ver int, 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 @@ -666,18 +671,6 @@ func postProcessTrace(ver int, 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 } @@ -773,30 +766,51 @@ 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 } // Event types in the trace. @@ -809,21 +823,21 @@ const ( 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, new stack id, stack id] - EvGoStart = 14 // goroutine starts running [timestamp, goroutine 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] @@ -831,7 +845,7 @@ 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 [timestamp, goroutine id] EvGoInSyscall = 32 // denotes that goroutine is in syscall when tracing starts [timestamp, goroutine id] @@ -840,7 +854,10 @@ const ( 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] - EvCount = 38 + 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 { @@ -850,27 +867,27 @@ var EventDescriptions = [EvCount]struct { Args []string }{ EvNone: {"None", 1005, false, []string{}}, - EvBatch: {"Batch", 1005, false, []string{"p", "seq", "ticks"}}, - EvFrequency: {"Frequency", 1005, false, []string{"freq", "unused"}}, + 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{}}, + 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"}}, + 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"}}, + 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{}}, @@ -884,7 +901,10 @@ var EventDescriptions = [EvCount]struct { EvGoInSyscall: {"GoInSyscall", 1005, false, []string{"g"}}, EvHeapAlloc: {"HeapAlloc", 1005, false, []string{"mem"}}, EvNextGC: {"NextGC", 1005, false, []string{"mem"}}, - EvTimerGoroutine: {"TimerGoroutine", 1005, false, []string{"g", "unused"}}, + 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 337d5a85d7..340f106484 100644 --- a/src/internal/trace/parser_test.go +++ b/src/internal/trace/parser_test.go @@ -89,10 +89,10 @@ func TestParseVersion(t *testing.T) { func TestTimestampOverflow(t *testing.T) { // Test that parser correctly handles large timestamps (long tracing). w := newWriter() - w.emit(EvBatch, 0, 0, 0) - w.emit(EvFrequency, 1e9, 0) + w.emit(EvBatch, 0, 0) + w.emit(EvFrequency, 1e9) for ts := uint64(1); ts < 1e16; ts *= 2 { - w.emit(EvGoCreate, 1, ts, ts, 1, 0) + w.emit(EvGoCreate, ts, ts, 0, 0) } if _, err := Parse(w, ""); err != nil { t.Fatalf("failed to parse: %v", err) @@ -110,7 +110,7 @@ func newWriter() *writer { } func (w *writer) emit(typ byte, args ...uint64) { - nargs := byte(len(args)) - 2 + nargs := byte(len(args)) - 1 if nargs > 3 { nargs = 3 } diff --git a/src/runtime/proc.go b/src/runtime/proc.go index 98a986cd63..a847823da4 100644 --- a/src/runtime/proc.go +++ b/src/runtime/proc.go @@ -1796,23 +1796,7 @@ func execute(gp *g, inheritTime bool) { // GoSysExit has to happen when we have a P, but before GoStart. // So we emit it here. if gp.syscallsp != 0 && gp.sysblocktraced { - // Since gp.sysblocktraced is true, we must emit an event. - // There is a race between the code that initializes sysexitseq - // and sysexitticks (in exitsyscall, which runs without a P, - // and therefore is not stopped with the rest of the world) - // and the code that initializes a new trace. - // The recorded sysexitseq and sysexitticks must therefore - // be treated as "best effort". If they are valid for this trace, - // then great, use them for greater accuracy. - // But if they're not valid for this trace, assume that the - // trace was started after the actual syscall exit (but before - // we actually managed to start the goroutine, aka right now), - // and assign a fresh time stamp to keep the log consistent. - seq, ts := gp.sysexitseq, gp.sysexitticks - if seq == 0 || int64(seq)-int64(trace.seqStart) < 0 { - seq, ts = tracestamp() - } - traceGoSysExit(seq, ts) + traceGoSysExit(gp.sysexitticks) } traceGoStart() } @@ -2481,7 +2465,6 @@ func exitsyscall(dummy int32) { } _g_.sysexitticks = 0 - _g_.sysexitseq = 0 if trace.enabled { // Wait till traceGoSysBlock event is emitted. // This ensures consistency of the trace (the goroutine is started after it is blocked). @@ -2492,7 +2475,7 @@ func exitsyscall(dummy int32) { // Tracing code can invoke write barriers that cannot run without a P. // So instead we remember the syscall exit time and emit the event // in execute when we have a P. - _g_.sysexitseq, _g_.sysexitticks = tracestamp() + _g_.sysexitticks = cputicks() } _g_.m.locks-- @@ -2540,7 +2523,7 @@ func exitsyscallfast() bool { // Denote blocking of the new syscall. traceGoSysBlock(_g_.m.p.ptr()) // Denote completion of the current syscall. - traceGoSysExit(tracestamp()) + traceGoSysExit(0) }) } _g_.m.p.ptr().syscalltick++ @@ -2564,7 +2547,7 @@ func exitsyscallfast() bool { osyield() } } - traceGoSysExit(tracestamp()) + traceGoSysExit(0) } }) if ok { diff --git a/src/runtime/runtime2.go b/src/runtime/runtime2.go index 0fdea400de..8cfe6b06e6 100644 --- a/src/runtime/runtime2.go +++ b/src/runtime/runtime2.go @@ -332,16 +332,17 @@ type g struct { waitsince int64 // approx time when the g become blocked waitreason string // if status==Gwaiting schedlink guintptr - preempt bool // preemption signal, duplicates stackguard0 = stackpreempt - paniconfault bool // panic (instead of crash) on unexpected fault address - preemptscan bool // preempted g does scan for gc - gcscandone bool // g has scanned stack; protected by _Gscan bit in status - gcscanvalid bool // false at start of gc cycle, true if G has not run since last scan - throwsplit bool // must not split stack - raceignore int8 // ignore race detection events - sysblocktraced bool // StartTrace has emitted EvGoInSyscall about this goroutine - sysexitticks int64 // cputicks when syscall has returned (for tracing) - sysexitseq uint64 // trace seq when syscall has returned (for tracing) + preempt bool // preemption signal, duplicates stackguard0 = stackpreempt + paniconfault bool // panic (instead of crash) on unexpected fault address + preemptscan bool // preempted g does scan for gc + gcscandone bool // g has scanned stack; protected by _Gscan bit in status + gcscanvalid bool // false at start of gc cycle, true if G has not run since last scan + throwsplit bool // must not split stack + raceignore int8 // ignore race detection events + sysblocktraced bool // StartTrace has emitted EvGoInSyscall about this goroutine + sysexitticks int64 // cputicks when syscall has returned (for tracing) + traceseq uint64 // trace event sequencer + tracelastp puintptr // last P emitted an event for this goroutine lockedm *m sig uint32 writebuf []byte diff --git a/src/runtime/trace.go b/src/runtime/trace.go index 06fbdfac94..092f941f0c 100644 --- a/src/runtime/trace.go +++ b/src/runtime/trace.go @@ -13,7 +13,6 @@ package runtime import ( - "runtime/internal/atomic" "runtime/internal/sys" "unsafe" ) @@ -27,21 +26,21 @@ const ( traceEvGomaxprocs = 4 // current value of GOMAXPROCS [timestamp, GOMAXPROCS, stack id] traceEvProcStart = 5 // start of P [timestamp, thread id] traceEvProcStop = 6 // stop of P [timestamp] - traceEvGCStart = 7 // GC start [timestamp, stack id] + traceEvGCStart = 7 // GC start [timestamp, seq, stack id] traceEvGCDone = 8 // GC done [timestamp] traceEvGCScanStart = 9 // GC scan start [timestamp] traceEvGCScanDone = 10 // GC scan done [timestamp] traceEvGCSweepStart = 11 // GC sweep start [timestamp, stack id] traceEvGCSweepDone = 12 // GC sweep done [timestamp] traceEvGoCreate = 13 // goroutine creation [timestamp, new goroutine id, new stack id, stack id] - traceEvGoStart = 14 // goroutine starts running [timestamp, goroutine id] + traceEvGoStart = 14 // goroutine starts running [timestamp, goroutine id, seq] traceEvGoEnd = 15 // goroutine ends [timestamp] traceEvGoStop = 16 // goroutine stops (like in select{}) [timestamp, stack] traceEvGoSched = 17 // goroutine calls Gosched [timestamp, stack] traceEvGoPreempt = 18 // goroutine is preempted [timestamp, stack] traceEvGoSleep = 19 // goroutine calls Sleep [timestamp, stack] traceEvGoBlock = 20 // goroutine blocks [timestamp, stack] - traceEvGoUnblock = 21 // goroutine is unblocked [timestamp, goroutine id, stack] + traceEvGoUnblock = 21 // goroutine is unblocked [timestamp, goroutine id, seq, stack] traceEvGoBlockSend = 22 // goroutine blocks on chan send [timestamp, stack] traceEvGoBlockRecv = 23 // goroutine blocks on chan recv [timestamp, stack] traceEvGoBlockSelect = 24 // goroutine blocks on select [timestamp, stack] @@ -49,7 +48,7 @@ const ( traceEvGoBlockCond = 26 // goroutine blocks on Cond [timestamp, stack] traceEvGoBlockNet = 27 // goroutine blocks on network [timestamp, stack] traceEvGoSysCall = 28 // syscall enter [timestamp, stack] - traceEvGoSysExit = 29 // syscall exit [timestamp, goroutine id, real timestamp] + traceEvGoSysExit = 29 // syscall exit [timestamp, goroutine id, seq, real timestamp] traceEvGoSysBlock = 30 // syscall blocks [timestamp] traceEvGoWaiting = 31 // denotes that goroutine is blocked when tracing starts [timestamp, goroutine id] traceEvGoInSyscall = 32 // denotes that goroutine is in syscall when tracing starts [timestamp, goroutine id] @@ -58,7 +57,10 @@ const ( traceEvTimerGoroutine = 35 // denotes timer goroutine [timer goroutine id] traceEvFutileWakeup = 36 // denotes that the previous wakeup of this goroutine was futile [timestamp] traceEvString = 37 // string dictionary entry [ID, length, string] - traceEvCount = 38 + traceEvGoStartLocal = 38 // goroutine starts running on the same P as the last event [timestamp, goroutine id] + traceEvGoUnblockLocal = 39 // goroutine is unblocked on the same P as the last event [timestamp, goroutine id, stack] + traceEvGoSysExitLocal = 40 // syscall exit on the same P as the last event [timestamp, goroutine id, real timestamp] + traceEvCount = 41 ) const ( @@ -105,6 +107,7 @@ var trace struct { ticksEnd int64 // cputicks when tracing was stopped timeStart int64 // nanotime when tracing was started timeEnd int64 // nanotime when tracing was stopped + seqGC uint64 // GC start/done sequencer reading traceBufPtr // buffer currently handed off to user empty traceBufPtr // stack of empty buffers fullHead traceBufPtr // queue of full buffers @@ -122,31 +125,9 @@ var trace struct { buf traceBufPtr // global trace buffer, used when running without a p } -var traceseq uint64 // global trace sequence number - -// tracestamp returns a consistent sequence number, time stamp pair -// for use in a trace. We need to make sure that time stamp ordering -// (assuming synchronized CPUs) and sequence ordering match. -// To do that, we increment traceseq, grab ticks, and increment traceseq again. -// We treat odd traceseq as a sign that another thread is in the middle -// of the sequence and spin until it is done. -// Not splitting stack to avoid preemption, just in case the call sites -// that used to call xadd64 and cputicks are sensitive to that. -//go:nosplit -func tracestamp() (seq uint64, ts int64) { - seq = atomic.Load64(&traceseq) - for seq&1 != 0 || !atomic.Cas64(&traceseq, seq, seq+1) { - seq = atomic.Load64(&traceseq) - } - ts = cputicks() - atomic.Store64(&traceseq, seq+2) - return seq >> 1, ts -} - // traceBufHeader is per-P tracing buffer. type traceBufHeader struct { link traceBufPtr // in trace.empty/full - lastSeq uint64 // sequence number of last event lastTicks uint64 // when we wrote the last event pos int // next write offset in arr stk [traceStackSize]uintptr // scratch buffer for traceback @@ -194,13 +175,6 @@ func StartTrace() error { return errorString("tracing is already enabled") } - trace.seqStart, trace.ticksStart = tracestamp() - trace.timeStart = nanotime() - trace.headerWritten = false - trace.footerWritten = false - trace.strings = make(map[string]uint64) - trace.stringSeq = 0 - // Can't set trace.enabled yet. While the world is stopped, exitsyscall could // already emit a delayed event (see exitTicks in exitsyscall) if we set trace.enabled here. // That would lead to an inconsistent trace: @@ -213,12 +187,15 @@ func StartTrace() error { for _, gp := range allgs { status := readgstatus(gp) if status != _Gdead { - traceGoCreate(gp, gp.startpc) + traceGoCreate(gp, gp.startpc) // also resets gp.traceseq/tracelastp } if status == _Gwaiting { + // traceEvGoWaiting is implied to have seq=1. + gp.traceseq++ traceEvent(traceEvGoWaiting, -1, uint64(gp.goid)) } if status == _Gsyscall { + gp.traceseq++ traceEvent(traceEvGoInSyscall, -1, uint64(gp.goid)) } else { gp.sysblocktraced = false @@ -226,6 +203,17 @@ func StartTrace() error { } traceProcStart() traceGoStart() + // Note: ticksStart needs to be set after we emit traceEvGoInSyscall events. + // If we do it the other way around, it is possible that exitsyscall will + // query sysexitticks after ticksStart but before traceEvGoInSyscall timestamp. + // It will lead to a false conclusion that cputicks is broken. + trace.ticksStart = cputicks() + trace.timeStart = nanotime() + trace.headerWritten = false + trace.footerWritten = false + trace.strings = make(map[string]uint64) + trace.stringSeq = 0 + trace.seqGC = 0 _g_.m.startingtrace = false trace.enabled = true @@ -382,11 +370,9 @@ func ReadTrace() []byte { var data []byte data = append(data, traceEvFrequency|0<= 0 { @@ -525,7 +506,6 @@ func traceEvent(ev byte, skip int, args ...uint64) { buf.varint(0) lenp = &buf.arr[buf.pos-1] } - buf.varint(seqDiff) buf.varint(tickDiff) for _, a := range args { buf.varint(a) @@ -892,7 +872,8 @@ func traceProcStop(pp *p) { } func traceGCStart() { - traceEvent(traceEvGCStart, 3) + traceEvent(traceEvGCStart, 3, trace.seqGC) + trace.seqGC++ } func traceGCDone() { @@ -916,13 +897,23 @@ func traceGCSweepDone() { } func traceGoCreate(newg *g, pc uintptr) { + newg.traceseq = 0 + newg.tracelastp = getg().m.p // +PCQuantum because traceFrameForPC expects return PCs and subtracts PCQuantum. id := trace.stackTab.put([]uintptr{pc + sys.PCQuantum}) traceEvent(traceEvGoCreate, 2, uint64(newg.goid), uint64(id)) } func traceGoStart() { - traceEvent(traceEvGoStart, -1, uint64(getg().m.curg.goid)) + _g_ := getg().m.curg + _p_ := _g_.m.p + _g_.traceseq++ + if _g_.tracelastp == _p_ { + traceEvent(traceEvGoStartLocal, -1, uint64(_g_.goid)) + } else { + _g_.tracelastp = _p_ + traceEvent(traceEvGoStart, -1, uint64(_g_.goid), _g_.traceseq) + } } func traceGoEnd() { @@ -930,10 +921,14 @@ func traceGoEnd() { } func traceGoSched() { + _g_ := getg() + _g_.tracelastp = _g_.m.p traceEvent(traceEvGoSched, 1) } func traceGoPreempt() { + _g_ := getg() + _g_.tracelastp = _g_.m.p traceEvent(traceEvGoPreempt, 1) } @@ -945,19 +940,37 @@ func traceGoPark(traceEv byte, skip int, gp *g) { } func traceGoUnpark(gp *g, skip int) { - traceEvent(traceEvGoUnblock, skip, uint64(gp.goid)) + _p_ := getg().m.p + gp.traceseq++ + if gp.tracelastp == _p_ { + traceEvent(traceEvGoUnblockLocal, skip, uint64(gp.goid)) + } else { + gp.tracelastp = _p_ + traceEvent(traceEvGoUnblock, skip, uint64(gp.goid), gp.traceseq) + } } func traceGoSysCall() { traceEvent(traceEvGoSysCall, 1) } -func traceGoSysExit(seq uint64, ts int64) { - if int64(seq)-int64(trace.seqStart) < 0 { - // The timestamp was obtained during a previous tracing session, ignore. - return - } - traceEvent(traceEvGoSysExit, -1, uint64(getg().m.curg.goid), seq, uint64(ts)/traceTickDiv) +func traceGoSysExit(ts int64) { + if ts != 0 && ts < trace.ticksStart { + // There is a race between the code that initializes sysexitticks + // (in exitsyscall, which runs without a P, and therefore is not + // stopped with the rest of the world) and the code that initializes + // a new trace. The recorded sysexitticks must therefore be treated + // as "best effort". If they are valid for this trace, then great, + // use them for greater accuracy. But if they're not valid for this + // trace, assume that the trace was started after the actual syscall + // exit (but before we actually managed to start the goroutine, + // aka right now), and assign a fresh time stamp to keep the log consistent. + ts = 0 + } + _g_ := getg().m.curg + _g_.traceseq++ + _g_.tracelastp = _g_.m.p + traceEvent(traceEvGoSysExit, -1, uint64(_g_.goid), _g_.traceseq, uint64(ts)/traceTickDiv) } func traceGoSysBlock(pp *p) { -- cgit v1.3 From 75b844f0d228bda5dea2aabae096909f81355bac Mon Sep 17 00:00:00 2001 From: Dmitry Vyukov Date: Thu, 7 Apr 2016 15:48:15 +0200 Subject: runtime/trace: test detection of broken timestamps On some processors cputicks (used to generate trace timestamps) produce non-monotonic timestamps. It is important that the parser distinguishes logically inconsistent traces (e.g. missing, excessive or misordered events) from broken timestamps. The former is a bug in tracer, the latter is a machine issue. Test that (1) parser does not return a logical error in case of broken timestamps and (2) broken timestamps are eventually detected and reported. Change-Id: Ib4b1eb43ce128b268e754400ed8b5e8def04bd78 Reviewed-on: https://go-review.googlesource.com/21608 Reviewed-by: Austin Clements --- src/internal/trace/parser.go | 15 +++++++++++ src/runtime/trace/trace_stack_test.go | 5 +--- src/runtime/trace/trace_test.go | 48 +++++++++++++++++++++++++---------- 3 files changed, 50 insertions(+), 18 deletions(-) (limited to 'src/internal') diff --git a/src/internal/trace/parser.go b/src/internal/trace/parser.go index e6f29445c1..843d0eaf63 100644 --- a/src/internal/trace/parser.go +++ b/src/internal/trace/parser.go @@ -9,10 +9,12 @@ import ( "bytes" "fmt" "io" + "math/rand" "os" "os/exec" "strconv" "strings" + _ "unsafe" ) // Event describes one event in the trace. @@ -371,6 +373,16 @@ func parseEvents(ver int, rawEvents []rawEvent, strings map[uint64]string) (even 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 { @@ -813,6 +825,9 @@ func argNum(raw rawEvent, ver int) int { 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 ( diff --git a/src/runtime/trace/trace_stack_test.go b/src/runtime/trace/trace_stack_test.go index c3fb0f6fee..52a71bfb94 100644 --- a/src/runtime/trace/trace_stack_test.go +++ b/src/runtime/trace/trace_stack_test.go @@ -125,10 +125,7 @@ func TestTraceSymbolize(t *testing.T) { <-pipeReadDone Stop() - events, _, err := parseTrace(t, buf) - if err != nil { - t.Fatalf("failed to parse trace: %v", err) - } + events, _ := parseTrace(t, buf) // Now check that the stacks are correct. type frame struct { diff --git a/src/runtime/trace/trace_test.go b/src/runtime/trace/trace_test.go index d10e928a66..5fad3fb7f0 100644 --- a/src/runtime/trace/trace_test.go +++ b/src/runtime/trace/trace_test.go @@ -61,13 +61,13 @@ func TestTrace(t *testing.T) { } } -func parseTrace(t *testing.T, r io.Reader) ([]*trace.Event, map[uint64]*trace.GDesc, error) { +func parseTrace(t *testing.T, r io.Reader) ([]*trace.Event, map[uint64]*trace.GDesc) { events, err := trace.Parse(r, "") if err == trace.ErrTimeOrder { t.Skipf("skipping trace: %v", err) } if err != nil { - return nil, nil, err + t.Fatalf("failed to parse trace: %v", err) } gs := trace.GoroutineStats(events) for goid := range gs { @@ -75,7 +75,31 @@ func parseTrace(t *testing.T, r io.Reader) ([]*trace.Event, map[uint64]*trace.GD // But still check that RelatedGoroutines does not crash, hang, etc. _ = trace.RelatedGoroutines(events, goid) } - return events, gs, nil + return events, gs +} + +func testBrokenTimestamps(t *testing.T, data []byte) { + // On some processors cputicks (used to generate trace timestamps) + // produce non-monotonic timestamps. It is important that the parser + // distinguishes logically inconsistent traces (e.g. missing, excessive + // or misordered events) from broken timestamps. The former is a bug + // in tracer, the latter is a machine issue. + // So now that we have a consistent trace, test that (1) parser does + // not return a logical error in case of broken timestamps + // and (2) broken timestamps are eventually detected and reported. + trace.BreakTimestampsForTesting = true + defer func() { + trace.BreakTimestampsForTesting = false + }() + for i := 0; i < 1e4; i++ { + _, err := trace.Parse(bytes.NewReader(data), "") + if err == trace.ErrTimeOrder { + return + } + if err != nil { + t.Fatalf("failed to parse trace: %v", err) + } + } } func TestTraceStress(t *testing.T) { @@ -209,10 +233,9 @@ func TestTraceStress(t *testing.T) { runtime.GOMAXPROCS(procs) Stop() - _, _, err = parseTrace(t, buf) - if err != nil { - t.Fatalf("failed to parse trace: %v", err) - } + trace := buf.Bytes() + parseTrace(t, buf) + testBrokenTimestamps(t, trace) } // Do a bunch of various stuff (timers, GC, network, etc) in a separate goroutine. @@ -353,9 +376,9 @@ func TestTraceStressStartStop(t *testing.T) { } time.Sleep(time.Millisecond) Stop() - if _, _, err := parseTrace(t, buf); err != nil { - t.Fatalf("failed to parse trace: %v", err) - } + trace := buf.Bytes() + parseTrace(t, buf) + testBrokenTimestamps(t, trace) } <-outerDone } @@ -413,10 +436,7 @@ func TestTraceFutileWakeup(t *testing.T) { done.Wait() Stop() - events, _, err := parseTrace(t, buf) - if err != nil { - t.Fatalf("failed to parse trace: %v", err) - } + events, _ := parseTrace(t, buf) // Check that (1) trace does not contain EvFutileWakeup events and // (2) there are no consecutive EvGoBlock/EvGCStart/EvGoBlock events // (we call runtime.Gosched between all operations, so these would be futile wakeups). -- cgit v1.3 From c4c182140adedf300800778127840e3b8b9f7423 Mon Sep 17 00:00:00 2001 From: Dmitry Vyukov Date: Sat, 23 Apr 2016 21:18:34 +0200 Subject: internal/trace: fix event ordering for coarse timestamps Arm arch uses coarse-grained kernel timer as cputicks. As the result sort.Sort smashes trace entirely. Use sort.Stable instead. Change-Id: Idfa017a86a489be58cf239f7fe56d7f4b66b52a9 Reviewed-on: https://go-review.googlesource.com/22317 Run-TryBot: Dmitry Vyukov TryBot-Result: Gobot Gobot Reviewed-by: Austin Clements --- src/internal/trace/order.go | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) (limited to 'src/internal') diff --git a/src/internal/trace/order.go b/src/internal/trace/order.go index f9ec44c745..8ca2da52aa 100644 --- a/src/internal/trace/order.go +++ b/src/internal/trace/order.go @@ -133,7 +133,7 @@ func order1007(m map[int][]*Event) (events []*Event, err error) { ev.Ts = ts } } - sort.Sort(eventList(events)) + sort.Stable(eventList(events)) return } -- cgit v1.3