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 <austin@google.com>

diff --git a/src/internal/trace/parser.go b/src/internal/trace/parser.go
index e6f29445c15e6611c19635ec5aa5a6278f218118..843d0eaf63dcd69306469061f24507ce08193c76 100644 (file)
--- 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 c3fb0f6fee788de2e278fb4c3494e6c26d14175e..52a71bfb94c68c0af548add5c10160ee1a2fcb56 100644 (file)
--- 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 d10e928a66fa4678b49152ff7729b0b05b070ea4..5fad3fb7f048336b8b3ccf551f8e254c18b2ecb9 100644 (file)
--- 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).