Ohne Kategorie

Rückgabewert 0 ist kein Beleg — sechs Nächte Benchmark, die nichts gemessen haben

7 min read

Ein Benchmark lief sechs Nächte lang, meldete jedes Mal Erfolg und hat dabei nichts gemessen. Die systemd-Unit endete sauber. Die Ergebnisdateien waren 84 Bytes groß. Hier steht, wie ein Job einen mit einer Null belügt — und welche zwei kleinen Wächter das beenden.

Das Symptom

Auf einem Linux-Rechner mit zwei GPUs läuft nachts ein Modellvergleich: Werkzeugaufrufe, Bildbeschreibung, Nährwertschätzung aus Fotos. Start um 01:00, Dauer etwa vier Stunden, eine Ergebnisdatei je Szenario.

Beim Nachsehen wegen einer völlig anderen Sache fiel mir auf, dass der Lauf nach fünfzig Sekunden fertig war. Nicht vier Stunden. Fünfzig Sekunden. Das Dienstprotokoll blieb gelassen:

nightly-bench.service: Deactivated successfully.
nightly-bench.service: Consumed 9.658s CPU time, 121.7M memory peak.

Und die Ergebnisse:

-rw-r--r-- 1 root root  84 Aug 21 01:00 A-tools.txt
-rw-r--r-- 1 root root  85 Aug 21 01:00 B-vision.txt
-rw-r--r-- 1 root root  88 Aug 21 01:00 C-nutrition.txt

Byte-identische Größen über sechs Nächte. Das ist keine Streuung. Das ist eine Konstante — und eine Konstante in einer Messung ist immer ein Fehler.

Defekt A: die Skripte waren nie richtig da

Jede Datei enthielt genau eine Zeile:

python3: can't open file '/tmp/bench-agent.py': [Errno 2] No such file or directory

Die drei Benchmark-Harnesses lagen in /tmp. Die Maschine war zurückgesetzt worden, und /tmp tat, wofür es da ist. Es existierte keine Kopie — ich habe jedes plausible Verzeichnis und beide Container durchsucht, bevor ich akzeptiert habe, dass sie endgültig weg sind.

Das ist ein peinlicher, aber gewöhnlicher Fehler: ein Skript, das als Wegwerf-Experiment anfing, wurde still zur Infrastruktur, und niemand hat es umgezogen. Der interessante Teil kommt jetzt.

Defekt B: das Skript konnte gar keinen Fehlschlag melden

Jedes Szenario endete mit einer Zeile dieser Form:

timeout 14400 python3 -u /tmp/bench-agent.py $LISTE > "$AUS/A-tools.txt" 2>&1
echo "  Ende $(date '+%H:%M:%S'), Rueckgabe $?"

Lies das $? noch einmal. Es enthält nicht den Rückgabewert von python3. Bash expandiert die Bestandteile dieser Zeichenkette von links nach rechts, und die Kommandosubstitution $(date …) führt ein Kommando aus. Wenn $? an die Reihe kommt, steht darin der Rückgabewert von date — und der ist immer 0.

Die Positivkontrolle braucht eine Zeile:

$ false; echo "Ende $(date +%s), Rueckgabe $?"
Ende 1787236298, Rueckgabe 0

$ false; echo "Rueckgabe $?"
Rueckgabe 1

Das Protokoll schrieb also brav Rueckgabe 0, während Python mit 2 endete. Dieser Defekt hat mit den fehlenden Dateien nichts zu tun. Er saß die ganze Zeit in dem Skript und garantierte still, dass kein Szenario-Fehlschlag jemals gemeldet werden kann — dieser nicht und kein künftiger. Defekt A war der Unfall. Defekt B war der Grund, warum er sechs Nächte unsichtbar blieb.

Die Korrektur ist trivial, sobald man sie sieht: den Rückgabewert als allererste Anweisung nach dem Kommando sichern.

timeout 14400 python3 -u "$LIB/bench-agent.py" ... > "$AUS/A-tools.txt" 2>&1
RC=$?                      # erste Anweisung, vor jeder Substitution
echo "  Ende $(date '+%H:%M:%S'), Rueckgabe $RC"

Die Regel, die daraus folgt: exit 0 ist kein Beleg

Beide Defekte haben dieselbe Form. Etwas meldete Erfolg, und dieser Erfolg war strukturell statt erarbeitet. Ein Result=success von systemd sagt, dass ein Prozess mit Null geendet hat. Es sagt nichts darüber, ob er seine Arbeit getan hat.

Der sanierte Läufer traut Rückgabewerten deshalb nicht mehr allein. Jedes Szenario wird an seiner Ausgabe geprüft: Mindestgröße, plus ein Grep auf die Signaturen eines Werkzeugfehlers statt einer Messung.

