Nützliche JVM Flags – Teil 2

Im zweiten Teil dieser Serie beschäftigen wir uns mit den verschiedenen Kategorien von JVM Flags. Außerdem lernen wir unsere ersten „geheimen“ XX-Flags kennen.

Kategorien und Syntax von JVM Flags

Die HotSpot JVM bietet Flags in drei Kategorien an. Die erste Kategorie sind die sogenannten Standard-Flags. Wie der Name schon andeutet, sind Funktionsweise und Ausgaben eines Standard-Flags stabil, und das Flag wird auch in zukünftigen Releases der JVM genau so unterstützt werden. Eine Liste der Standard-Flags liefert java, wenn man es ohne Parameter (oder aber mit dem Parameter -help, der selbst bereits ein solches Standard-Flag ist) aufruft. Mehrere Standard-Flags, z.B. -server, haben wir im ersten Teil dieser Serie bereits kennengelernt.

Die zweite Kategorie sind die X-Flags, nicht-standardisierte Flags deren Verhalten oder Vorhandensein sich bei zukünftigen Releases ändern kann. Alle Flags dieser Kategorie beginnen mit „-X“ und können mit java -X aufgelistet werden. Zu beachten ist, dass java -X nicht unbedingt eine vollständige Liste dieser Flags liefert; so fehlt z.B. das Flag -Xcomp.

Die dritte – und mit Abstand größte – Kategorie bilden die XX-Flags, die ebenfalls nicht standardisiert sind. Gelistet werden können XX-Flags nicht, sie sind also gewissermaßen geheim (Update: XX-Flags können seit Kurzem doch gelistet werden! Siehe hierzu Teil 3 unserer Serie). Abgesehen davon besteht für den Praxiseinsatz aber keinerlei Notwendigkeit einer Unterscheidung zwischen X-Flags und XX-Flags. Das Verhalten der X-Flags ist ziemlich stabil, während viele der XX-Flags eher experimenteller Natur sind (und insbesondere von den JVM-Entwicklern selbst fürs Debugging der JVM-Implementierung verwendet werden). In der lesenswerten HotSpot-Dokumentation zu nicht-standardisierten Flags findet sich noch die Abgrenzung, dass die XX-Flags nicht leichtfertig verwendet werden sollten. Das trifft aber meiner Meinung nach auf die X-Flags (und die Standard-Flags) genauso zu. Unabhängig von der Kategorie ist es empfehlenswert, sich gut über die Funktionsweise eines Flags zu informieren bevor man es einsetzt.

Beachtenswert ist bei den XX-Flags noch die Syntax. Alle XX-Flags beginnen mit „-XX:“, aber wie es danach weitergeht entscheidet der Typ des Flags.

• Bei einem boolschen Flag folgt entweder „+“ oder „-“ und danach erst der eigentliche Name der zu setzenden JVM-Option. So aktiviert -XX:+ die Option , während -XX:- die Option deaktiviert.
• Bei einem Flag, das einen Wert wie z.B. String oder Integer entgegennimmt, folgt zunächst der Name des Flags, danach ein „=“ und schließlich der zu setzende Wert. So setzt -XX:= die Option auf den Wert .

Wenden wir uns nun einigen XX-Flags aus dem Umfeld des JIT-Compilers zu.

-XX:+PrintCompilation und -XX:+CITime

Es ist sehr aufschlussreich, während der Laufzeit einer Java-Anwendung zu beobachten wie aktiv der JIT-Compiler ist. Möglich wird dies mit dem Flag -XX:+PrintCompilation, welches eine einfache Ausgabe zur Kompilierung von Bytecode in Maschinencode aktiviert. Sehen wir uns ein Beispiel (mit gekürzter Ausgabe) für einen Lauf der Server-VM an:

1$ java -server -XX:+PrintCompilation Benchmark
2  1       java.lang.String::hashCode (64 bytes)
3  2       java.lang.AbstractStringBuilder::stringSizeOfInt (21 bytes)
4  3       java.lang.Integer::getChars (131 bytes)
5  4       java.lang.Object::<init> (1 bytes)
6---   n   java.lang.System::arraycopy (static)
7  5       java.util.HashMap::indexFor (6 bytes)
8  6       java.lang.Math::min (11 bytes)
9  7       java.lang.String::getChars (66 bytes)
10  8       java.lang.AbstractStringBuilder::append (60 bytes)
11  9       java.lang.String::<init> (72 bytes)
12 10       java.util.Arrays::copyOfRange (63 bytes)
13 11       java.lang.StringBuilder::append (8 bytes)
14 12       java.lang.AbstractStringBuilder::<init> (12 bytes)
15 13       java.lang.StringBuilder::toString (17 bytes)
16 14       java.lang.StringBuilder::<init> (18 bytes)
17 15       java.lang.StringBuilder::append (8 bytes)
18[...]
19 29       java.util.regex.Matcher::reset (83 bytes)

