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",