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));