Richtig messen mit BenchmarkDotNet

In Lektion 3.9.5 haben Sie BenchmarkDotNet zum ersten Mal benutzt: Die Wochenübersicht brauchte nach der Reparatur ein Zehntel der Zeit, und die Tabelle hat es belegt. Dort war der Unterschied groß, dreihundert Abfragen gegen eine. In diesem Modul geht es um kleinere Unterschiede: eine Zuweisung hier, ein paar Nanosekunden dort, die erst unter Last zählen. Solche Unterschiede sind leicht falsch zu messen, und eine falsche Messung ist schlimmer als keine, weil sie eine Entscheidung begründet. Diese Lektion zeigt, wie eine Messung gebaut sein muss, damit sie stimmt, wie man ihr Ergebnis liest und wo ihre Grenzen liegen. Am Ende hat die Kladde ein eigenes Projekt bench/Kladde.Benchmarks, das in den nächsten Lektionen wächst.

Neu in dieser Lektion:

Warum eine Stoppuhr nicht reicht

Der naheliegende Weg, eine Methode zu messen, ist eine Schleife mit Stopwatch. Legen Sie in k3-uebungen/3-12 eine Datei stoppuhr.cs an. Sie prüft eine Million Mal, ob ein Schlagwort „Wartung“ heißt, gleich in welcher Schreibweise, und misst jede Runde:

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

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

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, "wartung", StringComparison.OrdinalIgnoreCase) ? 1 : 0;
    }

    double nanoseconds = watch.Elapsed.TotalNanoseconds / calls;
    Console.WriteLine($"Runde {round}: {calls,9:N0} Aufrufe, {nanoseconds,10:N1} ns je Aufruf ({hits:N0} Treffer)");
}

Die Zeile #:property PublishAot=false kennen Sie aus Lektion 3.9.5: Dateibasierte Apps sind sonst für Native AOT vorbereitet, und das braucht hier niemand. Starten Sie die Datei einmal ohne und einmal mit Release:

dotnet run stoppuhr.cs
dotnet run -c Release stoppuhr.cs

Runde 1:         1 Aufrufe,   73.500,0 ns je Aufruf (1 Treffer)
Runde 2: 1.000.000 Aufrufe,        8,7 ns je Aufruf (1.000.000 Treffer)
Runde 3: 1.000.000 Aufrufe,        9,5 ns je Aufruf (1.000.000 Treffer)
Runde 4: 1.000.000 Aufrufe,       17,5 ns je Aufruf (1.000.000 Treffer)
Runde 5: 1.000.000 Aufrufe,       12,5 ns je Aufruf (1.000.000 Treffer)
Runde 6: 1.000.000 Aufrufe,       12,2 ns je Aufruf (1.000.000 Treffer)
Runde 1:         1 Aufrufe,   34.500,0 ns je Aufruf (1 Treffer)
Runde 2: 1.000.000 Aufrufe,       11,5 ns je Aufruf (1.000.000 Treffer)
Runde 3: 1.000.000 Aufrufe,        2,5 ns je Aufruf (1.000.000 Treffer)
Runde 4: 1.000.000 Aufrufe,        2,1 ns je Aufruf (1.000.000 Treffer)
Runde 5: 1.000.000 Aufrufe,        6,7 ns je Aufruf (1.000.000 Treffer)
Runde 6: 1.000.000 Aufrufe,        1,6 ns je Aufruf (1.000.000 Treffer)

Die ersten sechs Zeilen sind der Debug-Build, die letzten sechs Release. Ihre Zahlen sind andere, das Muster ist dasselbe, und es enthält vier Lektionen:

• Der erste Aufruf ist tausendmal langsamer. Er übersetzt die Methode erst aus der Zwischensprache in Maschinencode (JIT). Wer nur einen Aufruf misst, misst den Übersetzer.
• Die zweite Runde ist langsamer als die dritte. .NET übersetzt in Stufen: zuerst schnell und schlicht (Stufe 0), und eine Methode, die oft läuft, später noch einmal gründlich (Stufe 1). Eine lange Schleife wird mittendrin umgestellt (On-Stack Replacement). Bis dahin läuft der schlichte Code.
• Runden schwanken ohne Grund im Code. Runde 5 im Release-Build braucht dreimal so lang wie Runde 4. Der Rechner tut nebenbei anderes, die Taktfrequenz ändert sich, eine Speicherbereinigung fällt in die Runde.
• Debug misst etwas anderes. Im Debug-Build optimiert der Compiler nicht; die Zahlen dort sagen über den Betrieb nichts.

Dazu kommt, was diese Schleife nicht zeigt: Ein Compiler, der merkt, dass ein Ergebnis nie benutzt wird, darf die Arbeit weglassen. Hier zählt hits die Treffer und wird ausgegeben, deshalb bleibt die Arbeit stehen. Ohne diese Ausgabe würde die Schleife vielleicht gar nichts messen.