internal/trace: add a validator test for the new clock snapshots

Check that the clock snapshots, when expected to be present, are
non-zero and monotonically increasing.

This required some refactoring to make the validator aware of the
version of the trace it is validating.

Change-Id: I04c4dd10fe6975cbac12bb0ddaebcec3a5284e7b
Reviewed-on: https://go-review.googlesource.com/c/go/+/669715
Auto-Submit: Michael Knyszek <mknyszek@google.com>
LUCI-TryBot-Result: Go LUCI <golang-scoped@luci-project-accounts.iam.gserviceaccount.com>
Reviewed-by: Michael Knyszek <mknyszek@google.com>
Reviewed-by: David Chase <drchase@google.com>

src/internal/trace/gc_test.go

@@ -118,7 +118,7 @@ func TestMMUTrace(t *testing.T) {
 	}
 	t.Run("V2", func(t *testing.T) {
 		testPath := "testdata/tests/go122-gc-stress.test"
-		r, _, err := testtrace.ParseFile(testPath)
+		r, _, _, err := testtrace.ParseFile(testPath)
 		if err != nil {
 			t.Fatalf("malformed test %s: bad trace file: %v", testPath, err)
 		}

src/internal/trace/reader_test.go

@@ -37,11 +37,11 @@ func TestReaderGolden(t *testing.T) {
 			t.Fatalf("failed to relativize testdata path: %v", err)
 		}
 		t.Run(testName, func(t *testing.T) {
-			tr, exp, err := testtrace.ParseFile(testPath)
+			tr, ver, exp, err := testtrace.ParseFile(testPath)
 			if err != nil {
 				t.Fatalf("failed to parse test file at %s: %v", testPath, err)
 			}
-			testReader(t, tr, exp)
+			testReader(t, tr, ver, exp)
 		})
 	}
 }
@@ -93,7 +93,7 @@ func FuzzReader(f *testing.F) {
 	})
 }
 
