Nützliche JVM Flags – Teil 8 (GC Logging)

Im letzten Teil dieser Serie beschäftigen wir uns mit dem Thema Garbage Collection Logging und den dazugehörigen Flags. Das GC Log ist eines der wichtigsten Mittel, das uns zur Verfügung steht, um mögliche Schwachstellen in der Heap- und GC-Konfiguration oder dem Speicherverhalten der Anwendung aufzudecken. Im GC Log stehen exakte Daten zu GC-Ergebnissen und -Dauer, die bei jedem GC-Vorgang geschrieben werden.

-XX:+PrintGC

Mit dem Flag -XX:+PrintGC (oder dem Alias -verbose:gc) lässt sich ein sehr einfaches GC Logging aktivieren, das für jede Young Generation GC und jede Full GC eine Zeile schreibt. Hier eine Beispielausgabe:
[GC 246656K->243120K(376320K), 0,0929090 secs] [Full GC 243120K->241951K(629760K), 1,5589690 secs]

Die Zeile beginnt (rot markiert) mit dem GC-Typ, entweder „GC“ oder „Full GC“. Danach folgt (blau markiert) die Angabe des belegten Heap-Speichers vor bzw. nach der GC (getrennt durch einen Pfeil) sowie die aktuell reservierte Heap-Größe (in Klammern). Abschließend wird noch die Dauer der GC (Echtzeit in Sekunden) angegeben.

In der ersten Zeile bedeutet also 246656K->243120K(376320K), dass vor der GC 246656K und nach der GC 243120K Heap-Speicher belegt waren. Die Gesamtgröße des Heap zum Zeitpunkt der GC betrug 376320K. Außerdem hat die GC 0,0929090 Sekunden gedauert.

Das einfache GC Logging hat ein Format, das unabhängig vom verwendeten GC-Algorithmus ist und uns daher keine weiteren Details liefern kann. So können wir in obigem Beispiel nicht einmal erkennen, ob Objekte von der Young in die Old Generation verschoben wurden. Für die Praxis nützlicher ist deshalb das detaillierte GC Logging.

-XX:+PrintGCDetails

Wenn wir anstelle von -XX:+PrintGC das Flag -XX:+PrintGCDetails verwenden, aktivieren wir das detaillierte GC Logging. Das Format unterscheidet sich je nach verwendetem GC-Algorithmus. Betrachten wir zum Auftakt ein Beispiel für eine Young Generation GC bei Verwendung des Throughput Collector. Zum besseren Verständnis habe ich die Ausgabe in mehrere Zeilen umgebrochen und eingerückt; im GC Log handelt es sich um eine einzige Zeile, die für Menschen weniger leicht zu lesen ist.
[GC [PSYoungGen: 142816K->10752K(142848K)] 246648K->243136K(375296K), 0,0935090 secs ] [Times: user=0,55 sys=0,10, real=0,09 secs]

Wir erkennen bereits bekannte Elemente aus dem einfachen GC Log wieder: Es handelt sich um eine Young Generation GC (rot), welche 0,0935090 Sekunden gedauert hat und den belegten Heap-Speicher von 246648K auf 243136K (blau) reduziert hat. Zusätzlich erhalten wir Informationen zur Young Generation, nämlich den verwendeten Kollektor (orange) sowie ihre Kapazität und Füllstand (grün). Im Beispiel konnte der „PSYoungGen“-Kollektor den belegten Heap-Speicher in der Young Generation von 142816K auf 10752K reduzieren.

An der Kapazitätsangabe der Young Generation kann man gut erkennen, dass die GC ausgelöst wurde weil die Young Generation eine anstehende Objektallokation ansonsten nicht hätte durchführen können (142816K der verfügbaren 142848K waren bereits belegt). Ebenfalls sehen wir, dass die meisten Objekte von Young nach Old verschoben wurden, denn ein Vergleich der grünen und blauen Angaben zeigt, dass die Young Generation fast komplett geleert wurde, die Belegung des Gesamtheap sich aber kaum verändert hat.

