Measuring right with BenchmarkDotNet

In lesson 3.9.5 you used BenchmarkDotNet for the first time: after the repair, the week overview needed a tenth of the time, and the table proved it. There the difference was large, three hundred queries against one. This module is about smaller differences: an allocation here, a few nanoseconds there, which only count under load. Such differences are easy to measure wrongly, and a wrong measurement is worse than none, because it justifies a decision. This lesson shows how a measurement has to be built to be right, how to read its result, and where its limits are. At the end, the Kladde has a project of its own, bench/Kladde.Benchmarks, which grows in the next lessons.

New in this lesson:

Why a stopwatch is not enough

The obvious way to measure a method is a loop with Stopwatch. In k3-exercises/3-12, create a file stopwatch.cs. It checks a million times whether a tag is “service”, whatever its spelling, and measures each round:

// stopwatch.cs: the same method measured with a Stopwatch, round after round
#:property PublishAot=false
using System.Diagnostics;

string tag = args.Length > 0 ? args[0] : "SERVICE";

for (int round = 1; round <= 6; round++)
{
    var watch = Stopwatch.StartNew();
    int hits = 0;
    int calls = round == 1 ? 1 : 1_000_000;
    for (int i = 0; i < calls; i++)
    {
        hits += string.Equals(tag, "service", StringComparison.OrdinalIgnoreCase) ? 1 : 0;
    }

    double nanoseconds = watch.Elapsed.TotalNanoseconds / calls;
    Console.WriteLine($"Round {round}: {calls,9:N0} calls, {nanoseconds,10:N1} ns per call (hits: {hits:N0})");
}

You know the line #:property PublishAot=false from lesson 3.9.5: file-based apps are otherwise prepared for Native AOT, and nobody needs that here. Run the file once without and once with Release:

dotnet run stopwatch.cs
dotnet run -c Release stopwatch.cs

Round 1:         1 calls,   73,500.0 ns per call (hits: 1)
Round 2: 1,000,000 calls,        8.7 ns per call (hits: 1,000,000)
Round 3: 1,000,000 calls,        9.5 ns per call (hits: 1,000,000)
Round 4: 1,000,000 calls,       17.5 ns per call (hits: 1,000,000)
Round 5: 1,000,000 calls,       12.5 ns per call (hits: 1,000,000)
Round 6: 1,000,000 calls,       12.2 ns per call (hits: 1,000,000)
Round 1:         1 calls,   34,500.0 ns per call (hits: 1)
Round 2: 1,000,000 calls,       11.5 ns per call (hits: 1,000,000)
Round 3: 1,000,000 calls,        2.5 ns per call (hits: 1,000,000)
Round 4: 1,000,000 calls,        2.1 ns per call (hits: 1,000,000)
Round 5: 1,000,000 calls,        6.7 ns per call (hits: 1,000,000)
Round 6: 1,000,000 calls,        1.6 ns per call (hits: 1,000,000)

The first six lines are the debug build, the last six are release. Your numbers will be different, the pattern is the same, and it holds four lessons:

• The first call is a thousand times slower. It first compiles the method from the intermediate language into machine code (JIT). Whoever measures only one call measures the compiler.
• The second round is slower than the third. .NET compiles in tiers: first quick and plain (tier 0), and a method that runs often gets compiled once more, thoroughly, later (tier 1). A long loop is switched over in the middle (on-stack replacement). Until then the plain code runs.
• Rounds fluctuate for no reason in the code. Round 5 in the release build takes three times as long as round 4. The machine is doing other things on the side, the clock frequency changes, a garbage collection falls into the round.
• Debug measures something different. In the debug build the compiler does not optimize; the numbers there say nothing about production.

On top of that comes what this loop does not show: a compiler that notices that a result is never used may leave out the work. Here hits counts the hits and is printed, which is why the work stays. Without that output, the loop might measure nothing at all.