From ab609d2ac70200b0b1b8132e118b808928fe87a2 Mon Sep 17 00:00:00 2001 From: not-matthias Date: Fri, 30 Oct 2026 19:30:04 +0100 Subject: [PATCH] fix(go-runner): count all timed segments of a b.Loop() iteration In b.Loop() mode, each iteration is saved as one round. The round time was the time since the last StartTimer call, so the timed work before a StopTimer/StartTimer pair in the same iteration was dropped. A benchmark that times its work, stops the timer for a teardown, and restarts it before the next b.Loop() reported only the few hundred nanoseconds between that StartTimer and b.Loop(), while go test reported the real time per operation. Save the timed duration accumulated since the previous round instead. b.N rounds are unchanged: runN resets the timer before each round, so the delta is b.duration. --- example/setup_test.go | 12 ++++++ go-runner/overlay/benchmark1.24.0.go | 1 + go-runner/overlay/benchmark1.24.0.patch | 35 ++++++++-------- go-runner/overlay/benchmark1.25.0.go | 1 + go-runner/overlay/benchmark1.25.0.patch | 37 ++++++++--------- go-runner/overlay/benchmark1.26.0.go | 1 + go-runner/overlay/benchmark1.26.0.patch | 37 ++++++++--------- go-runner/overlay/codspeed.go | 16 +++----- go-runner/src/integration_tests.rs | 40 +++++++++++++++++++ ...sts__assert_results_snapshots@example.snap | 11 +++++ 10 files changed, 128 insertions(+), 63 deletions(-) diff --git a/example/setup_test.go b/example/setup_test.go index b0254ab..0f9d19c 100644 --- a/example/setup_test.go +++ b/example/setup_test.go @@ -74,6 +74,18 @@ func BenchmarkWithOutlierMeasurementModern(b *testing.B) { } } +// The timer is restarted after the teardown, so the timed work is not the last timed segment of +// the iteration. +func BenchmarkWithTeardownInLoopModern(b *testing.B) { + for b.Loop() { + time.Sleep(1 * time.Millisecond) + + b.StopTimer() + time.Sleep(10 * time.Millisecond) + b.StartTimer() + } +} + func BenchmarkWithoutStartupModern(b *testing.B) { time.Sleep(10 * time.Millisecond) b.ResetTimer() diff --git a/go-runner/overlay/benchmark1.24.0.go b/go-runner/overlay/benchmark1.24.0.go index 20c6c3c..1a9d695 100644 --- a/go-runner/overlay/benchmark1.24.0.go +++ b/go-runner/overlay/benchmark1.24.0.go @@ -174,6 +174,7 @@ func (b *B) ResetTimer() { b.startTimestamp = CurrentTimestamp() } b.duration = 0 + b.savedDuration = 0 b.netAllocs = 0 b.netBytes = 0 diff --git a/go-runner/overlay/benchmark1.24.0.patch b/go-runner/overlay/benchmark1.24.0.patch index be877e2..2bb59ab 100644 --- a/go-runner/overlay/benchmark1.24.0.patch +++ b/go-runner/overlay/benchmark1.24.0.patch @@ -72,7 +72,7 @@ } } -@@ -161,10 +170,18 @@ +@@ -161,10 +170,19 @@ b.startAllocs = memStats.Mallocs b.startBytes = memStats.TotalAlloc b.start = highPrecisionTimeNow() @@ -80,6 +80,7 @@ + b.startTimestamp = CurrentTimestamp() } b.duration = 0 ++ b.savedDuration = 0 b.netAllocs = 0 b.netBytes = 0 + @@ -91,7 +92,7 @@ } // SetBytes records the number of bytes processed in a single operation. -@@ -180,6 +197,11 @@ +@@ -180,6 +198,11 @@ // runN runs a single benchmark for the specified number of iterations. func (b *B) runN(n int) { @@ -103,7 +104,7 @@ benchmarkLock.Lock() defer benchmarkLock.Unlock() ctx, cancelCtx := context.WithCancel(context.Background()) -@@ -192,7 +214,9 @@ +@@ -192,7 +215,9 @@ runtime.GC() b.resetRaces() b.N = n @@ -114,7 +115,7 @@ b.ctx = ctx b.cancelCtx = cancelCtx -@@ -201,8 +225,13 @@ +@@ -201,8 +226,13 @@ b.StartTimer() b.benchFunc(b) b.StopTimer() @@ -128,7 +129,7 @@ } // run1 runs the first iteration of benchFunc. It reports whether more -@@ -225,6 +254,8 @@ +@@ -225,6 +255,8 @@ }() <-b.signal if b.failed { @@ -137,7 +138,7 @@ fmt.Fprintf(b.w, "%s--- FAIL: %s\n%s", b.chatty.prefix(), b.name, b.output) return false } -@@ -253,6 +284,8 @@ +@@ -253,6 +285,8 @@ // subbenchmarks. b must not have subbenchmarks. func (b *B) run() { labelsOnce.Do(func() { @@ -146,7 +147,7 @@ fmt.Fprintf(b.w, "goos: %s\n", runtime.GOOS) fmt.Fprintf(b.w, "goarch: %s\n", runtime.GOARCH) if b.importPath != "" { -@@ -312,8 +345,8 @@ +@@ -312,8 +346,8 @@ }() // b.Loop does its own ramp-up logic so we just need to run it once. @@ -157,7 +158,7 @@ // Run the benchmark for at least the specified amount of time. if b.benchTime.n > 0 { // We already ran a single iteration in run1. -@@ -323,18 +356,10 @@ +@@ -323,18 +357,10 @@ b.runN(b.benchTime.n) } } else { @@ -178,7 +179,7 @@ } // Elapsed returns the measured elapsed time of the benchmark. -@@ -368,42 +393,93 @@ +@@ -368,42 +394,93 @@ } func (b *B) stopOrScaleBLoop() bool { @@ -293,7 +294,7 @@ } // Loop returns true as long as the benchmark should continue running. -@@ -440,13 +516,41 @@ +@@ -440,13 +517,41 @@ // whereas b.N-based benchmarks must run the benchmark function (and any // associated setup and cleanup) several times. func (b *B) Loop() bool { @@ -337,7 +338,7 @@ // BenchmarkResult contains the results of a benchmark run. type BenchmarkResult struct { N int // The number of iterations. -@@ -455,6 +559,9 @@ +@@ -455,6 +560,9 @@ MemAllocs uint64 // The total number of memory allocations. MemBytes uint64 // The total number of bytes allocated. @@ -347,7 +348,7 @@ // Extra records additional metrics reported by ReportMetric. Extra map[string]float64 } -@@ -635,6 +742,9 @@ +@@ -635,6 +743,9 @@ w: os.Stdout, bench: true, }, @@ -357,7 +358,7 @@ importPath: importPath, benchFunc: func(b *B) { for _, Benchmark := range bs { -@@ -644,6 +754,9 @@ +@@ -644,6 +755,9 @@ benchTime: benchTime, bstate: bstate, } @@ -367,7 +368,7 @@ if Verbose() { main.chatty = newChattyPrinter(main.w) } -@@ -672,6 +785,7 @@ +@@ -672,6 +786,7 @@ chatty: b.chatty, bench: true, }, @@ -375,7 +376,7 @@ benchFunc: b.benchFunc, benchTime: b.benchTime, } -@@ -679,6 +793,8 @@ +@@ -679,6 +794,8 @@ } r := b.doBench() if b.failed { @@ -384,7 +385,7 @@ // The output could be very long here, but probably isn't. // We print it all, regardless, because we don't want to trim the reason // the benchmark failed. -@@ -686,6 +802,8 @@ +@@ -686,6 +803,8 @@ continue } results := r.String() @@ -393,7 +394,7 @@ if b.chatty != nil { fmt.Fprintf(b.w, "%-*s\t", s.maxLen, benchName) } -@@ -746,6 +864,7 @@ +@@ -746,6 +865,7 @@ chatty: b.chatty, bench: true, }, diff --git a/go-runner/overlay/benchmark1.25.0.go b/go-runner/overlay/benchmark1.25.0.go index 67849e3..5ea7931 100644 --- a/go-runner/overlay/benchmark1.25.0.go +++ b/go-runner/overlay/benchmark1.25.0.go @@ -174,6 +174,7 @@ func (b *B) ResetTimer() { b.startTimestamp = CurrentTimestamp() } b.duration = 0 + b.savedDuration = 0 b.netAllocs = 0 b.netBytes = 0 diff --git a/go-runner/overlay/benchmark1.25.0.patch b/go-runner/overlay/benchmark1.25.0.patch index ae711c0..aa6e5d0 100644 --- a/go-runner/overlay/benchmark1.25.0.patch +++ b/go-runner/overlay/benchmark1.25.0.patch @@ -53,7 +53,7 @@ } } -@@ -176,10 +170,18 @@ +@@ -176,10 +170,19 @@ b.startAllocs = memStats.Mallocs b.startBytes = memStats.TotalAlloc b.start = highPrecisionTimeNow() @@ -61,6 +61,7 @@ + b.startTimestamp = CurrentTimestamp() } b.duration = 0 ++ b.savedDuration = 0 b.netAllocs = 0 b.netBytes = 0 + @@ -72,7 +73,7 @@ } // SetBytes records the number of bytes processed in a single operation. -@@ -195,6 +197,11 @@ +@@ -195,6 +198,11 @@ // runN runs a single benchmark for the specified number of iterations. func (b *B) runN(n int) { @@ -84,7 +85,7 @@ benchmarkLock.Lock() defer benchmarkLock.Unlock() ctx, cancelCtx := context.WithCancel(context.Background()) -@@ -218,6 +225,7 @@ +@@ -218,6 +226,7 @@ b.StartTimer() b.benchFunc(b) b.StopTimer() @@ -92,7 +93,7 @@ b.previousN = n b.previousDuration = b.duration -@@ -246,6 +254,8 @@ +@@ -246,6 +255,8 @@ }() <-b.signal if b.failed { @@ -101,7 +102,7 @@ fmt.Fprintf(b.w, "%s--- FAIL: %s\n%s", b.chatty.prefix(), b.name, b.output) return false } -@@ -274,6 +284,8 @@ +@@ -274,6 +285,8 @@ // subbenchmarks. b must not have subbenchmarks. func (b *B) run() { labelsOnce.Do(func() { @@ -110,7 +111,7 @@ fmt.Fprintf(b.w, "goos: %s\n", runtime.GOOS) fmt.Fprintf(b.w, "goarch: %s\n", runtime.GOARCH) if b.importPath != "" { -@@ -344,18 +356,10 @@ +@@ -344,18 +357,10 @@ b.runN(b.benchTime.n) } } else { @@ -131,7 +132,7 @@ } // Elapsed returns the measured elapsed time of the benchmark. -@@ -408,9 +412,9 @@ +@@ -408,9 +413,9 @@ func (b *B) loopSlowPath() bool { // Consistency checks @@ -144,7 +145,7 @@ if b.loop.i&loopPoisonMask != 0 { panic(fmt.Sprintf("unknown loop stop condition: %#x", b.loop.i)) } -@@ -426,7 +430,10 @@ +@@ -426,7 +431,10 @@ } // Within a b.Loop loop, we don't use b.N (to avoid confusion). b.N = 0 @@ -155,7 +156,7 @@ // Start the next iteration. b.loop.i++ -@@ -445,16 +452,31 @@ +@@ -445,16 +453,31 @@ more = false } else { // Handle fixed time case @@ -189,7 +190,7 @@ // Start the next iteration. b.loop.i++ return true -@@ -495,6 +517,8 @@ +@@ -495,6 +518,8 @@ // whereas b.N-based benchmarks must run the benchmark function (and any // associated setup and cleanup) several times. func (b *B) Loop() bool { @@ -198,7 +199,7 @@ // This is written such that the fast path is as fast as possible and can be // inlined. // -@@ -509,6 +533,7 @@ +@@ -509,6 +534,7 @@ // path can do consistency checks and fail. if b.loop.i < b.loop.n { b.loop.i++ @@ -206,7 +207,7 @@ return true } return b.loopSlowPath() -@@ -535,6 +560,9 @@ +@@ -535,6 +561,9 @@ MemAllocs uint64 // The total number of memory allocations. MemBytes uint64 // The total number of bytes allocated. @@ -216,7 +217,7 @@ // Extra records additional metrics reported by ReportMetric. Extra map[string]float64 } -@@ -715,6 +743,9 @@ +@@ -715,6 +744,9 @@ w: os.Stdout, bench: true, }, @@ -226,7 +227,7 @@ importPath: importPath, benchFunc: func(b *B) { for _, Benchmark := range bs { -@@ -724,6 +755,9 @@ +@@ -724,6 +756,9 @@ benchTime: benchTime, bstate: bstate, } @@ -236,7 +237,7 @@ if Verbose() { main.chatty = newChattyPrinter(main.w) } -@@ -752,6 +786,7 @@ +@@ -752,6 +787,7 @@ chatty: b.chatty, bench: true, }, @@ -244,7 +245,7 @@ benchFunc: b.benchFunc, benchTime: b.benchTime, } -@@ -760,6 +795,8 @@ +@@ -760,6 +796,8 @@ } r := b.doBench() if b.failed { @@ -253,7 +254,7 @@ // The output could be very long here, but probably isn't. // We print it all, regardless, because we don't want to trim the reason // the benchmark failed. -@@ -767,6 +804,8 @@ +@@ -767,6 +805,8 @@ continue } results := r.String() @@ -262,7 +263,7 @@ if b.chatty != nil { fmt.Fprintf(b.w, "%-*s\t", s.maxLen, benchName) } -@@ -827,6 +866,7 @@ +@@ -827,6 +867,7 @@ chatty: b.chatty, bench: true, }, diff --git a/go-runner/overlay/benchmark1.26.0.go b/go-runner/overlay/benchmark1.26.0.go index 3a8d171..9ec4b2e 100644 --- a/go-runner/overlay/benchmark1.26.0.go +++ b/go-runner/overlay/benchmark1.26.0.go @@ -174,6 +174,7 @@ func (b *B) ResetTimer() { b.startTimestamp = CurrentTimestamp() } b.duration = 0 + b.savedDuration = 0 b.netAllocs = 0 b.netBytes = 0 diff --git a/go-runner/overlay/benchmark1.26.0.patch b/go-runner/overlay/benchmark1.26.0.patch index ce62a75..d6b3093 100644 --- a/go-runner/overlay/benchmark1.26.0.patch +++ b/go-runner/overlay/benchmark1.26.0.patch @@ -53,7 +53,7 @@ } } -@@ -176,10 +170,18 @@ +@@ -176,10 +170,19 @@ b.startAllocs = memStats.Mallocs b.startBytes = memStats.TotalAlloc b.start = highPrecisionTimeNow() @@ -61,6 +61,7 @@ + b.startTimestamp = CurrentTimestamp() } b.duration = 0 ++ b.savedDuration = 0 b.netAllocs = 0 b.netBytes = 0 + @@ -72,7 +73,7 @@ } // SetBytes records the number of bytes processed in a single operation. -@@ -195,6 +197,11 @@ +@@ -195,6 +198,11 @@ // runN runs a single benchmark for the specified number of iterations. func (b *B) runN(n int) { @@ -84,7 +85,7 @@ benchmarkLock.Lock() defer benchmarkLock.Unlock() ctx, cancelCtx := context.WithCancel(context.Background()) -@@ -218,6 +225,7 @@ +@@ -218,6 +226,7 @@ b.StartTimer() b.benchFunc(b) b.StopTimer() @@ -92,7 +93,7 @@ b.previousN = n b.previousDuration = b.duration -@@ -246,6 +254,8 @@ +@@ -246,6 +255,8 @@ }() <-b.signal if b.failed { @@ -101,7 +102,7 @@ fmt.Fprintf(b.w, "%s--- FAIL: %s\n%s", b.chatty.prefix(), b.name, b.output) return false } -@@ -274,6 +284,8 @@ +@@ -274,6 +285,8 @@ // subbenchmarks. b must not have subbenchmarks. func (b *B) run() { labelsOnce.Do(func() { @@ -110,7 +111,7 @@ fmt.Fprintf(b.w, "goos: %s\n", runtime.GOOS) fmt.Fprintf(b.w, "goarch: %s\n", runtime.GOARCH) if b.importPath != "" { -@@ -347,18 +359,10 @@ +@@ -347,18 +360,10 @@ b.runN(b.benchTime.n) } } else { @@ -131,7 +132,7 @@ } // Elapsed returns the measured elapsed time of the benchmark. -@@ -413,9 +417,9 @@ +@@ -413,9 +418,9 @@ func (b *B) loopSlowPath() bool { // Consistency checks @@ -144,7 +145,7 @@ if b.loop.i&loopPoisonMask != 0 { panic(fmt.Sprintf("unknown loop stop condition: %#x", b.loop.i)) } -@@ -431,7 +435,10 @@ +@@ -431,7 +436,10 @@ } // Within a b.Loop loop, we don't use b.N (to avoid confusion). b.N = 0 @@ -155,7 +156,7 @@ // Start the next iteration. b.loop.i++ -@@ -450,16 +457,31 @@ +@@ -450,16 +458,31 @@ more = false } else { // Handle fixed time case @@ -189,7 +190,7 @@ // Start the next iteration. b.loop.i++ return true -@@ -500,6 +522,8 @@ +@@ -500,6 +523,8 @@ // whereas b.N-based benchmarks must run the benchmark function (and any // associated setup and cleanup) several times. func (b *B) Loop() bool { @@ -198,7 +199,7 @@ // This is written such that the fast path is as fast as possible and can be // inlined. // -@@ -514,6 +538,7 @@ +@@ -514,6 +539,7 @@ // path can do consistency checks and fail. if b.loop.i < b.loop.n { b.loop.i++ @@ -206,7 +207,7 @@ return true } return b.loopSlowPath() -@@ -540,6 +565,9 @@ +@@ -540,6 +566,9 @@ MemAllocs uint64 // The total number of memory allocations. MemBytes uint64 // The total number of bytes allocated. @@ -216,7 +217,7 @@ // Extra records additional metrics reported by ReportMetric. Extra map[string]float64 } -@@ -720,6 +748,9 @@ +@@ -720,6 +749,9 @@ w: os.Stdout, bench: true, }, @@ -226,7 +227,7 @@ importPath: importPath, benchFunc: func(b *B) { for _, Benchmark := range bs { -@@ -729,6 +760,9 @@ +@@ -729,6 +761,9 @@ benchTime: benchTime, bstate: bstate, } @@ -236,7 +237,7 @@ if Verbose() { main.chatty = newChattyPrinter(main.w) } -@@ -757,6 +791,7 @@ +@@ -757,6 +792,7 @@ chatty: b.chatty, bench: true, }, @@ -244,7 +245,7 @@ benchFunc: b.benchFunc, benchTime: b.benchTime, } -@@ -765,6 +800,8 @@ +@@ -765,6 +801,8 @@ } r := b.doBench() if b.failed { @@ -253,7 +254,7 @@ // The output could be very long here, but probably isn't. // We print it all, regardless, because we don't want to trim the reason // the benchmark failed. -@@ -772,6 +809,8 @@ +@@ -772,6 +810,8 @@ continue } results := r.String() @@ -262,7 +263,7 @@ if b.chatty != nil { fmt.Fprintf(b.w, "%-*s\t", s.maxLen, benchName) } -@@ -832,6 +871,7 @@ +@@ -832,6 +872,7 @@ chatty: b.chatty, bench: true, }, diff --git a/go-runner/overlay/codspeed.go b/go-runner/overlay/codspeed.go index a5f0458..b7d67da 100644 --- a/go-runner/overlay/codspeed.go +++ b/go-runner/overlay/codspeed.go @@ -31,6 +31,10 @@ type codspeed struct { // Indicates whether a measurement has been saved already. This aims to prevent saving measurements // twice, because `b.Loop()` saves them internally as well but is also called from runN savedMeasurement bool + // The value of b.duration when the previous round was saved. A round is the timed duration + // accumulated since then, so it includes every StartTimer/StopTimer segment of a b.Loop() + // iteration and not only the last one. + savedDuration time.Duration // The start time of the first b.Loop() call. This includes the benchmark execution // time, including the overhead of start/stop the timer each loop iteration. @@ -274,16 +278,8 @@ func (b *B) SaveMeasurement() { // For b.Loop() loops: loopSlowPath sets b.N to 0 to prevent b.N loops within b.Loop. However, since // we're starting/stopping the timer for each iteration in the b.Loop() loop, we can use 1 as // the number of iterations for this round. - timeSinceStart := highPrecisionTimeSince(b.start) - - // If this gets called from b.Loop(), we have to take the duration compared to the previous StartTimer, - // if it's called from runN, we can use b.duration - duration := time.Duration(0) - if b.N == 0 { - duration = timeSinceStart - } else { - duration = b.duration - } + duration := b.duration - b.savedDuration + b.savedDuration = b.duration b.codspeedItersPerRound = append(b.codspeedItersPerRound, max(int64(b.N), 1)) b.codspeedTimePerRoundNs = append(b.codspeedTimePerRoundNs, duration) diff --git a/go-runner/src/integration_tests.rs b/go-runner/src/integration_tests.rs index f0e2874..33f91bd 100644 --- a/go-runner/src/integration_tests.rs +++ b/go-runner/src/integration_tests.rs @@ -106,6 +106,46 @@ fn test_build_and_run(#[case] project_name: &str) { assert_results_snapshots(&profile_dir, project_name); } +/// A `b.Loop()` round must include the timed work that runs before `b.StopTimer()`, even when +/// `b.StartTimer()` is called again before the next `b.Loop()`. +#[test_log::test] +fn test_b_loop_round_includes_work_before_stop_timer() { + const BENCH_NAME: &str = "BenchmarkWithTeardownInLoopModern"; + // The benchmark sleeps 1ms with the timer running in each iteration. + const MIN_ROUND_NS: f64 = 1_000_000.0; + + let project_dir = PathBuf::from(env!("CARGO_MANIFEST_DIR")).join("testdata/projects/example"); + let temp_dir = TempDir::new().unwrap(); + let profile_dir = temp_dir.path().join("profile"); + let cli = crate::cli::Cli { + bench: format!("^{BENCH_NAME}$"), + benchtime: "1x".into(), + packages: vec![".".into()], + }; + if let Err(error) = crate::run_benchmarks(&*profile_dir, project_dir.as_path(), &cli) { + panic!("Benchmarks couldn't run: {error}"); + } + + let results = std::fs::read_dir(profile_dir.join("results")) + .expect("Failed to read results directory") + .map(|entry| { + let file = std::fs::File::open(entry.unwrap().path()).unwrap(); + serde_json::from_reader::<_, serde_json::Value>(file).unwrap() + }) + .collect::>(); + let benchmark = results + .iter() + .flat_map(|result| result["benchmarks"].as_array().unwrap()) + .find(|benchmark| benchmark["name"] == BENCH_NAME) + .expect("Benchmark result not found"); + + let min_ns = benchmark["stats"]["min_ns"].as_f64().unwrap(); + assert!( + min_ns >= MIN_ROUND_NS, + "Round of {min_ns}ns does not include the timed work" + ); +} + fn can_build_project(project_dir: &Path) -> bool { if let Some(required_version) = project_go_version(project_dir) { let current_version = go_version().unwrap(); diff --git a/go-runner/src/snapshots/codspeed_go_runner__integration_tests__assert_results_snapshots@example.snap b/go-runner/src/snapshots/codspeed_go_runner__integration_tests__assert_results_snapshots@example.snap index b93d29f..816598b 100644 --- a/go-runner/src/snapshots/codspeed_go_runner__integration_tests__assert_results_snapshots@example.snap +++ b/go-runner/src/snapshots/codspeed_go_runner__integration_tests__assert_results_snapshots@example.snap @@ -213,6 +213,17 @@ expression: results }, "stats": "[stats]" }, + { + "name": "BenchmarkWithTeardownInLoopModern", + "uri": "example/setup_test.go::BenchmarkWithTeardownInLoopModern", + "config": { + "warmup_time_ns": null, + "min_round_time_ns": null, + "max_time_ns": null, + "max_rounds": null + }, + "stats": "[stats]" + }, { "name": "BenchmarkWithoutStartupModern", "uri": "example/setup_test.go::BenchmarkWithoutStartupModern",