Im „Times“-Abschnitt liefert uns das Log noch Angaben zur verwendeten CPU-Zeit im User Space („user“) bzw. Kernel Space („sys“) des Betriebssystems sowie zur tatsächlich verstrichenen Zeit („real“), jeweils bezogen auf die gesamte GC. Der Wert bei „real“ ist mit 0,09 eine gerundete Version der bereits weiter oben angegebenen 0,0935090 Sekunden. Wenn die verbrauchte CPU-Zeit wesentlich höher ist als die tatsächlich verstrichene Zeit, ist das ein Indikator dafür, dass die GC mit mehreren Threads durchgeführt wurde. Die CPU-Zeit ergibt sich dann aus der Summe der CPU-Zeiten aller GC-Threads. Tatsächlich wurden im vorliegenden Beispiel acht GC-Threads verwendet.

Betrachten wir nun die Ausgaben zu einer Full GC.
[Full GC [PSYoungGen: 10752K->9707K(142848K)] [ParOldGen: 232384K->232244K(485888K)] 243136K->241951K(628736K) [PSPermGen: 3162K->3161K(21504K)], 1,5265450 secs ] [Times: user=10,96 sys=0,06, real=1,53 secs]

Im Vergleich zu den Young Generation GCs erhalten wir hier (im bekannten Format) weitere Details zur Old Generation und Permanent Generation. Wir sehen für alle drei Generationen, welcher Kollektor verwendet wurde, wie ihr Füllstand vor und nach der GC und wie ihre aktuelle Kapazität ist. Die Angaben zur Young und Old Generation ergeben jeweils in Summe die Werte, die für den Gesamtheap (blau) gelistet werden. Zum Beispiel sind aktuell 241951K des Heap belegt, wovon 9707K auf die Young Generation und 232244K auf die Old Generation entfallen. Die Full GC hat ca. 1,53 Sekunden gedauert, und die verbrauchte CPU-Zeit von 10,96 Sekunden im User Space zeigt, dass hier ebenfalls mehrere GC-Threads (es waren erneut acht) verwendet wurden.

Die Angaben zu den einzelnen Generationen erlauben uns, Rückschlüsse über den Auslöser der GC zu ziehen. Hat eine der drei Generationen ihre Kapazitätsgrenze erreicht, so hat dies mit Sicherheit die GC ausgelöst. Im obigen Beispiel ist jedoch keine der drei Generationen an ihre Kapazitätsgrenze gestoßen. Das kann beim Throughput Collector passieren, wenn die GC Ergonomics (siehe Teil 6  dieser Serie) anhand interner Messungen entscheiden, dass schon vorher eine GC durchgeführt werden sollte.

Ein weiterer möglicher Auslöser für eine Full GC ist, wenn sie explizit von der Anwendung (oder über eine der externen JVM-Schnittstellen) angefordert wurde. Solche sogenannten „System GCs“ kann man im GC Log ebenfalls eindeutig identifizieren. Bei System GCs beginnt die Zeile mit „Full GC (System)“ anstelle von „Full GC“.

Für den Serial Collector ist das detaillierte GC Log sehr ähnlich zu dem des Throughput Collector. Der einzige nennenswerte Unterschied ist, dass die einzelnen Bereiche andere Namen haben, da andere GC-Algorithmen verwendet werden (z.B. „Tenured“ anstelle von „ParOldGen“). Das ist hilfreich, denn anhand dieser eindeutigen Namen kann man allein aus dem GC Log erkennen, welcher Garbage Collector verwendet wurde.

Für den CMS Collector ist das GC Log für Young Generation GCs ebenfalls sehr ähnlich zu dem des Throughput Collector, erneut mit anderer Namensgebung. Für die nebenläufigen Old Generation GCs unterscheiden sich die Ausgaben jedoch sehr von denen der anderen Kollektoren, weil sie Einträge zu den verschiedenen Phasen des CMS Collector enthalten. Außerdem können die Ausgaben des CMS Collector aufgrund der nebenläufigen Ausführung mit den Ausgaben von Young Generation GCs verzahnt sein. Mit der Kenntnis der anderen Formate ist es aber nicht schwierig, die Ausgaben zu den einzelnen Phasen zu verstehen. Bei der Interpretation von Zeiten sollte man allerdings im Kopf haben, dass die meisten Phasen des Kollektors nebenläufig sind. Lange Zeitspannen für einzelne Phasen oder die gesamte GC deuten deshalb – im Gegensatz zu den Stop-the-World-Kollektoren – nicht unbedingt auf ein Problem hin.

