357 Sekunden pro Push, und die Tests waren nicht schuld

Vor jedem git push läuft bei uns ein Gate: ein Lefthook-Hook, der genau die Prüfungen startet, die danach ohnehin in der CI laufen. Die Idee ist simpel. Ein roter Pipeline-Lauf, von dem man zwölf Minuten später per Mail erfährt, kostet mehr Zeit als eine Minute Warten auf dem eigenen Rechner.

Zuletzt brauchte dieses Gate 357 Sekunden. Fast sechs Minuten, bei jedem Push, auch wenn nur eine Zeile in einer Markdown-Datei korrigiert war.

Am 25. August wurde es zweimal hintereinander mit --no-verify umgangen. Das war das eigentliche Problem. Ein roter Lauf ärgert; ein Gate, das man sich angewöhnt zu umgehen, sichert gar nichts mehr ab.

Erst messen

Verdächtig war zuerst die Testsuite selbst, bei uns die Contract-Suite unter tests/ci, die für jede Änderung prüft, ob Deployment-Konfiguration, CI-Definition und Infrastrukturvorlagen noch zueinander passen. Dann das Container-Setup: Die Suite läuft in python:3.12-alpine und installiert dort bei jedem Lauf ihre Abhängigkeiten. Ein vorgebautes Image stand als Massnahme auf dem Plan, dazu drei weitere Ideen.

Wir haben sie gemessen, bevor wir sie umgesetzt haben. Instrumentierung im Gate, Phasenmarker im Container, ein Bericht pro Lauf.

Das vorgebaute Image war nach einem einzigen Lauf erledigt: apk und pip brauchten zusammen 4,0 Sekunden. Dafür ein Image bauen, in die Registry schieben und aktuell halten: Der Aufwand wäre grösser als der Gewinn. Parallelisierung fiel aus einem ähnlichen Grund weg. Die meisten Pushes starten ohnehin nur eine einzige Aufgabe, da lässt sich nichts überlappen.

Was am Ende gewirkt hat, stand auf keiner der vier Positionen des Plans.

Nicht die Tests, das Lesen

Die Phasenmarker zeigten etwas, das keine der geplanten Massnahmen getroffen hätte. Die Suite selbst, 1099 Tests über rund 70 Module, war schnell. Langsam war das Lesen der Dateien.

Dieselbe Suite, dasselbe Image, derselbe Rechner:

Im Profil gab es keinen Hotspot: kein einzelnes Modul, keine langsame Abfrage, keine Endlosschleife, sondern ein flacher Ausläufer über alle 70 Module, System-CPU-Zeit ungefähr so hoch wie User-CPU-Zeit. Das ist die Signatur von Syscall-Latenz pro Datei und damit der Worst Case von virtiofs unter Docker Desktop für macOS.

Die Konsequenz war unbequem, aber klar: Wenn Lesen über den Mount teuer ist, darf der Container nicht über den Mount lesen.

Statt Mount: tar über stdin

Das Repository wird nicht mehr gemountet, sondern in den Container gestreamt. git ls-files erzeugt die Dateiliste, tar packt sie, docker run -i nimmt den Stream entgegen und entpackt ihn im Dateisystem des Containers.

git ls-files und ausdrücklich nicht git archive HEAD: Das Gate wird auch von Hand gegen einen schmutzigen Arbeitsbaum aufgerufen. Ein Gate, das dann still den committeten Stand prüft, während man auf uncommittete Änderungen schaut, ist genau der Fall, gegen den es existiert.

Drei Flags an diesem tar sind tragend, und jedes davon hat uns einen fehlgeschlagenen Lauf gekostet:

Ergebnis: 357 Sekunden auf 61 Sekunden. Gleiche Suite, gleicher Umfang, kein übersprungener Test.

Die restlichen 61 Sekunden

Bei 61 Sekunden verschiebt sich die Frage. Wir haben deshalb pro Änderungsform einmal sauber gemessen:

Interessant ist die erste Zeile. Wer eine Zeile in einer Client-Website ändert, wartet 1,1 Sekunden auf die Tests dieser Website und 60,2 Sekunden auf eine Contract-Suite, die von dieser Änderung nichts wissen kann.

