From 07b94b2db23eda9ff4629cd8c2a0a32decdae08b Mon Sep 17 00:00:00 2001 From: =?utf8?q?Felix=20Geisend=C3=B6rfer?= Date: Fri, 28 Feb 2025 17:30:54 +0100 Subject: [PATCH] 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 Reviewed-by: David Chase LUCI-TryBot-Result: Go LUCI Reviewed-by: Michael Knyszek --- src/internal/trace/internal/testgen/trace.go | 77 +++++++++++++++---- src/internal/trace/reader_test.go | 74 ++++++++++++++++++ .../trace/testdata/generators/go123-sync.go | 30 ++++++++ .../trace/testdata/generators/go125-sync.go | 31 ++++++++ .../trace/testdata/tests/go123-sync.test | 26 +++++++ .../trace/testdata/tests/go125-sync.test | 32 ++++++++ 6 files changed, 257 insertions(+), 13 deletions(-) create mode 100644 src/internal/trace/testdata/generators/go123-sync.go create mode 100644 src/internal/trace/testdata/generators/go125-sync.go create mode 100644 src/internal/trace/testdata/tests/go123-sync.test create mode 100644 src/internal/trace/testdata/tests/go125-sync.test diff --git a/src/internal/trace/internal/testgen/trace.go b/src/internal/trace/internal/testgen/trace.go index af469f525c..415acaccae 100644 --- a/src/internal/trace/internal/testgen/trace.go +++ b/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 diff --git a/src/internal/trace/reader_test.go b/src/internal/trace/reader_test.go index b395183e0e..222d2dfa82 100644 --- a/src/internal/trace/reader_test.go +++ b/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}, + }) +} diff --git a/src/internal/trace/testdata/generators/go123-sync.go b/src/internal/trace/testdata/generators/go123-sync.go new file mode 100644 index 0000000000..257581c7ea --- /dev/null +++ b/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{}) +} diff --git a/src/internal/trace/testdata/generators/go125-sync.go b/src/internal/trace/testdata/generators/go125-sync.go new file mode 100644 index 0000000000..30ebf6717a --- /dev/null +++ b/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) +} diff --git a/src/internal/trace/testdata/tests/go123-sync.test b/src/internal/trace/testdata/tests/go123-sync.test new file mode 100644 index 0000000000..44e98e6c95 --- /dev/null +++ b/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 diff --git a/src/internal/trace/testdata/tests/go125-sync.test b/src/internal/trace/testdata/tests/go125-sync.test new file mode 100644 index 0000000000..dac3723b62 --- /dev/null +++ b/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 -- 2.50.0