Quarkus Native Image mit VisualVM beobachten
Kategorie Software Engineering | 2 Kommentare »
Eigentlich wollte ich schon vor 2 Wochen darüber schreiben, wie man sich mit VisualVM zu einem Quarkus Native Image während der Laufzeit verbindet. Da ich aber zunächst erläutern wollte, was ein JVM Native Image überhaupt ist, wurde der Post immer länger und ich habe den Inhalt lieber auf 2 Posts aufgeteilt. Heute also der 2. Teil mit konkreter Anleitung, wie man sich während der Laufzeit zu einem JVM Native Image zum Beispiel mit VisualVM verbindet.
JVM Laufzeit Überwachung
Während der Laufzeit einer JVM Anwendung passiert neben der Ausführung der eigentlich Geschäftslogik noch viel mehr, etwa:
- Garbage Collection
- Laden von Bytecode in Form von Klassendateien
- Kompilierung von Bytecode
- Optimierung des kompilierten Bytecodes
Die JVM stellt verschiedene Schnittstellen bereit, um sie bei der Ausführung zu überwachen. Man kann auch Speicherabbilder („Memory Dump“) ziehen oder ein Profiling durchführen, um zum Beispiel Speicherlecks zu finden oder Performance Analysen durchzuführen.
Bei der Ausführung einer nativen JVM Anwendung hingegen kümmert sich die JVM primär nur noch um die Speicherverwaltung, denn die Anwendung liegt bereits als nativer Code vor, der während der Ausführung nicht weiter optimiert wird.
VisualVM
Ein beliebtes Werkzeug für die JVM Überwachung ist VisualVM. VisualVM kann ich mittels SDKMAN folgendermaßen installieren:
sdk install visualvmNach dem Start sieht man in der linken Seitenleiste alle auf dem System laufenden JVMs. Dort sollte zumindest die JVM von VisualVM selbst auftauchen, denn natürlich ist VisualVM auch eine JVM Anwendung.
Quarkus Native Image
Als Versuchsobjekt habe ich einen kleinen Quarkus REST Service geschrieben. Um diesen zu kompilieren und auszuführen, benötigt man ein JDK der GraalVM Community Edition, die man folgendermaßen per SDKMAN installieren kann:
sdk install java 21.0.2-graalceDen Quellcode kompiliert man mittels:
./mvnw verify -DnativeAnschließend kann man den Service folgendermaßen starten:
./target/quarkus-native-startup-*-runnerHat man VisualVM noch geöffnet, taucht der Service direkt in der Seitenleiste als „io.quarkus.runner.GeneratedMain“ auf und man kann ihn per Doppelklick als Tab öffnen.
Vergleicht der geneigte Leser den Quarkus Service mit der JVM von VisualVM, dann wird er feststellen, dass weniger Überwachungswerkzeuge zur Verfügung stehen. Zum jetzigen Zeitpunkt funktionieren eigentlich nur die Graphen zur Überwachung des Speichermanagements und der CPU Nutzung. Auch einen Heap Dump kann man ziehen. Alle anderen Werkzeuge wie Profiler stehen hingegen momentan noch nicht zur Verfügung.
Damit ich mich überhaupt auf die Quarkus JVM verbinden kann, musste ich Quarkus mitteilen, dass es die notwendigen Schnittstellen in das native Image mit übernimmt. Standardmäßig tut Quarkus dies nicht, um die Größe des nativen Image zu minimieren. Der Unterschied in der Image Größe beträgt rund 9MB (59MB ohne vs. 68MB mit).
Die einzige notwendige Änderung ist, in der „src/main/resources/application.properties“ Datei von Quarkus die folgende Zeile hinzufügen:
quarkus.native.monitoring=allDank dieser Zeile kann VisualVM mittels „jvmstat“ die Quarkus JVM überwachen. Auch eine Verbindung via JMX ist prinzipiell möglich, bietet aber momentan keinen Vorteil, da VisualVM keine weiteren Werkzeuge für native Images unterstützt. Um JMX zur Verfügung zu stellen, muss man das native Image mit einigen zusätzlichen Parametern starten:
./target/quarkus-native-startup-*-runner \
-Dcom.sun.management.jmxremote \
-Dcom.sun.management.jmxremote.port=1099 \
-Dcom.sun.management.jmxremote.rmi.port=1099 \
-Dcom.sun.management.jmxremote.ssl=false \
-Dcom.sun.management.jmxremote.authenticate=false \
-Djava.rmi.server.hostname=127.0.0.1Last mittels wrk erzeugen
Der Quarkus Service bietet einen REST Endpunkt, den man folgendermaßen abfragen kann:
curl -X POST --location "http://localhost:8080/are-you-ready" \
-H "Content-Type: application/json" \
-d '{
"activity": "partying"
}'Als Antwort sollte man „Let’s get started with partying!“ erhalten. Im GitHub Repo gibt es ein kleines Lua Skript für das Benchmark Werkzeug wrk. Hat man wrk installiert, kann man einen Benchmark Lauf mit folgendem Befehl starten:
wrk -t26 -c600 -d25s http://localhost:8080/api/activities -s wrk.lua
Running 25s test @ http://localhost:8080/api/activities
26 threads and 600 connections
Thread Stats Avg Stdev Max +/- Stdev
Latency 1.59ms 2.80ms 48.51ms 90.97%
Req/Sec 29.28k 3.57k 77.31k 70.28%
18973322 requests in 25.10s, 2.46GB read
Non-2xx or 3xx responses: 18973322
Requests/sec: 755994.00
Transfer/sec: 100.22MBAuf meinem Rechner mit 16 physischen Cores und 96GB Speicher kommen in 25 Sekunden knapp 19 Millionen Request zusammen. Dabei sendet wrk bis zu 600 Requests gleichzeitig unter Nutzung von 26 Threads.
In VisualVM kann man den tatsächlich verwendeten Speicher für den JVM Heap beobachten. Man sieht, dass der Speicher immer wieder durch Garbage Collection Läufe aufgeräumt wird.
Trotz dieser enormen Last verbraucht der Quarkus Service selbst in der Spitze nicht mehr als 256MB. Das ist absolut erstaunlich!
Ernüchterung stellt sich auf den ersten Blick ein, wenn man den Service als klassische Bytecode Anwendung kompiliert und ausführt. Der Speicherverbrauch während des Lasttests steigt zwar auf fast 2GB, aber dafür schafft mein Rechner statt 18 fast 30 Millionen Requests in den 25 Sekunden.
Der primäre Grund: Die klassische JVM kann den kompilierten Code auf mein einziges Nutzungsmuster optimieren, da mein Service hochgradig unrealistisch ist. Hat man also tatsächlich eine so extrem hohe Last mit sehr gleichbleibenden Nutzungsmustern, dann sollte man auch weiterhin eine klassische JVM Anwendung bevorzugen!
Da VisualVM wenig Information zum Garbage Collection Verhalten liefert, kann man sich grundlegende Infos auf der Kommandozeile ausgeben lassen, indem man den Service mit folgenden Flags startet:
/target/quarkus-native-startup-*-runner -verbose:gc -XX:+PrintGC
...
[27.758s] GC(597) Full GC (Collect on allocation) 182.50M->13.00M 10.047ms
[27.794s] GC(598) Incremental GC (Collect on allocation) 175.50M->13.00M 1.268ms
[27.830s] GC(599) Incremental GC (Collect on allocation) 172.50M->13.00M 1.309ms
[27.866s] GC(600) Incremental GC (Collect on allocation) 169.50M->13.00M 1.302ms
[27.900s] GC(601) Incremental GC (Collect on allocation) 166.50M->13.00M 1.351ms
[27.937s] GC(602) Incremental GC (Collect on allocation) 177.50M->13.00M 1.332ms
[27.976s] GC(603) Incremental GC (Collect on allocation) 189.00M->13.50M 1.421ms
[28.020s] GC(604) Incremental GC (Collect on allocation) 204.00M->13.50M 1.957ms
[28.061s] GC(605) Incremental GC (Collect on allocation) 198.50M->13.50M 1.291ms
[28.102s] GC(606) Incremental GC (Collect on allocation) 195.00M->13.50M 0.891ms
[28.142s] GC(607) Incremental GC (Collect on allocation) 191.50M->13.50M 1.212ms
[28.180s] GC(608) Incremental GC (Collect on allocation) 188.00M->13.50M 1.289ms
[28.219s] GC(609) Incremental GC (Collect on allocation) 184.50M->13.50M 1.318msMan sieht, dass ca. zweimal pro Sekunde ein vollständiger Garbage Collection Lauf erfolgt und dazwischen mehrere inkrementelle. Viel mehr kann man daraus aber auch nicht raus lesen.
Es wird noch einige Zeit dauern, bis man native Images vollständig während der Laufzeit überwachen kann. Doch schon heute ist das Erzeugen eines Heap Dumps und die grafische Darstellung des Speicherverbrauchs hilfreich, um eine Idee zu bekommen, was in einem nativen JVM Image während der Laufzeit so vorgeht.
Hach, so eine altbackene Swing-Desktop-App, da wird mir doch ganz nostalgisch ums Herz
Der Kelch von Java Desktop Anwendungen ist glücklicherweise mehr oder weniger komplett an mir vorbei gegangen :-)