GraalVM Native Image: Wenn die Uhr des Build-Servers im Binary landet
GraalVM Native Image übersetzt Java-Anwendungen vorab in ein natives Binary. Der Start dauert dann Millisekunden statt Sekunden, der Speicherbedarf sinkt deutlich, und zur Laufzeit wird keine JVM mehr benötigt. Für Anwendungen, die auf jedem Knoten eines Kubernetes-Clusters mitlaufen, sind das gute Argumente. Im konkreten Beispielprojekt, in dem sich ein schwer zu findender Fehler eingeschlichen hatte, ging es genau um Kubernetes Infrastruktur: Ein eigener CSI-Treiber wird als DaemonSet betrieben und belegt so Ressourcen auf jeder einzelnen Node.
Damit diese Optimierungen funktionieren, verschiebt Native Image Arbeit vom Programmstart in den Build.
Dazu gehört die Klasseninitialisierung:
Statische Initializer werden nicht zwangsläufig beim Start ausgeführt, sondern können bereits beim Bau des Binaries laufen.
Deren Ergebnis wandert als fertiges Objektnetz in den sogenannten Image Heap.
Keine Initialisierung mehr zur Laufzeit, keine Arbeit für einen Just in Time Compiler.
Das ist zum einen der Hebel für den Geschwindigkeitsgewinn aber gleichzeitig eine Fehlerquelle, die in der klassischen JVM-Welt so nicht existiert.
Was ein statischer Initializer ableitet und ermittelt, wird einmalig zum Buildzeitpunt auf der Buildmaschine ausgeführt.
Ein Zeitstempel, der nicht altert
Die Anwendung, um die es hier geht, ist ein CSI-Treiber für Kubernetes. Sie spricht gRPC über einen Unix-Domain-Socket. gRPC-Java setzt intern auf Netty auf.
Netty liefert eine Konfigurationsdatei für Native Image mit, die das gesamte Paket io.netty für die Initialisierung zur Buildzeit vormerkt.
Das ist so gewollt und in den allermeisten Fällen unproblematisch.
In diesem Paket liegt jedoch auch eine unscheinbare Klasse, die die Zeitbasis für sämtliche geplanten Aufgaben von Netty bereitstellt:
private static final long START_TIME;
static {
START_TIME = System.nanoTime();
}System.nanoTime() liefert keine Uhrzeit, sondern einen monotonen Zähler, der unter Linux seit dem Systemstart läuft.
Er dient dazu, Zeitdifferenzen zu ermitteln.
Wird dieser Wert zur Buildzeit ermittelt, dann steht im Binary die Betriebszeit des Build-Servers zum Zeitpunkt des Builds.
Jede geplante Aufgabe von Netty berechnet ihre Fälligkeit auf dieser Basis.
Läuft das Binary später auf einem Rechner, dessen Uptime kleiner ist, als die des Build-Servers, also auf jedem frisch gestarteten Node, dann wird die Differenz negativ.
In der Folge kippt die Fristberechnung in einen Überlauf und liefert für jede Aufgabe eine Wartezeit von null.
Der Effekt: Sämtliche Timer feuern sofort und dauerhaft.
Geisterbug
Der Fehler zeigte sich nicht als Zeitproblem, sondern als sehr merkwürdiges Netzwerkverhalten:
-
Der Keepalive-Ping des gRPC-Servers, laut Voreinstellung alle zwei Stunden einmal fällig, lief in einer Endlosschleife.
-
Jeder RPC, der eine Deadline mitbrachte, wurde in dem Moment abgebrochen, in dem er ankam. Aufrufe ohne Deadline wurden dagegen in zwei Millisekunden korrekt beantwortet.
-
Die Anwendung selbst protokollierte einen erfolgreichen Start und lief weiter, ohne Absturz und ohne Neustart.
In Kubernetes sah das so aus, dass die Sidecar-Container neben dem Treiber in einen CrashLoop gingen und the connection is draining meldeten, während der Treiber-Container als gesund galt.
Ein Fehlerbild, das zunächst in alle möglichen Richtung zeigt. Außer der richtigen.
Zufallsfund
Der eigentlich beunruhigende Teil ist, wie der Fehler auffiel.
Aus demselben Commit, mit derselben Toolchain, entstanden nacheinander zwei Binaries. Das eine funktionierte, das andere nicht. Der Unterschied lag nicht im Quelltext, sondern allein darin, wann gebaut wurde: Das funktionierende Binary entstand etwa eine Stunde nach einem Neustart des Build-Rechners, das defekte rund fünfzehn Stunden danach.
Damit war das Verhalten weder reproduzierbar noch erklärbar, solange im Quelltext gesucht wurde. Und die Suche begann selbstverständlich auf Basis des Quelltextes. Inklusive bit-bisect, wodurch das Verhalten noch unerklärlicher wurde.
Noch schlimmer: Sämtliche Tests liefen durch.
Die CSI-Konformitätssuite gegen das native Binary war grün, ebenso ein Upload-Smoketest und ein Test der Weboberfläche.
Auch die End-to-End-Tests, die einen echten Kubernetes-Cluster in Containern starten und die Anwendung dort als DaemonSet ausrollen, meldeten Erfolg.
Der Grund dafür ist, wie so oft, erst im Nachhinein offensichtlich: Alle diese Prüfungen laufen auf der Maschine, die das Binary gebaut hat. Dort liegt der eingefrorene Zeitstempel zuverlässig in der Vergangenheit, und die Rechnung geht auf. Der Fehler tritt ausschließlich auf einem Rechner auf, der später gestartet wurde, als der Build-Server. Also mit hoher Wahrscheinlichkeit auf vielen realen Cluster-Nodes, aber in keiner der benutzten Testumgebungen.
Aufgefallen ist das letzlich nur, weil zufällig in einer frisch erzeugten virtuellen Maschine getestet wurde.
Fehler kommen selten allein
Die Ursache war schnell behoben, indem die betreffende Klasse explizit von der Buildzeit-Initialisierung ausgenommen wurde:
<buildArg>--initialize-at-run-time=io.netty.util.concurrent.SystemTicker</buildArg>Interessanter als die eine Zeile ist die Frage, was sonst noch im Image Heap steckt. Eine systematische Durchsicht aller zur Buildzeit initialisierten Klassen förderte einen zweiten Fall zutage: Auch die Anzahl der verfügbaren Prozessorkerne wird von Netty in einem statischen Feld zwischengespeichert, und die Speicherverwaltung dimensioniert sich daraus.
Ein auf einer Maschine mit zwölf Kernen gebautes Binary legte auf einem Node mit zwei Kernen unverändert vierundzwanzig Speicherarenen an. Das ist kein Korrektheitsproblem, aber ein unnötiger Ressourcenverbrauch, und gerade bei einem DaemonSet mit knappem Memory-Limit durchaus relevant. Nach einem analogen Fix folgt die Netty Speicher-Dimensionierung wieder der tatsächlichen Umgebung.
Zur selben Kategorie gehören unter anderem MAC-Adresse und Prozess-ID, Umgebungsvariablen und System-Properties, temporäre Verzeichnisse sowie Startwerte von Zufallszahlengeneratoren. Alles Werte, die eine Anwendung sinnvollerweise beim Start ermittelt, und die im Native Image ohne weiteres Zutun im Build landen können.
Lessons Learned
Buildzeit-Initialisierung ist eine Verhaltensänderung.
Ein statischer Initializer, der auf der JVM jahrelang korrekt war, kann im Native Image etwas völlig anderes bedeuten.
Das gilt besonders für Bibliotheken, deren Quelltext man nie gelesen hat.
Die riskanten Werte sind die, die eine Umgebung beschreiben.
Uhrzeit, Betriebszeit, Kernanzahl, Speichergrenzen, Hostname, Prozess-ID, Random-Seed.
Die Konfiguration der Abhängigkeiten ist Teil der eigenen Konfiguration.
Bibliotheken bringen eigene native-image.properties mit und melden dort teilweise ganze Paketbäume für die Buildzeit an.
Das ist praktisch, aber es ist eine Entscheidung, die übernommen und nicht selbst und bewusst getroffen wurde.
Ein grüner Testlauf auf dem Build-Rechner sagt hier wenig aus.
Wenn der Fehler darin besteht, dass die Buildmaschine im Binary steckt, dann ist die Buildmaschine der einzige Ort, an dem er sich nicht zeigt.
Unterschiede zwischen zwei Builds sind ein Symptom, kein Rauschen.
Zwei Binaries aus demselben Commit, die sich unterschiedlich verhalten, sind ein starker Hinweis auf genau diese Fehlerklasse.
Die naheliegende Reaktion, einfach noch einmal zu bauen, führt dabei nicht zum Ziel.
Fehler finden
Folgen Ansätze können helfen, diese Art von Fehlern zu finden.
Report der Klasseninitialisierung auswerten.
Mit -H:+PrintClassInitialization erzeugt Native Image eine Liste aller Klassen samt Angabe, ob sie zur Bau- oder zur Laufzeit initialisiert werden und warum.
Diese Liste lässt sich auf die eigenen Abhängigkeiten eingrenzen und automatisiert oder maschinell nach den kritischen Aufrufen in statischen Initializern durchsuchen.
Im geschilderten Fall blieben von rund neuntausend Klassen siebenundzwanzig zur genaueren Betrachtung übrig.
Auf einer anderen Maschine testen als der, die gebaut hat.
Und zwar auf einer, die nach dem Build gestartet wurde.
Eine frisch erzeugte VM oder ein frisch gestarteter Cluster-Node genügt.
Testcontainer auf dem Build-Rechner reichen ausdrücklich nicht, da sie sich mit dem Container dessen Uhr und Kerne teilen.
Umgebungen bewusst variieren.
Weniger CPU-Kerne, engere Memory-Limits, andere Kernel-Version.
Werte, die sich bei solchen Variationen nicht ändern, obwohl sie sollten, sind verdächtig.
Ein Test mit taskset auf zwei Kernen war im geschilderten Fall aussagekräftiger als die komplette End-to-End-Suite.
Konfigurationsentscheidungen im Build absichern.
Ein einmal gefundenes --initialize-at-run-time sollte nicht stillschweigend wieder verschwinden können.
Ein kleiner Test, der die Buildkonfiguration prüft, ist ein guter Schutz gegen Regressionen.
Zu den Themen Java, Kubernetes und Cloudarchitektur bieten wir sowohl Beratung, Entwicklungsunterstützung als auch passende Schulungen an:
Auch für Ihren individuellen Bedarf können wir Workshops und Schulungen anbieten. Sprechen Sie uns gerne an.