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)

Author: adamsitnik

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
 

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

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