From 178b6adeb8d551a1e57adcd8b62be62150d35f6f Mon Sep 17 00:00:00 2001 From: Adam Sitnik Date: Mon, 26 Oct 2020 16:42:58 +0100 Subject: [PATCH] Don't run the benchmark once per iteration if only the first ivocation lasts longer than IterationTime (#1573) * add the test * if the Jitting took more than IterationTime but still less than 1s (a magic number based on observations of the reported bug) we call it one more time to see if Jitting itself has not dominated the first invocation if it did, it shoud NOT be a single invocation engine (fixes #837, fixes #1337 and fixes #1338) --- src/BenchmarkDotNet/Engines/EngineFactory.cs | 8 +++ src/BenchmarkDotNet/Engines/EngineResolver.cs | 3 +- .../Engine/EngineFactoryTests.cs | 50 +++++++++++++++++-- 3 files changed, 56 insertions(+), 5 deletions(-) diff --git a/src/BenchmarkDotNet/Engines/EngineFactory.cs b/src/BenchmarkDotNet/Engines/EngineFactory.cs index f15c21facc..c438890e84 100644 --- a/src/BenchmarkDotNet/Engines/EngineFactory.cs +++ b/src/BenchmarkDotNet/Engines/EngineFactory.cs @@ -44,6 +44,14 @@ public IEngine CreateReadyToRun(EngineParameters engineParameters) var singleActionEngine = CreateSingleActionEngine(engineParameters); var singleInvocationTime = Jit(singleActionEngine, ++jitIndex, invokeCount: 1, unrollFactor: 1); + if (singleInvocationTime > engineParameters.IterationTime && singleInvocationTime < TimeInterval.FromSeconds(1.0)) + { + // if the Jitting took more than IterationTime but still less than 1s (a magic number based on observations of the reported bug) + // we call it one more time to see if Jitting itself has not dominated the first invocation + // if it did, it shoud NOT be a single invocation engine (see #837, #1337 and #1338) + singleInvocationTime = Jit(singleActionEngine, ++jitIndex, invokeCount: 1, unrollFactor: 1); + } + if (singleInvocationTime > engineParameters.IterationTime) return singleActionEngine; // executing once takes longer than iteration time => long running benchmark, needs no pilot and no overhead diff --git a/src/BenchmarkDotNet/Engines/EngineResolver.cs b/src/BenchmarkDotNet/Engines/EngineResolver.cs index 9f042e003d..8ecee9e93c 100644 --- a/src/BenchmarkDotNet/Engines/EngineResolver.cs +++ b/src/BenchmarkDotNet/Engines/EngineResolver.cs @@ -10,6 +10,7 @@ public class EngineResolver : Resolver { internal const int DefaultMinWorkloadIterationCount = 15; internal const int DefaultMaxWorkloadIterationCount = 100; + internal const int DefaultIterationTime = 500; internal const int ForceAutoWarmup = -1; internal const int DefaultMinWarmupIterationCount = 6; @@ -20,7 +21,7 @@ public class EngineResolver : Resolver private EngineResolver() { Register(RunMode.RunStrategyCharacteristic, () => RunStrategy.Throughput); - Register(RunMode.IterationTimeCharacteristic, () => TimeInterval.Millisecond * 500); + Register(RunMode.IterationTimeCharacteristic, () => TimeInterval.Millisecond * DefaultIterationTime); Register(RunMode.MinIterationCountCharacteristic, () => DefaultMinWorkloadIterationCount); Register(RunMode.MaxIterationCountCharacteristic, () => DefaultMaxWorkloadIterationCount); diff --git a/tests/BenchmarkDotNet.Tests/Engine/EngineFactoryTests.cs b/tests/BenchmarkDotNet.Tests/Engine/EngineFactoryTests.cs index 74287d168b..08cd29fcd8 100644 --- a/tests/BenchmarkDotNet.Tests/Engine/EngineFactoryTests.cs +++ b/tests/BenchmarkDotNet.Tests/Engine/EngineFactoryTests.cs @@ -7,6 +7,7 @@ using BenchmarkDotNet.Jobs; using BenchmarkDotNet.Running; using JetBrains.Annotations; +using Perfolizer.Horology; using Xunit; namespace BenchmarkDotNet.Tests.Engine @@ -33,6 +34,14 @@ private void VeryTimeConsumingSingle(long _) Thread.Sleep(IterationTime); } + private void TimeConsumingOnlyForTheFirstCall(long _) + { + if (timesBenchmarkCalled++ == 0) + { + Thread.Sleep(IterationTime); + } + } + private void InstantNoUnroll(long invocationCount) => timesBenchmarkCalled += (int) invocationCount; private void InstantUnroll(long _) => timesBenchmarkCalled += 16; @@ -78,10 +87,10 @@ public void ForDefaultSettingsVeryTimeConsumingBenchmarksAreExecutedOncePerItera var engine = new EngineFactory().CreateReadyToRun(engineParameters); Assert.Equal(1, timesGlobalSetupCalled); - Assert.Equal(1, timesIterationSetupCalled); // 1x for Target - Assert.Equal(1, timesBenchmarkCalled); - Assert.Equal(1, timesOverheadCalled); - Assert.Equal(1, timesIterationCleanupCalled); // 1x for Target + Assert.Equal(2, timesIterationSetupCalled); // 2x for Target + Assert.Equal(2, timesBenchmarkCalled); + Assert.Equal(2, timesOverheadCalled); + Assert.Equal(2, timesIterationCleanupCalled); // 2x for Target Assert.Equal(0, timesGlobalCleanupCalled); // cleanup is called as part of dispose Assert.Equal(1, engine.TargetJob.Run.InvocationCount); // call the benchmark once per iteration @@ -95,6 +104,39 @@ public void ForDefaultSettingsVeryTimeConsumingBenchmarksAreExecutedOncePerItera Assert.Equal(1, timesGlobalCleanupCalled); } + [Theory] + [InlineData(120)] // 120 ms as in the bug report + [InlineData(250)] // 250 ms as configured in dotnet/performance repo + [InlineData(EngineResolver.DefaultIterationTime)] // 500 ms - the default BDN setting + public void BenchmarksThatRunLongerThanIterationTimeOnlyDuringFirstInvocationAreNotInvokedOncePerIteration(int iterationTime) + { + var engineParameters = CreateEngineParameters( + mainNoUnroll: TimeConsumingOnlyForTheFirstCall, + mainUnroll: InstantUnroll, + job: Job.Default.WithIterationTime(TimeInterval.FromMilliseconds(iterationTime))); + + var engine = new EngineFactory().CreateReadyToRun(engineParameters); + + Assert.Equal(1, timesGlobalSetupCalled); + // the factory should call the benchmark: + // 1st time with unroll factor to JIT the code + // one more to check that the Jitting has not dominated the reported time + // and one more time to JIT the 16 unroll factor case as it turned out that Jitting has dominated the time + Assert.Equal(1 + 1 + 1, timesIterationSetupCalled); + Assert.Equal(1 + 1 + 16, timesBenchmarkCalled); + Assert.Equal(1 + 1 + 16, timesOverheadCalled); + Assert.Equal(1 + 1 + 1, timesIterationCleanupCalled); // 2x for Target + Assert.Equal(0, timesGlobalCleanupCalled); // cleanup is called as part of dispose + + Assert.False(engine.TargetJob.Run.HasValue(RunMode.InvocationCountCharacteristic)); // we need pilot stage + + Assert.False(engine.TargetJob.Run.HasValue(AccuracyMode.EvaluateOverheadCharacteristic)); + + engine.Dispose(); // cleanup is called as part of dispose + + Assert.Equal(1, timesGlobalCleanupCalled); + } + [Fact] public void ForJobsWithExplicitUnrollFactorTheGlobalSetupIsCalledAndMultiActionCodeGetsJitted() => AssertGlobalSetupWasCalledAndMultiActionGotJitted(Job.Default.WithUnrollFactor(16));