From 847f15716625d24c6a6af8f741dff66781b6bcdd Mon Sep 17 00:00:00 2001 From: =?utf8?q?Felix=20Geisend=C3=B6rfer?= Date: Sat, 3 May 2025 15:56:23 +0300 Subject: [PATCH] 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 LUCI-TryBot-Result: Go LUCI Reviewed-by: Michael Knyszek Reviewed-by: David Chase --- src/internal/trace/gc_test.go | 2 +- src/internal/trace/reader_test.go | 7 ++- src/internal/trace/summary_test.go | 4 +- src/internal/trace/testtrace/format.go | 23 ++++---- src/internal/trace/testtrace/validation.go | 68 ++++++++++++++++------ src/internal/trace/trace_test.go | 3 +- src/internal/trace/tracev1_test.go | 3 +- 7 files changed, 72 insertions(+), 38 deletions(-) diff --git a/src/internal/trace/gc_test.go b/src/internal/trace/gc_test.go index 39f28cc0f6..9c6d0fcb0e 100644 --- a/src/internal/trace/gc_test.go +++ b/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) } diff --git a/src/internal/trace/reader_test.go b/src/internal/trace/reader_test.go index 37c21da667..b395183e0e 100644 --- a/src/internal/trace/reader_test.go +++ b/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 { diff --git a/src/internal/trace/summary_test.go b/src/internal/trace/summary_test.go index 396bd5f096..c5f1910262 100644 --- a/src/internal/trace/summary_test.go +++ b/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) } diff --git a/src/internal/trace/testtrace/format.go b/src/internal/trace/testtrace/format.go index 82b69340ae..5c3c64787d 100644 --- a/src/internal/trace/testtrace/format.go +++ b/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 } diff --git a/src/internal/trace/testtrace/validation.go b/src/internal/trace/testtrace/validation.go index f61f7a3ffa..da0e871287 100644 --- a/src/internal/trace/testtrace/validation.go +++ b/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 - gs map[trace.GoID]*goState - ps map[trace.ProcID]*procState - ms map[trace.ThreadID]*schedContext - ranges map[trace.ResourceID][]string - tasks map[trace.TaskID]string - nSync int - Go121 bool + lastTs trace.Time + gs map[trace.GoID]*goState + ps map[trace.ProcID]*procState + ms map[trace.ThreadID]*schedContext + ranges map[trace.ResourceID][]string + tasks map[trace.TaskID]string + lastSync trace.Sync + 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), - ps: make(map[trace.ProcID]*procState), - ms: make(map[trace.ThreadID]*schedContext), - ranges: make(map[trace.ResourceID][]string), - tasks: make(map[trace.TaskID]string), + gs: make(map[trace.GoID]*goState), + ps: make(map[trace.ProcID]*procState), + ms: make(map[trace.ThreadID]*schedContext), + ranges: make(map[trace.ResourceID][]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 { - e.Errorf("sync count is not sequential: expected %d, got %d", v.nSync+1, s.N) + if s.N != v.lastSync.N+1 { + 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 { diff --git a/src/internal/trace/trace_test.go b/src/internal/trace/trace_test.go index 4ff87c1ede..8c40e84a81 100644 --- a/src/internal/trace/trace_test.go +++ b/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 { diff --git a/src/internal/trace/tracev1_test.go b/src/internal/trace/tracev1_test.go index 008c7535c9..42a8371887 100644 --- a/src/internal/trace/tracev1_test.go +++ b/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 { -- 2.50.0