Die Ausgabe von -XX:+PrintCompilation liefert jedes Mal eine neue Zeile, wenn eine Methode kompiliert wird. In jeder Zeile werden zunächst eine laufende Nummer und anschließend Name und Größe der zu kompilierenden Methode ausgegeben. So wird in Zeile 1 die Methode hashCode der Klasse String in Maschinencode kompiliert. Je nach Art der Methode werden noch Zusatzinformationen in Form von Kürzeln geliefert. Beispielsweise werden native Methoden bei ihrem Aufruf lediglich mit einem „n“ und ohne laufende Nummer protokolliert, wie hier im Fall von System.arraycopy. Auch kann man gut erkennen, wann Methoden rekompiliert werden; siehe die Ausgaben zu StringBuilder.append in den Zeilen 11 und 15. Insgesamt endet die Nummerierung bei 29, d.h. es gab während der Laufzeit der Anwendung 29 Kompiliervorgänge.

Gut erkennen kann man an solchen Ausgaben übrigens den Unterschied zwischen dem Verhalten des JIT-Compilers bei der Client- und der Server-VM. In unserem Beispiel werden mit der Server-VM 29 Zeilen an Ausgaben geliefert, mit der Client-VM hingegen ganze 55 Zeilen (ohne Abbildung). Dies mag auf den ersten Blick verwunderlich erscheinen. Allerdings beobachtet die Server-VM standardmäßig Methoden über einen viel längeren Zeitraum als die Client-VM und trifft erst danach eine Entscheidung über deren Kompilierung, so dass diese ggf. erst zu einem späteren Zeitpunkt erfolgen.

Zusätzlich können wir durch das Setzen des Flags -XX:+CITime verschiedene Statistiken zur Kompilierung erzeugen, die bei Beendigung der JVM ausgegeben werden. Betrachten wir einen Auszug:

1$ java -server -XX:+CITime Benchmark
2[...]
3Accumulated compiler times (for compiled methods only)
4------------------------------------------------
5  Total compilation time   :  0.178 s
6    Standard compilation   :  0.129 s, Average : 0.004
7    On stack replacement   :  0.049 s, Average : 0.024
8[...]

Wir sehen, dass insgesamt 0,178 Sekunden (für die 29 Kompiliervorgänge) aufgewendet wurden. Davon beziehen sich 0,049 Sekunden auf On-Stack-Replacement, d.h. das Kompilieren einer Methode, die sich momentan auf dem Stack befindet. Diese Technik ist zwar nicht ganz einfach zu implementieren, aber sehr wichtig, denn ansonsten könnte man Methoden die gerade ausgeführt werden (und ggf. sehr lange Schleifen enthalten) nicht on-the-fly durch ihre kompilierten Gegenstücke ersetzen.

Tatsächlich liefert -XX:+CITime noch weitere Ausgaben, die wir aber hier überspringen. Aufschlussreich ist erneut der Vergleich zwischen der Client- und der Server-VM. Die Statistiken zur Client-VM (ohne Abbildung) sagen, dass zwar 55 Methoden kompiliert wurden, aber nur 0,021 Sekunden dafür aufgewendet wurden. Die Server-VM hat also insgesamt weniger oft kompiliert, dafür aber wesentlich mehr Zeit (für Optimierung) in die Kompilierung investiert als die Client-VM.

Im ersten Teil unserer Serie haben wir die Flags -Xint und -Xcomp kennengelernt, welche die JVM zu einem ausschließlichen Interpretieren bzw. zu einem sofortigen vollständigen Kompilieren sämtlichen Bytecodes zwingen. Mit -XX:+PrintCompilation und -XX:+CITime können wir uns nun ein genaueres Bild davon machen, wie sich der JIT-Compiler in beiden Fällen verhält. Bei Verwendung von -Xint liefert -XX:+PrintCompilation in beiden Fällen exakt 0 Zeilen an Ausgaben. Ebenso erfahren wir aus den Statistiken von -XX:+CITime wie erwartet, dass keinerlei Zeit auf Kompilierung verwendet wurde. Bei -Xcomp sieht das schon ganz anders aus. Die Client-VM liefert uns unmittelbar nach dem Start der Anwendung 726 Zeilen an Ausgaben (und danach keine weiteren mehr, denn es wurde ja bereits alles kompiliert). Mit der Server-VM sind es sogar 993 Zeilen an Ausgaben, was uns erneut die aggressivere Optimierung gegenüber der Client-VM verdeutlicht. Auch die Statistiken bei Beendigung der Anwendung sprechen eine klare Sprache; betrachten wir als Beispiel die Ausgaben der Server-VM:

1$ java -server -Xcomp -XX:+CITime Benchmark
2[...]
3Accumulated compiler times (for compiled methods only)
4------------------------------------------------
5  Total compilation time   :  1.567 s
6    Standard compilation   :  1.567 s, Average : 0.002
7    On stack replacement   :  0.000 s, Average : -1.#IO
8[...]

Es werden ganze 1,567 Sekunden mit Kompilierung verbracht. Das ist ungefähr zehn Mal so viel Zeit wie mit der Standard-Einstellung der JVM verwendet wird, im Ergebnis läuft die Anwendung aber trotzdem langsamer. Die Client-VM benötigt übrigens nur 0,208 Sekunden für ihre 726 Methoden, ist im Ergebnis aber noch langsamer als die Server-VM. Zu beachten ist im obigen Beispiel noch, dass kein On-Stack-Replacement stattfinden kann, da jede Methode sofort bei ihrem ersten Aufruf kompiliert wird. Die missglückte Ausgabe „Average: -1.#IO“ (korrekt wäre: 0) verdeutlicht uns, dass man bei nicht-standardisierten Flags nicht unbedingt saubere Ausgaben erwarten kann.

-XX:+UnlockExperimentalVMOptions

Bevor wir uns weiteren Flags zur Kompilierung zuwenden, machen wir einen kleinen Exkurs. Es kommt bisweilen vor, dass man ein bestimmtes XX-Flag setzt, die JVM sich aber unmittelbar nach ihrem Start selbst beendet und die Ausgabe „Unrecognized VM option“ liefert. In so einem Fall sollte man als erstes prüfen, ob man sich beim Namen des Flags vertippt hat. Ist der Name korrekt und die JVM erkennt das Flag trotzdem nicht, so kann es sein, dass das Flag erst durch das Setzen eines anderen Flags, -XX:+UnlockExperimentalVMOptions, freigeschaltet werden muss. Ich muss gestehen, so ganz ist mir der Sinn und Zweck dieses zusätzlichen Sicherungsmechanismus nicht klar. Offenbar erfordern einige XX-Flags höhere Vorsichtsmaßnahmen als andere, z.B. weil sie exzessiv Debug-Ausgaben in eine Datei schreiben.

Manchmal reicht übrigens selbst -XX:+UnlockExperimentalVMOptions nicht aus, um ein gewünschtes Flag zu aktivieren. In so einem Fall ist das Flag nur zum Debugging der JVM, nicht aber zur Verwendung im Betrieb vorgesehen. Um das Flag im Rahmen der Entwicklung dennoch nutzen zu können, kann man einen Debug-Build der JVM verwenden. Debug-Builds für die Java 6 HotSpot JVM gibt es hier.

-XX:+LogCompilation und -XX:+PrintOptoAssembly

Wem die Ausgaben von -XX:+PrintCompilation nicht genügen, der kann sich mit dem Flag -XX:+LogCompilation umfangreiche Ausgaben zur Kompilierung in die Datei „hotspot.log“ schreiben lassen. Neben vielen Details zu den kompilierten Methoden gibt -XX:+LogCompilation auch aus, wann welche Compiler-Threads für welche Tasks gestartet wurden. Zu beachten ist, dass -XX:+LogCompilation das Setzen von -XX:+UnlockExperimentalVMOptions voraussetzt.

Außerdem ermöglicht uns die JVM sogar, die Resultate der Kompilierung von Bytecode in Maschinencode zu sehen. Einen geeigneten Einstieg bietet hier das Flag -XX:+PrintOptoAssembly, welches bei jeder Kompilierung den resultierenden Maschinencode ausgibt (und zwar sowohl auf der Standardausgabe als auch in die Datei „hotspot.log“). Dieses Flag erfordert allerdings einen Debug-Build der JVM und die Verwendung der Server-VM. Anhand der Nutzung von -XX:+PrintOptoAssembly lässt sich schön herausfinden, welche Optimierungen die JVM tatsächlich durchführt, z.B. im Bereich der Dead-Code-Elimination. Um den Rahmen dieses Blogs nicht zu sprengen, verweise ich an dieser Stelle auf einen interessanten Erfahrungsbericht, der hier zu finden ist.

Weitere Informationen zu XX-Flags

Wer nun neugierig geworden ist und sich selbst einen Überblick über die XX-Flags der HotSpot JVM verschaffen möchte, dem empfehle ich das Studium (oder einfach nur ein schnelles Durchblättern) der folgenden beiden zwar nicht ganz vollständigen aber dennoch sehr beeindruckenden Listen: A Collection of JVM Options und The most complete list of -XX options for Java 6 JVM.