pruefe_ausgabe() {
    local name="$1" datei="$2" rc="$3" min_bytes="${4:-500}"
    local groesse=0
    [ -r "$datei" ] && groesse=$(stat -c %s "$datei")
    [ "$rc" -ne 0 ] && { echo "  !! $name: Harness endete mit $rc" >&2; FEHLER=$((FEHLER+1)); }
    if [ "$groesse" -lt "$min_bytes" ]; then
        echo "  !! $name: nur $groesse Bytes — das ist kein Messergebnis." >&2
        FEHLER=$((FEHLER+1)); return 1
    fi
    if grep -qE "can't open file|ModuleNotFoundError|Traceback" "$datei"; then
        echo "  !! $name: Ausgabe enthaelt einen Werkzeugfehler, kein Ergebnis." >&2
        FEHLER=$((FEHLER+1)); return 1
    fi
}

Zwei Details darin verdienen ihren Platz. Der Wächter prüft auf -r (lesbar), nicht auf -s (nicht leer) — stat braucht keine Leserechte, eine unlesbare Datei käme sonst durch die Größenprüfung. Und die Größe allein reicht nicht: ein Python-Traceback ist bequem größer als 500 Bytes und segelte glatt hindurch. Größe und Inhalt.

Danach habe ich den Wächter gegen den echten Fehlerfall getestet — die tatsächliche 84-Byte-Datei der letzten kaputten Nacht — plus einen großen Traceback, eine fehlende Datei und, entscheidend, eine gesunde Datei, die durchgehen muss. Vier Fälle, drei gefangen, einer durchgelassen. Ein Wächter, den man nur an Fehlschlägen getestet hat, ist ein Wächter, der womöglich alles ablehnt.

Dieselbe Fehlerklasse, zweimal an einem Nachmittag

Später am selben Tag wollte ich zwei Einstellungen eines Inferenzservers vergleichen und habe die Binärdatei direkt gestartet statt über ihren üblichen Verwalter. Sie kam hoch. Sie antwortete. Sie meldete:

prompt processing, n_tokens = 512, t = 38.91 s / 13.16 tokens per second

Dreizehn Token pro Sekunde auf einer Karte, die rund tausend macht. Der GPU-Speicher hatte sich nicht bewegt. Der Verwalter liefert normalerweise seine eigenen CUDA-Bibliotheken mit und zeigt der Binärdatei per Umgebungsvariablen den Weg dorthin; bar gestartet lud kein GPU-Backend, und der Server fiel still auf die CPU zurück — bei tadellos formatierten Zeitmessungen.

Ohne Prüfung hätte dieser Lauf eine vollständige, plausible, hübsch formatierte Vergleichstabelle aus CPU-Zahlen produziert. Der A/B-Harness sichert die Voraussetzung deshalb jetzt zu und weigert sich zu berichten, wenn er sie nicht belegen kann:

treffer = re.findall(r"offloaded (\d+)/(\d+) layers to GPU", protokoll)
if not treffer:
    log("  !! Keine offload-Zeile im Serverprotokoll — CPU-Fallback. Uebersprungen.")
    continue
n, m = int(treffer[-1][0]), int(treffer[-1][1])
if n < m:
    log("  !! Nur %d von %d Schichten auf der GPU — nicht vergleichbar." % (n, m))
    continue

Dieser Wächter hat dann einen Fehlschlag gefangen, den ich nicht vorhergesehen hatte: ein verwaister Serverprozess aus einem abgebrochenen Lauf hielt noch den Port, der neue Server konnte nicht binden und starb, und die Bereitschaftsprüfung wurde fröhlich vom alten Prozess mit den alten Einstellungen beantwortet. Der Wächter kannte diese Geschichte nicht. Er wusste nur, dass er die GPU-Nutzung nicht belegen konnte, und hat deshalb keine Zahl geliefert. Das ist das richtige Verhalten, und genau deshalb ist die Zusicherung mehr wert als der eine Fehler, für den sie geschrieben wurde.

Ein Nachtrag, der dazugehört: derselbe Harness weigerte sich korrekt mit Rückgabewert 3 — und ich habe seine Ausgabe durch | cat geschickt und damit den Rückgabewert auf 0 überschrieben. Dieselbe Fehlerklasse wie Defekt B, in derselben Stunde, von derselben Person, die gerade darüber schrieb.

Was ich mitnehmen würde

  • Eine Konstante in einer Messung ist ein Fehler. Identische Ausgabegrößen über mehrere Läufe sind der billigste Geruch, den es gibt, und kosten ein ls -la.
  • Exit 0 heißt, ein Prozess ist beendet — nicht, dass er funktioniert hat. Prüfe das Erzeugnis, nicht den Status.
  • $? sofort sichern. Alles zwischen Kommando und Auslesen — selbst ein Zeitstempel — kann es überschreiben.
  • Jede Diagnose braucht eine Positivkontrolle. Ein sauberer Grep und ein kaputtes Muster sehen identisch aus. Schick etwas durch, das anschlagen muss.
  • Sichere deine Voraussetzungen zu, nicht nur deine Ergebnisse. „Wird die GPU überhaupt benutzt“ ist eine billigere Frage als „warum sind diese Zahlen seltsam“ — und man kann sie automatisch stellen.

Nichts davon ist klug. Alles davon ist der Unterschied zwischen sechs Nächten Daten und sechs Nächten 84-Byte-Dateien, die wie Erfolg aussahen.