First Time Call with BenchmarkDotNet

Question

I have tried out BenchmarkDotNet with a simple test class

public class BenchTest
{
    bool First = false;

    [Benchmark]
    public void FirstTimeInitEffect()
    {
        if (First == false)
        {
            Console.WriteLine("First called");
            First = true;
            Thread.Sleep(1000);
        }
        else
        {
            Thread.Sleep(10);
        }

    }
}

And let it run with

    static void Main(string[] args)
    {
        var cfg = ManualConfig.Create(DefaultConfig.Instance);
        var job = new Job();
        job.Accuracy.RemoveOutliers = false;
        cfg.Add(new Job[] {
            job
            }
        );

        BenchmarkRunner.Run<BenchTest>(cfg);
    }

This prints a nice summary but what I am missing from the results is that the first call to the method FirstTimeInitEffect takes 1s. I would expect from a benchmark tool to show me the first call effects as well. I have tried a custom config to prevent the removal of outliers but that did not the trick. Am I using the tool wrong or is this outside the scope of the tool?

    // * Detailed results *
BenchTest.FirstTimeInitEffect: Job-LQPFTL(RemoveOutliers=False)
Runtime = Clr 4.0.30319.42000, 32bit LegacyJIT-v4.6.1586.0; GC = Concurrent Workstation
Mean = 10.8548 ms, StdErr = 0.0169 ms (0.16%); N = 15, StdDev = 0.0654 ms
Min = 10.7158 ms, Q1 = 10.8058 ms, Median = 10.8963 ms, Q3 = 10.9011 ms, Max = 10.9029 ms
IQR = 0.0953 ms, LowerFence = 10.6628 ms, UpperFence = 11.0440 ms
ConfidenceInterval = [10.8217 ms; 10.8879 ms] (CI 95%)
Skewness = -1.01049139924314, Kurtosis = 2.40561202562778


Total time: 00:00:21 (21.92 sec)

// * Summary *

BenchmarkDotNet=v0.10.1, OS=Microsoft Windows NT 6.2.9200.0
Processor=Intel(R) Core(TM) i7-4770K CPU 3.50GHz, ProcessorCount=8
Frequency=3417979 Hz, Resolution=292.5706 ns, Timer=TSC
  [Host]     : Clr 4.0.30319.42000, 32bit LegacyJIT-v4.6.1586.0
  Job-LQPFTL : Clr 4.0.30319.42000, 32bit LegacyJIT-v4.6.1586.0

RemoveOutliers=False  Allocated=0 B

              Method |       Mean |    StdDev |
-------------------- |----------- |---------- |
 FirstTimeInitEffect | 10.8548 ms | 0.0654 ms |

Answer 1

BenchmarkDotNet does a lot of warmup iterations; it allows to achieve a steady state before we start to collect actual measurements. Also, it does some additional stuff which also invokes your method (jitting, pilot iterations, and so on). So, the first call was omitted and wasn't included in the summary.

If you want to get statistics based on all measurements (without jitting, pilot and warmup iterations), you should use RunStrategy.ColdStart (instead of RunStrategy.Throughput which is default). It works fine since BenchmarkDotNet v0.10.2.

Source code:

[SimpleJob(RunStrategy.ColdStart, targetCount: 5)]
[MinColumn, MaxColumn, MeanColumn, MedianColumn]
public class BenchTest
{
    private bool firstCall;

    [Benchmark]
    public void FirstTimeInitEffect()
    {
        if (firstCall == false)
        {
            firstCall = true;
            Console.WriteLine("// First call");
            Thread.Sleep(1000);
        }
        else
            Thread.Sleep(10);
    }
}

Measurements:

Result 1: 1 op, 1000582715.59 ns, 1.0006 s/op
Result 2: 1 op, 10190609.23 ns, 10.1906 ms/op
Result 3: 1 op, 10164930.24 ns, 10.1649 ms/op
Result 4: 1 op, 10604238.53 ns, 10.6042 ms/op
Result 5: 1 op, 10420930.04 ns, 10.4209 ms/op

Detailed results:

Mean = 208.4175 ms, StdErr = 198.1331 ms (95.07%); N = 5, StdDev = 443.0390 ms
Min = 10.1163 ms, Q1 = 10.1203 ms, Median = 10.4233 ms, Q3 = 505.7118 ms, Max = 1,000.9497 ms
IQR = 495.5915 ms, LowerFence = -733.2670 ms, UpperFence = 1,249.0991 ms
ConfidenceInterval = [-179.9233 ms; 596.7583 ms] (CI 95%)
Skewness = 1.07, Kurtosis = 2.08

Summary:

BenchmarkDotNet=v0.10.1, OS=Microsoft Windows NT 6.2.9200.0
Processor=Intel(R) Core(TM) i7-6700HQ CPU 2.60GHz, ProcessorCount=8
Frequency=2531252 Hz, Resolution=395.0614 ns, Timer=TSC
  [Host]     : Clr 4.0.30319.42000, 32bit LegacyJIT-v4.6.1586.0
  Job-IQRRGS : Clr 4.0.30319.42000, 32bit LegacyJIT-v4.6.1586.0

RunStrategy=ColdStart  TargetCount=5  Allocated=1.64 kB

              Method |        Mean |      StdErr |      StdDev |        Min |           Max |     Median |
-------------------- |------------ |------------ |------------ |----------- |-------------- |----------- |
 FirstTimeInitEffect | 208.4175 ms | 198.1331 ms | 443.0390 ms | 10.1163 ms | 1,000.9497 ms | 10.4233 ms |