-func testReader(t *testing.T, tr io.Reader, exp *testtrace.Expectation) {
+func testReader(t *testing.T, tr io.Reader, ver version.Version, exp *testtrace.Expectation) {
 	r, err := trace.NewReader(tr)
 	if err != nil {
 		if err := exp.Check(err); err != nil {
@@ -102,6 +102,7 @@ func testReader(t *testing.T, tr io.Reader, exp *testtrace.Expectation) {
 		return
 	}
 	v := testtrace.NewValidator()
+	v.GoVersion = ver
 	for {
 		ev, err := r.ReadEvent()
 		if err == io.EOF {

src/internal/trace/summary_test.go

@@ -264,7 +264,7 @@ func basicGoroutineSummaryChecks(t *testing.T, summary *trace.GoroutineSummary)
 }
 
 func summarizeTraceTest(t *testing.T, testPath string) *trace.Summary {
-	trc, _, err := testtrace.ParseFile(testPath)
+	trc, _, _, err := testtrace.ParseFile(testPath)
 	if err != nil {
 		t.Fatalf("malformed test %s: bad trace file: %v", testPath, err)
 	}
@@ -388,7 +388,7 @@ func basicGoroutineExecStatsChecks(t *testing.T, stats *trace.GoroutineExecStats
 
 func TestRelatedGoroutinesV2Trace(t *testing.T) {
 	testPath := "testdata/tests/go122-gc-stress.test"
-	trc, _, err := testtrace.ParseFile(testPath)
+	trc, _, _, err := testtrace.ParseFile(testPath)
 	if err != nil {
 		t.Fatalf("malformed test %s: bad trace file: %v", testPath, err)
 	}

src/internal/trace/testtrace/format.go

@@ -8,33 +8,34 @@ import (
 	"bytes"
 	"fmt"
 	"internal/trace/raw"
+	"internal/trace/version"
 	"internal/txtar"
 	"io"
 )
 
 // ParseFile parses a test file generated by the testgen package.
-func ParseFile(testPath string) (io.Reader, *Expectation, error) {
+func ParseFile(testPath string) (io.Reader, version.Version, *Expectation, error) {
 	ar, err := txtar.ParseFile(testPath)
 	if err != nil {
-		return nil, nil, fmt.Errorf("failed to read test file for %s: %v", testPath, err)
+		return nil, 0, nil, fmt.Errorf("failed to read test file for %s: %v", testPath, err)
 	}
 	if len(ar.Files) != 2 {
-		return nil, nil, fmt.Errorf("malformed test %s: wrong number of files", testPath)
+		return nil, 0, nil, fmt.Errorf("malformed test %s: wrong number of files", testPath)
 	}
 	if ar.Files[0].Name != "expect" {
-		return nil, nil, fmt.Errorf("malformed test %s: bad filename %s", testPath, ar.Files[0].Name)
+		return nil, 0, nil, fmt.Errorf("malformed test %s: bad filename %s", testPath, ar.Files[0].Name)
 	}
 	if ar.Files[1].Name != "trace" {
-		return nil, nil, fmt.Errorf("malformed test %s: bad filename %s", testPath, ar.Files[1].Name)
+		return nil, 0, nil, fmt.Errorf("malformed test %s: bad filename %s", testPath, ar.Files[1].Name)
 	}
 	tr, err := raw.NewTextReader(bytes.NewReader(ar.Files[1].Data))
 	if err != nil {
-		return nil, nil, fmt.Errorf("malformed test %s: bad trace file: %v", testPath, err)
+		return nil, 0, nil, fmt.Errorf("malformed test %s: bad trace file: %v", testPath, err)
 	}
 	var buf bytes.Buffer
 	tw, err := raw.NewWriter(&buf, tr.Version())
 	if err != nil {
-		return nil, nil, fmt.Errorf("failed to create trace byte writer: %v", err)
+		return nil, 0, nil, fmt.Errorf("failed to create trace byte writer: %v", err)
 	}
 	for {
 		ev, err := tr.ReadEvent()
@@ -42,15 +43,15 @@ func ParseFile(testPath string) (io.Reader, *Expectation, error) {
 			break
 		}
 		if err != nil {
-			return nil, nil, fmt.Errorf("malformed test %s: bad trace file: %v", testPath, err)
+			return nil, 0, nil, fmt.Errorf("malformed test %s: bad trace file: %v", testPath, err)
 		}
 		if err := tw.WriteEvent(ev); err != nil {
-			return nil, nil, fmt.Errorf("internal error during %s: failed to write trace bytes: %v", testPath, err)
+			return nil, 0, nil, fmt.Errorf("internal error during %s: failed to write trace bytes: %v", testPath, err)
 		}
 	}
 	exp, err := ParseExpectation(ar.Files[0].Data)
 	if err != nil {
-		return nil, nil, fmt.Errorf("internal error during %s: failed to parse expectation %q: %v", testPath, string(ar.Files[0].Data), err)
+		return nil, 0, nil, fmt.Errorf("internal error during %s: failed to parse expectation %q: %v", testPath, string(ar.Files[0].Data), err)
 	}
-	return &buf, exp, nil
+	return &buf, tr.Version(), exp, nil
 }

src/internal/trace/testtrace/validation.go

@@ -8,20 +8,21 @@ import (
 	"errors"
 	"fmt"
 	"internal/trace"
+	"internal/trace/version"
 	"slices"
 	"strings"
 )
 
 // Validator is a type used for validating a stream of trace.Events.
 type Validator struct {
-	lastTs trace.Time
+	lastTs    trace.Time
-	gs     map[trace.GoID]*goState
+	gs        map[trace.GoID]*goState
-	ps     map[trace.ProcID]*procState
+	ps        map[trace.ProcID]*procState
-	ms     map[trace.ThreadID]*schedContext
+	ms        map[trace.ThreadID]*schedContext
-	ranges map[trace.ResourceID][]string
+	ranges    map[trace.ResourceID][]string
-	tasks  map[trace.TaskID]string
+	tasks     map[trace.TaskID]string
-	nSync  int
+	lastSync  trace.Sync
-	Go121  bool
+	GoVersion version.Version
 }
 
 type schedContext struct {
@@ -43,11 +44,12 @@ type procState struct {
 // NewValidator creates a new Validator.
 func NewValidator() *Validator {
 	return &Validator{
-		gs:     make(map[trace.GoID]*goState),
+		gs:        make(map[trace.GoID]*goState),
-		ps:     make(map[trace.ProcID]*procState),
+		ps:        make(map[trace.ProcID]*procState),
-		ms:     make(map[trace.ThreadID]*schedContext),
+		ms:        make(map[trace.ThreadID]*schedContext),
-		ranges: make(map[trace.ResourceID][]string),
+		ranges:    make(map[trace.ResourceID][]string),
-		tasks:  make(map[trace.TaskID]string),
+		tasks:     make(map[trace.TaskID]string),
+		GoVersion: version.Current,
 	}
 }
 
@@ -74,10 +76,38 @@ func (v *Validator) Event(ev trace.Event) error {
 	switch ev.Kind() {
 	case trace.EventSync:
 		s := ev.Sync()
-		if s.N != v.nSync+1 {
+		if s.N != v.lastSync.N+1 {
-			e.Errorf("sync count is not sequential: expected %d, got %d", v.nSync+1, s.N)
+			e.Errorf("sync count is not sequential: expected %d, got %d", v.lastSync.N+1, s.N)
 		}
-		v.nSync = s.N
+		// The trace reader currently emits synthetic sync events at the end of
+		// a trace. Those don't contain clock snapshots data, so we don't try
+		// to validate them.
+		//
+		// TODO(felixge): Drop the synthetic syncs as discussed in CL 653576.
+		if v.GoVersion >= version.Go125 && !(s.N > 1 && s.ClockSnapshot == nil) {
+			if s.ClockSnapshot == nil {
+				e.Errorf("sync %d has no clock snapshot", s.N)
+			}
+			if s.ClockSnapshot.Wall.IsZero() {
+				e.Errorf("sync %d has zero wall time", s.N)
+			}
+			if s.ClockSnapshot.Mono == 0 {
+				e.Errorf("sync %d has zero mono time", s.N)
+			}
+			if s.ClockSnapshot.Trace == 0 {
+				e.Errorf("sync %d has zero trace time", s.N)
+			}
+			if s.N >= 2 && !s.ClockSnapshot.Wall.After(v.lastSync.ClockSnapshot.Wall) {
+				e.Errorf("sync %d has non-increasing wall time: %v vs %v", s.N, s.ClockSnapshot.Wall, v.lastSync.ClockSnapshot.Wall)
+			}
+			if s.N >= 2 && !(s.ClockSnapshot.Mono > v.lastSync.ClockSnapshot.Mono) {
+				e.Errorf("sync %d has non-increasing mono time: %v vs %v", s.N, s.ClockSnapshot.Mono, v.lastSync.ClockSnapshot.Mono)
+			}
+			if s.N >= 2 && !(s.ClockSnapshot.Trace > v.lastSync.ClockSnapshot.Trace) {
+				e.Errorf("sync %d has non-increasing trace time: %v vs %v", s.N, s.ClockSnapshot.Trace, v.lastSync.ClockSnapshot.Trace)
+			}
+		}
+		v.lastSync = s
 	case trace.EventMetric:
 		m := ev.Metric()
 		if !strings.Contains(m.Name, ":") {
@@ -143,7 +173,7 @@ func (v *Validator) Event(ev trace.Event) error {
 			if new == trace.GoUndetermined {
 				e.Errorf("transition to undetermined state for goroutine %d", id)
 			}
-			if v.nSync > 1 && old == trace.GoUndetermined {
+			if v.lastSync.N > 1 && old == trace.GoUndetermined {
 				e.Errorf("undetermined goroutine %d after first global sync", id)
 			}
 			if new == trace.GoNotExist && v.hasAnyRange(trace.MakeResourceID(id)) {
@@ -196,7 +226,7 @@ func (v *Validator) Event(ev trace.Event) error {
 			if new == trace.ProcUndetermined {
 				e.Errorf("transition to undetermined state for proc %d", id)
 			}
-			if v.nSync > 1 && old == trace.ProcUndetermined {
+			if v.lastSync.N > 1 && old == trace.ProcUndetermined {
 				e.Errorf("undetermined proc %d after first global sync", id)
 			}
 			if new == trace.ProcNotExist && v.hasAnyRange(trace.MakeResourceID(id)) {
@@ -325,7 +355,7 @@ func (v *Validator) getOrCreateThread(e *errAccumulator, ev trace.Event, m trace
 		// Be lenient about GoUndetermined -> GoSyscall transitions if they
 		// originate from an old trace. These transitions lack thread
 		// information in trace formats older than 1.22.
-		if !v.Go121 {
+		if v.GoVersion >= version.Go122 {
 			return false
 		}
 		if ev.Kind() != trace.EventStateTransition {

src/internal/trace/trace_test.go

@@ -12,6 +12,7 @@ import (
 	"internal/testenv"
 	"internal/trace"
 	"internal/trace/testtrace"
+	"internal/trace/version"
 	"io"
 	"os"
 	"path/filepath"
@@ -617,7 +618,7 @@ func testTraceProg(t *testing.T, progName string, extra func(t *testing.T, trace
 		tb := traceBuf.Bytes()
 
 		// Test the trace and the parser.
-		testReader(t, bytes.NewReader(tb), testtrace.ExpectSuccess())
+		testReader(t, bytes.NewReader(tb), version.Current, testtrace.ExpectSuccess())
 
 		// Run some extra validation.
 		if !t.Failed() && extra != nil {

src/internal/trace/tracev1_test.go

@@ -7,6 +7,7 @@ package trace_test
 import (
 	"internal/trace"
 	"internal/trace/testtrace"
+	"internal/trace/version"
 	"io"
 	"os"
 	"path/filepath"
@@ -38,7 +39,7 @@ func TestTraceV1(t *testing.T) {
 			}
 
 			v := testtrace.NewValidator()
-			v.Go121 = true
+			v.GoVersion = version.Go121
 			for {
 				ev, err := tr.ReadEvent()
 				if err != nil {