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 --- src/runtime/trace/trace_test.go | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) (limited to 'src/runtime/trace/trace_test.go') 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-5-g9baa 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/runtime/trace/trace_test.go') 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-5-g9baa