internal/trace: add generator tests for sync events

Add generator tests that verify the timestamps for the sync events
emitted in the go1.25 trace format and earlier versions.

Add the ability to configure the properties of the per-generation sync
batches in testgen. Also refactor testgen to produce more realistic
timestamps by keeping track of lastTs and using it for structural
batches that don't have their own timestamps. Otherwise they default to
zero which means the minTs of the generation can't be controlled.

For #69869

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

Author: felixge

src/internal/trace/internal/testgen/trace.go

@@ -11,6 +11,7 @@ import (
 	"os"
 	"regexp"
 	"strings"
+	"time"
 
 	"internal/trace"
 	"internal/trace/raw"
@@ -55,6 +56,7 @@ type Trace struct {
 	events          []raw.Event
 	gens            []*Generation
 	validTimestamps bool
+	lastTs          Time
 
 	// Expectation state.
 	bad      bool
@@ -107,6 +109,7 @@ func (t *Trace) Generation(gen uint64) *Generation {
 		gen:     gen,
 		strings: make(map[string]uint64),
 		stacks:  make(map[stack]uint64),
+		sync:    sync{freq: 15625000},
 	}
 	t.gens = append(t.gens, g)
 	return g
@@ -178,6 +181,7 @@ type Generation struct {
 	batches []*Batch
 	strings map[string]uint64
 	stacks  map[stack]uint64
+	sync    sync
 
 	// Options applied when Trace.Generate is called.
 	ignoreStringBatchSizeLimit bool
@@ -188,14 +192,11 @@ type Generation struct {
 //
 // This is convenience function for generating correct batches.
 func (g *Generation) Batch(thread trace.ThreadID, time Time) *Batch {
-	if !g.trace.validTimestamps {
-		time = 0
-	}
 	b := &Batch{
-		gen:       g,
-		thread:    thread,
-		timestamp: time,
+		gen:    g,
+		thread: thread,
 	}
+	b.setTimestamp(time)
 	g.batches = append(g.batches, b)
 	return b
 }
@@ -238,20 +239,59 @@ func (g *Generation) Stack(stk []trace.StackFrame) uint64 {
 	return id
 }
 
+// Sync configures the sync batch for the generation. For go1.25 and later,
+// the time value is the timestamp of the EvClockSnapshot event. For earlier
+// version, the time value is the timestamp of the batch containing a lone
+// EvFrequency event.
+func (g *Generation) Sync(freq uint64, time Time, mono uint64, wall time.Time) {
+	if g.trace.ver < version.Go125 && (mono != 0 || !wall.IsZero()) {
+		panic(fmt.Sprintf("mono and wall args are not supported in go1.%d traces", g.trace.ver))
+	}
+	g.sync = sync{
+		freq:     freq,
+		time:     time,
+		mono:     mono,
+		walltime: wall,
+	}
+}
+
+type sync struct {
+	freq     uint64
+	time     Time
+	mono     uint64
+	walltime time.Time
+}
+
 // writeEventsTo emits event batches in the generation to tw.
 func (g *Generation) writeEventsTo(tw *raw.TextWriter) {
+	// go1.25+ sync batches are emitted at the start of the generation.
+	if g.trace.ver >= version.Go125 {
+		b := g.newStructuralBatch()
+		// Arrange for EvClockSnapshot's ts to be exactly g.sync.time.
+		b.setTimestamp(g.sync.time - 1)
+		b.RawEvent(tracev2.EvSync, nil)
+		b.RawEvent(tracev2.EvFrequency, nil, g.sync.freq)
+		sec := uint64(g.sync.walltime.Unix())
+		nsec := uint64(g.sync.walltime.Nanosecond())
+		b.Event("ClockSnapshot", g.sync.mono, sec, nsec)
+		b.writeEventsTo(tw)
+	}
+
 	// Write event batches for the generation.
 	for _, b := range g.batches {
 		b.writeEventsTo(tw)
 	}
 
-	// Write frequency.
-	b := g.newStructuralBatch()
-	b.RawEvent(tracev2.EvFrequency, nil, 15625000)
-	b.writeEventsTo(tw)
+	// Write lone EvFrequency sync batch for older traces.
+	if g.trace.ver < version.Go125 {
+		b := g.newStructuralBatch()
+		b.setTimestamp(g.sync.time)
+		b.RawEvent(tracev2.EvFrequency, nil, g.sync.freq)
+		b.writeEventsTo(tw)
+	}
 
 	// Write stacks.
-	b = g.newStructuralBatch()
+	b := g.newStructuralBatch()
 	b.RawEvent(tracev2.EvStacks, nil)
 	for stk, id := range g.stacks {
 		stk := stk.stk[:stk.len]
@@ -285,7 +325,9 @@ func (g *Generation) writeEventsTo(tw *raw.TextWriter) {
 }
 
 func (g *Generation) newStructuralBatch() *Batch {
-	return &Batch{gen: g, thread: trace.NoThread}
+	b := &Batch{gen: g, thread: trace.NoThread}
+	b.setTimestamp(g.trace.lastTs + 1)
+	return b
 }
 
 // Batch represents an event batch.
@@ -310,6 +352,7 @@ func (b *Batch) Event(name string, args ...any) {
 	if b.gen.trace.specs[ev].IsTimedEvent {
 		if b.gen.trace.validTimestamps {
 			uintArgs = []uint64{1}
+			b.gen.trace.lastTs += 1
 		} else {
 			uintArgs = []uint64{0}
 		}
@@ -333,7 +376,7 @@ func (b *Batch) uintArgFor(arg any, argSpec string) uint64 {
 	}
 	var u uint64
 	switch typStr {
-	case "value":
+	case "value", "mono", "sec", "nsec":
 		u = arg.(uint64)
 	case "stack":
 		u = b.gen.Stack(arg.([]trace.StackFrame))
@@ -392,6 +435,14 @@ func (b *Batch) writeEventsTo(tw *raw.TextWriter) {
 	}
 }
 
+// setTimestamp sets the timestamp for the batch.
+func (b *Batch) setTimestamp(t Time) {
+	if b.gen.trace.validTimestamps {
+		b.timestamp = t
+		b.gen.trace.lastTs = t
+	}
+}
+
 // Seq represents a sequence counter.
 type Seq uint64
 

src/internal/trace/reader_test.go

@@ -13,6 +13,7 @@ import (
 	"path/filepath"
 	"strings"
 	"testing"
+	"time"
 
 	"internal/trace"
 	"internal/trace/raw"
@@ -171,3 +172,76 @@ func dumpTraceToFile(t *testing.T, testName string, stress bool, b []byte) strin
 	}
 	return f.Name()
 }
+
+func TestTraceGenSync(t *testing.T) {
+	type sync struct {
+		Time          trace.Time
+		ClockSnapshot *trace.ClockSnapshot
+	}
+	runTest := func(testName string, wantSyncs []sync) {
+		t.Run(testName, func(t *testing.T) {
+			testPath := "testdata/tests/" + testName
+			r, _, _, err := testtrace.ParseFile(testPath)
+			if err != nil {
+				t.Fatalf("malformed test %s: bad trace file: %v", testPath, err)
+			}
+			tr, err := trace.NewReader(r)
+			if err != nil {
+				t.Fatalf("malformed test %s: bad trace file: %v", testPath, err)
+			}
+			var syncEvents []trace.Event
+			for {
+				ev, err := tr.ReadEvent()
+				if err == io.EOF {
+					break
+				}
+				if err != nil {
+					t.Fatalf("malformed test %s: bad trace file: %v", testPath, err)
+				}
+				if ev.Kind() == trace.EventSync {
+					syncEvents = append(syncEvents, ev)
+				}
+			}
+
+			if got, want := len(syncEvents), len(wantSyncs); got != want {
+				t.Errorf("got %d sync events, want %d", got, want)
+			}
+
+			for i, want := range wantSyncs {
+				got := syncEvents[i]
+				gotSync := syncEvents[i].Sync()
+				if got.Time() != want.Time {
+					t.Errorf("sync=%d got time %d, want %d", i+1, got.Time(), want.Time)
+				}
+				if gotSync.ClockSnapshot == nil && want.ClockSnapshot == nil {
+					continue
+				}
+				if gotSync.ClockSnapshot.Trace != want.ClockSnapshot.Trace {
+					t.Errorf("sync=%d got trace time %d, want %d", i+1, gotSync.ClockSnapshot.Trace, want.ClockSnapshot.Trace)
+				}
+				if !gotSync.ClockSnapshot.Wall.Equal(want.ClockSnapshot.Wall) {
+					t.Errorf("sync=%d got wall time %s, want %s", i+1, gotSync.ClockSnapshot.Wall, want.ClockSnapshot.Wall)
+				}
+				if gotSync.ClockSnapshot.Mono != want.ClockSnapshot.Mono {
+					t.Errorf("sync=%d got mono time %d, want %d", i+1, gotSync.ClockSnapshot.Mono, want.ClockSnapshot.Mono)
+				}
+			}
+		})
+	}
+
+	runTest("go123-sync.test", []sync{
+		{10, nil},
+		{40, nil},
+		// The EvFrequency batch for generation 3 is emitted at trace.Time(80),
+		// but 60 is the minTs of the generation, see b30 in the go generator.
+		{60, nil},
+		{63, nil},
+	})
+
+	runTest("go125-sync.test", []sync{
+		{9, &trace.ClockSnapshot{Trace: 10, Mono: 99, Wall: time.Date(2025, 2, 28, 15, 4, 9, 123, time.UTC)}},
+		{38, &trace.ClockSnapshot{Trace: 40, Mono: 199, Wall: time.Date(2025, 2, 28, 15, 4, 10, 123, time.UTC)}},
+		{58, &trace.ClockSnapshot{Trace: 60, Mono: 299, Wall: time.Date(2025, 2, 28, 15, 4, 11, 123, time.UTC)}},
+		{83, nil},
+	})
+}

src/internal/trace/testdata/generators/go123-sync.go

@@ -0,0 +1,30 @@
+// Copyright 2025 The Go Authors. All rights reserved.
+// Use of this source code is governed by a BSD-style
+// license that can be found in the LICENSE file.
+
+package main
+
+import (
+	"internal/trace"
+	"internal/trace/internal/testgen"
+	"internal/trace/tracev2"
+	"internal/trace/version"
+	"time"
+)
+
+func main() {
+	testgen.Main(version.Go123, gen)
+}
+
+func gen(t *testgen.Trace) {
+	g1 := t.Generation(1)
+	g1.Sync(1000000000, 10, 0, time.Time{})
+	b10 := g1.Batch(1, 15)
+	b10.Event("ProcStatus", trace.ProcID(0), tracev2.ProcRunning)
+	g2 := t.Generation(2)
+	g2.Sync(500000000, 20, 0, time.Time{})
+	g3 := t.Generation(3)
+	b30 := g3.Batch(1, 30)
+	b30.Event("ProcStatus", trace.ProcID(0), tracev2.ProcRunning)
+	g3.Sync(500000000, 40, 0, time.Time{})
+}

src/internal/trace/testdata/generators/go125-sync.go

@@ -0,0 +1,31 @@
+// Copyright 2025 The Go Authors. All rights reserved.
+// Use of this source code is governed by a BSD-style
+// license that can be found in the LICENSE file.
+
+package main
+
+import (
+	"internal/trace"
+	"internal/trace/internal/testgen"
+	"internal/trace/tracev2"
+	"internal/trace/version"
+	"time"
+)
+
+func main() {
+	testgen.Main(version.Go125, gen)
+}
+
+func gen(t *testgen.Trace) {
+	start := time.Date(2025, 2, 28, 15, 4, 9, 123, time.UTC)
+	g1 := t.Generation(1)
+	g1.Sync(1000000000, 10, 99, start)
+	b10 := g1.Batch(1, 15)
+	b10.Event("ProcStatus", trace.ProcID(0), tracev2.ProcRunning)
+	g2 := t.Generation(2)
+	g2.Sync(500000000, 20, 199, start.Add(1*time.Second))
+	g3 := t.Generation(3)
+	g3.Sync(500000000, 30, 299, start.Add(2*time.Second))
+	b30 := g3.Batch(1, 40)
+	b30.Event("ProcStatus", trace.ProcID(0), tracev2.ProcRunning)
+}

src/internal/trace/testdata/tests/go123-sync.test

@@ -0,0 +1,26 @@
+-- expect --
+SUCCESS
+-- trace --
+Trace Go1.23
+EventBatch gen=1 m=1 time=15 size=4
+ProcStatus dt=1 p=0 pstatus=1
+EventBatch gen=1 m=18446744073709551615 time=10 size=6
+Frequency freq=1000000000
+EventBatch gen=1 m=18446744073709551615 time=11 size=1
+Stacks
+EventBatch gen=1 m=18446744073709551615 time=12 size=1
+Strings
+EventBatch gen=2 m=18446744073709551615 time=20 size=6
+Frequency freq=500000000
+EventBatch gen=2 m=18446744073709551615 time=21 size=1
+Stacks
+EventBatch gen=2 m=18446744073709551615 time=22 size=1
+Strings
+EventBatch gen=3 m=1 time=30 size=4
+ProcStatus dt=1 p=0 pstatus=1
+EventBatch gen=3 m=18446744073709551615 time=40 size=6
+Frequency freq=500000000
+EventBatch gen=3 m=18446744073709551615 time=41 size=1
+Stacks
+EventBatch gen=3 m=18446744073709551615 time=42 size=1
+Strings

src/internal/trace/testdata/tests/go125-sync.test

@@ -0,0 +1,32 @@
+-- expect --
+SUCCESS
+-- trace --
+Trace Go1.25
+EventBatch gen=1 m=18446744073709551615 time=9 size=16
+Sync
+Frequency freq=1000000000
+ClockSnapshot dt=1 mono=99 sec=1740755049 nsec=123
+EventBatch gen=1 m=1 time=15 size=4
+ProcStatus dt=1 p=0 pstatus=1
+EventBatch gen=1 m=18446744073709551615 time=11 size=1
+Stacks
+EventBatch gen=1 m=18446744073709551615 time=12 size=1
+Strings
+EventBatch gen=2 m=18446744073709551615 time=19 size=17
+Sync
+Frequency freq=500000000
+ClockSnapshot dt=1 mono=199 sec=1740755050 nsec=123
+EventBatch gen=2 m=18446744073709551615 time=21 size=1
+Stacks
+EventBatch gen=2 m=18446744073709551615 time=22 size=1
+Strings
+EventBatch gen=3 m=18446744073709551615 time=29 size=17
+Sync
+Frequency freq=500000000
+ClockSnapshot dt=1 mono=299 sec=1740755051 nsec=123
+EventBatch gen=3 m=1 time=40 size=4
+ProcStatus dt=1 p=0 pstatus=1
+EventBatch gen=3 m=18446744073709551615 time=31 size=1
+Stacks
+EventBatch gen=3 m=18446744073709551615 time=32 size=1
+Strings