Wie wir aus Teil 7 dieser Serie wissen, findet auch bei Verwendung des CMS Collector eine Full GC statt, wenn ein nebenläufiger GC-Zyklus nicht schnell genug beendet wird. In diesem Fall tauchen im GC Log also auch bei Verwendung des CMS Collector „Full GC“-Einträge auf. Zusätzlich erhalten wir in diesem Fall eine Angabe zur Ursache der Full GC, z.B. den berüchtigten „concurrent mode failure“.

Um den Rahmen dieses Blogs nicht zu sprengen, verzichte ich auf eine genau Beschreibung des detaillierten Logs für den CMS Collector. Auch weil einer der Autoren des Kollektors hier bereits eine sehr gute und ausführliche Erklärung dazu gibt, die ich nur empfehlen kann.

-XX:+PrintGCTimeStamps und -XX:+PrintGCDateStamps

Es gibt die Möglichkeit, Zeit- und Datumsinformationen zum (einfachen oder detaillierten) GC Log hinzuzufügen. Mit -XX:+PrintGCTimeStamps wird jeder Zeile ein Zeitstempel vorangestellt, der die seit JVM-Start verstrichene Zeit in Sekunden angibt. Ein Beispiel:
0,185: [GC 66048K->53077K(251392K), 0,0977580 secs] 0,323: [GC 119125K->114661K(317440K), 0,1448850 secs] 0,603: [GC 246757K->243133K(375296K), 0,2860800 secs]

Mit -XX:+PrintGCDateStamps hingegen wird jeder Zeile eine absolute Datums- und Zeitangabe vorangestellt:
2014-01-03T12:08:38.102-0100: [GC 66048K->53077K(251392K), 0,0959470 secs] 2014-01-03T12:08:38.239-0100: [GC 119125K->114661K(317440K), 0,1421720 secs] 2014-01-03T12:08:38.513-0100: [GC 246757K->243133K(375296K), 0,2761000 secs]

Die Flags lassen sich auch miteinander kombinieren, falls beide Angaben von Interesse sind. Meine Empfehlung ist, stets beide Flags zu setzen, da man die Informationen gut verwenden kann um Daten aus dem GC Log mit anderen Daten zeitlich zu korrelieren.

-Xloggc

Standardmäßig wird das GC Log auf die Standardausgabe geschrieben. Mit -Xloggc: kann alternativ eine Datei als Ziel für die Ausgabe spezifiziert werden. Dieses Flag schließt übrigens die Flags -XX:+PrintGC und -XX:+PrintGCTimeStamps ein, aber um sich gegenüber unerwarteten Änderungen bei neuen JVM-Versionen zu schützen würde ich diese Flags, falls gewünscht, trotzdem setzen.

„Manageable“ Flags

Eine viel diskutierte Frage ist, ob man GC Logging bei JVMs in Produktionssystemen standardmäßig aktivieren sollte. Der Overhead für GC Logging ist in der Regel gering, weshalb ich hier zu einem „Ja“ tendiere. Eigentlich möchte ich aber auf den folgenden Punkt hinaus, der die Bedeutung der obigen Frage etwas reduziert: Man muss sich beim Start einer JVM gar nicht für oder gegen GC Logging entscheiden.

Bei der Hotspot-JVM gibt es eine spezielle Kategorie von Flags, deren Werte man zur Laufzeit ändern kann. Diese Kategorie nennt sich „manageable“ und beinhaltet insgesamt nur sehr wenige Flags, nicht einmal 20. Die oben besprochenen mit „PrintGC“ beginnenden Flags zählen zu dieser Kategorie. Es ist also ohne Weiteres möglich, GC Logging bei einer laufenden JVM zu aktivieren und auch wieder zu deaktivieren. Hierfür kann man beispielsweise das beim JDK mitgelieferte Kommandozeilentool jinfo nutzen, oder aber mit einem JMX-Client die setVMOption-Operation der HotSpotDiagnostic-MXBean aufrufen.