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>

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 (

src/runtime/trace/trace_stack_test.go

@@ -125,10 +125,7 @@ func TestTraceSymbolize(t *testing.T) {
 	<-pipeReadDone
 
 	Stop()
-	events, _, err := parseTrace(t, buf)
+	events, _ := parseTrace(t, buf)
-	if err != nil {
-		t.Fatalf("failed to parse trace: %v", err)
-	}
 
 	// Now check that the stacks are correct.
 	type frame struct {

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)
+	trace := buf.Bytes()
-	if err != nil {
+	parseTrace(t, buf)
-		t.Fatalf("failed to parse trace: %v", err)
+	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 {
+		trace := buf.Bytes()
-			t.Fatalf("failed to parse trace: %v", err)
+		parseTrace(t, buf)
-		}
+		testBrokenTimestamps(t, trace)
 	}
 	<-outerDone
 }
@@ -413,10 +436,7 @@ func TestTraceFutileWakeup(t *testing.T) {
 	done.Wait()
 
 	Stop()
-	events, _, err := parseTrace(t, buf)
+	events, _ := parseTrace(t, buf)
-	if err != nil {
-		t.Fatalf("failed to parse trace: %v", err)
-	}
 	// 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).