Naheliegend wäre eine Pfadzuordnung: Contract-Suite nur starten, wenn bestimmte Verzeichnisse betroffen sind. Genau die hatten wir, und wir haben sie am 26. August gelöscht, weil sie still übersprungen hat. Ein Gate, das im Erfolgsfall schweigt, meldet auch nicht, wenn es gar nichts geprüft hat.

Der Cache meldet sich

Übrig blieb der häufigste Alltagsfall: derselbe Baum, zweimal geprüft. Ein Push nach einem Rebase ohne inhaltliche Änderung, ein zweiter Versuch nach einem abgelehnten Push, ein git push direkt nach dem letzten Lauf.

Das Gate bildet dafür einen Fingerabdruck des Arbeitsbaums: HEAD, Index, Status und die Hashes der schmutzigen Pfade. Das kostet 0,578 Sekunden. Ist der Fingerabdruck bekannt und lief die Suite damit grün durch, wird sie übersprungen: 1,3 Sekunden statt 63,2.

Vier Regeln begrenzen den Cache:

• Cachefähig sind nur hermetische Suiten. Alles, dessen Ergebnis von etwas ausserhalb des Baums abhängt, läuft jedes Mal.
• Eingetragen werden nur bestandene Läufe. Ein Fehlschlag sagt nichts über den Baum aus.
• Einträge verfallen nach sieben Tagen. Der Baum ist nicht die ganze Eingabe: Basis-Image und Toolchain ändern sich, ohne dass eine Datei sich ändert.
• Es gibt einen Ausschalter. GATE_NO_CACHE=1 erzwingt den echten Lauf; wer misst, braucht ihn.

Das Wichtigste steht in keiner dieser Regeln: Ein Treffer schreibt eine Zeile. Sie sagt, dass hier nichts gelaufen ist und wie viel Zeit das gespart hat.

Der Bericht musste aus demselben Grund nachziehen. Ein Cache-Treffer erschien dort zuerst als gewöhnlicher Lauf von 1,3 Sekunden. Die Zahl stimmt und behauptet trotzdem etwas Falsches. Heute führt der Bericht Treffer in einer eigenen Spalte, mit einer Fussnote, dass diese Zeile misst, wie lange das Überspringen gedauert hat, und nicht die Suite.

Nebenbei: eine Schwelle, die nie geprüft wurde

Beim Instrumentieren fiel etwas auf, das mit Geschwindigkeit nichts zu tun hat. Eine Coverage-Konfiguration setzte fail_under = 100, der abschliessende Bericht lief aber ohne die passende Umgebungsvariable. Die Schwelle stand also da und wurde nie geprüft. Seit wann, lässt sich nicht mehr feststellen.

Kaum war sie aktiv, fiel das Gate, und zwar auf einem tatsächlich ungedeckten Zweig: der Warnung, dass ein Runner mehr Kerne meldet, als er durchsetzt. Keine Schikane einer frisch scharf gestellten Regel also, sondern eine echte Lücke, die eine kaputte Konfiguration verdeckt hatte. Ein Fixture-Test später: 1099 → 1100 Tests, 99 % → 100 %.

Fazit

Drei Punkte gelten über dieses eine Gate hinaus:

• Erst messen, auch wenn der Plan schon steht. Von vier geplanten Massnahmen war eine nach einem Lauf tot, eine zweite offensichtlich unrentabel, und was tatsächlich gewirkt hat, stand auf keiner Position.
• Ein flaches Profil zeigt aus dem Code heraus. Sticht keine Stelle heraus und zieht die System-CPU-Zeit mit, ist der Weg zu den Daten das Problem und nicht die Arbeit an ihnen.
• Geschwindigkeit darf nicht aus Schweigen entstehen. Jede gesparte Sekunde muss von etwas kommen, das man benennen kann: gestreamt statt gemountet, gecacht und gemeldet.

Bleibt die ehrliche Randnotiz: Das ist ein macOS-Problem. Unter Linux liest ein Bind-Mount ohne diese Strafe, und der Umbau hätte dort nie stattgefunden. Nur läuft die Entwicklung hier eben auf Macs, und ein Gate, das man umgeht, schützt niemanden, egal wie gut der technische Grund für seine Langsamkeit ist.