Ausführliche Garbage Collection in Java

1. Übersicht

In diesem Tutorial sehen wir uns an, wie Sie die ausführliche Speicherbereinigung in einer Java-Anwendung aktivieren . Wir beginnen mit der Einführung, was eine ausführliche Speicherbereinigung ist und warum sie nützlich sein kann.

Als nächstes sehen wir uns verschiedene Beispiele an und lernen die verschiedenen verfügbaren Konfigurationsoptionen kennen. Darüber hinaus konzentrieren wir uns auch auf die Interpretation der Ausgabe unserer ausführlichen Protokolle.

Weitere Informationen zur Garbage Collection (GC) und den verschiedenen verfügbaren Implementierungen finden Sie in unserem Artikel zu Java Garbage Collectors.

2. Kurze Einführung in die ausführliche Speicherbereinigung

Das Aktivieren der ausführlichen Garbage Collection-Protokollierung ist häufig erforderlich, wenn viele Probleme , insbesondere Speicherprobleme, optimiert und behoben werden sollen. In der Tat würden einige argumentieren, dass wir zur strengen Überwachung unseres Anwendungszustands immer die Garbage Collection-Leistung der JVM überwachen sollten.

Wie wir sehen werden, ist das GC-Protokoll ein sehr wichtiges Werkzeug, um mögliche Verbesserungen der Heap- und GC-Konfiguration unserer Anwendung aufzudecken. Für jedes GC-Ereignis enthält das GC-Protokoll genaue Daten zu den Ergebnissen und der Dauer.

Im Laufe der Zeit kann die Analyse dieser Informationen uns helfen, das Verhalten unserer Anwendung besser zu verstehen und die Leistung unserer Anwendung zu optimieren. Darüber hinaus kann es helfen, die GC-Häufigkeit und die Erfassungszeiten zu optimieren, indem die besten Heap-Größen, andere JVM-Optionen und alternative GC-Algorithmen angegeben werden.

2.1. Ein einfaches Java-Programm

Wir werden ein einfaches Java-Programm verwenden, um zu demonstrieren, wie unsere GC-Protokolle aktiviert und interpretiert werden:

public class Application { private static Map stringContainer = new HashMap(); public static void main(String[] args) { System.out.println("Start of program!"); String stringWithPrefix = "stringWithPrefix"; // Load Java Heap with 3 M java.lang.String instances for (int i = 0; i < 3000000; i++) { String newString = stringWithPrefix + i; stringContainer.put(newString, newString); } System.out.println("MAP size: " + stringContainer.size()); // Explicit GC! System.gc(); // Remove 2 M out of 3 M for (int i = 0; i < 2000000; i++) { String newString = stringWithPrefix + i; stringContainer.remove(newString); } System.out.println("MAP size: " + stringContainer.size()); System.out.println("End of program!"); } }

Wie wir im obigen Beispiel sehen können, lädt dieses einfache Programm 3 Millionen String- Instanzen in ein Map- Objekt. Wir rufen dann den Garbage Collector mit System.gc () explizit auf .

Schließlich entfernen wir 2 Millionen der String- Instanzen aus der Map . Wir verwenden auch explizit System.out.println , um die Interpretation der Ausgabe zu vereinfachen.

Im nächsten Abschnitt erfahren Sie, wie Sie die GC-Protokollierung aktivieren.

3. Aktivieren der „einfachen“ GC-Protokollierung

Beginnen wir damit, unser Programm auszuführen und die ausführliche GC über unsere JVM-Startargumente zu aktivieren:

-XX:+UseSerialGC -Xms1024m -Xmx1024m -verbose:gc

Das wichtige Argument hierbei ist -verbose: gc , das die Protokollierung von Garbage Collection-Informationen in ihrer einfachsten Form aktiviert . Standardmäßig wird das GC-Protokoll in stdout geschrieben und sollte eine Zeile für jeden GC der jungen Generation und jeden vollständigen GC ausgeben.

Für die Zwecke unseres Beispiels haben wir den seriellen Garbage Collector, die einfachste GC-Implementierung, über das Argument -XX: + UseSerialGC angegeben .

Wir haben auch eine minimale und maximale Heap-Größe von 1024 MB festgelegt, aber es gibt natürlich mehr JVM-Parameter, die wir optimieren können.

3.1. Grundlegendes Verständnis der ausführlichen Ausgabe

Schauen wir uns nun die Ausgabe unseres einfachen Programms an:

Start of program! [GC (Allocation Failure) 279616K->146232K(1013632K), 0.3318607 secs] [GC (Allocation Failure) 425848K->295442K(1013632K), 0.4266943 secs] MAP size: 3000000 [Full GC (System.gc()) 434341K->368279K(1013632K), 0.5420611 secs] [GC (Allocation Failure) 647895K->368280K(1013632K), 0.0075449 secs] MAP size: 1000000 End of program!

In der obigen Ausgabe sehen wir bereits viele nützliche Informationen darüber, was in der JVM vor sich geht.

Anfangs kann diese Ausgabe ziemlich entmutigend aussehen, aber jetzt gehen wir sie Schritt für Schritt durch.

Zunächst können wir sehen, dass vier Sammlungen stattfanden, eine vollständige GC und drei reinigende junge Generationen.

3.2. Die ausführliche Ausgabe im Detail

Zerlegen wir die Ausgabezeilen detaillierter, um genau zu verstehen, was vor sich geht:

  1. GC oder Full GC - Der Typ der Garbage Collection, entweder GC oder Full GC , um eine kleinere oder vollständige Garbage Collection zu unterscheiden
  2. (Allocation Failure) oder (System.gc ()) - Die Ursache der Sammlung - Allocation Failure zeigt an, dass in Eden kein Platz mehr für die Zuweisung unserer Objekte übrig war
  3. 279616K-> 146232K - Der belegte Heapspeicher vor bzw. nach dem GC (durch einen Pfeil getrennt)
  4. (1013632K) - Die aktuelle Kapazität des Heaps
  5. 0,3318607 Sekunden - Die Dauer des GC-Ereignisses in Sekunden

Wenn wir also die erste Zeile nehmen, bedeutet 279616K-> 146232K (1013632K) , dass der GC den belegten Heapspeicher von 279616K auf 146232K reduziert hat . Die Heap-Kapazität zum Zeitpunkt der GC betrug 1013632 K , und die GC dauerte 0,3318607 Sekunden.

Obwohl das einfache GC-Protokollierungsformat nützlich sein kann, enthält es nur begrenzte Details. Zum Beispiel können wir nicht sagen, ob der GC Objekte von der jungen zur alten Generation verschoben hat oder wie groß die Gesamtgröße der jungen Generation vor und nach jeder Sammlung war .

Aus diesem Grund ist eine detaillierte GC-Protokollierung nützlicher als die einfache.

4. Aktivieren der „detaillierten“ GC-Protokollierung

Um die detaillierte GC-Protokollierung zu aktivieren, verwenden wir das Argument -XX: + PrintGCDetails . Dadurch erhalten wir weitere Details zu jedem GC, z. B.:

  • Größe der jungen und alten Generation vor und nach jedem GC
  • Die Zeit, die ein GC in der jungen und alten Generation benötigt
  • Die Größe der Objekte, die bei jedem GC beworben werden
  • Eine Zusammenfassung der Größe des gesamten Heaps

Im nächsten Beispiel sehen wir, wie Sie noch detailliertere Informationen in unseren Protokollen erfassen, indem Sie -verbose: gc mit diesem zusätzlichen Argument kombinieren .

Please note that the -XX:+PrintGCDetails flag has been deprecated in Java 9, in favor of the new unified logging mechanism (more on this later). Anyway, the new equivalent of the -XX:+PrintGCDetails is the -Xlog:gc* option.

5. Interpreting the “detailed” Verbose Output

Let's run our sample program again:

-XX:+UseSerialGC -Xms1024m -Xmx1024m -verbose:gc -XX:+PrintGCDetails

This time the output is rather more verbose:

Start of program! [GC (Allocation Failure) [DefNew: 279616K->34944K(314560K), 0.3626923 secs] 279616K->146232K(1013632K), 0.3627492 secs] [Times: user=0.33 sys=0.03, real=0.36 secs] [GC (Allocation Failure) [DefNew: 314560K->34943K(314560K), 0.4589079 secs] 425848K->295442K(1013632K), 0.4589526 secs] [Times: user=0.41 sys=0.05, real=0.46 secs] MAP size: 3000000 [Full GC (System.gc()) [Tenured: 260498K->368281K(699072K), 0.5580183 secs] 434341K->368281K(1013632K), [Metaspace: 2624K->2624K(1056768K)], 0.5580738 secs] [Times: user=0.50 sys=0.06, real=0.56 secs] [GC (Allocation Failure) [DefNew: 279616K->0K(314560K), 0.0076722 secs] 647897K->368281K(1013632K), 0.0077169 secs] [Times: user=0.01 sys=0.00, real=0.01 secs] MAP size: 1000000 End of program! Heap def new generation total 314560K, used 100261K [0x00000000c0000000, 0x00000000d5550000, 0x00000000d5550000) eden space 279616K, 35% used [0x00000000c0000000, 0x00000000c61e9370, 0x00000000d1110000) from space 34944K, 0% used [0x00000000d3330000, 0x00000000d3330188, 0x00000000d5550000) to space 34944K, 0% used [0x00000000d1110000, 0x00000000d1110000, 0x00000000d3330000) tenured generation total 699072K, used 368281K [0x00000000d5550000, 0x0000000100000000, 0x0000000100000000) the space 699072K, 52% used [0x00000000d5550000, 0x00000000ebcf65e0, 0x00000000ebcf6600, 0x0000000100000000) Metaspace used 2637K, capacity 4486K, committed 4864K, reserved 1056768K class space used 283K, capacity 386K, committed 512K, reserved 1048576K

We should be able to recognize all of the elements from the simple GC log. But there are several new items.

Let's now consider the new items in the output which are highlighted in blue in the next section:

5.1. Interpreting a Minor GC in Young Generation

We'll begin by analyzing the new parts in a minor GC:

  • [GC (Allocation Failure) [DefNew: 279616K->34944K(314560K), 0.3626923 secs] 279616K->146232K(1013632K), 0.3627492 secs] [Times: user=0.33 sys=0.03, real=0.36 secs]

As before we'll break the lines down into parts:

  1. DefNew – Name of the garbage collector used. This not so obvious name stands for the single-threaded mark-copy stop-the-world garbage collector and is what is used to clean the Young generation
  2. 279616K->34944K – Usage of the Young generation before and after collection
  3. (314560K) – The total size of the Young generation
  4. 0.3626923 secs – The duration in seconds
  5. [Times: user=0.33 sys=0.03, real=0.36 secs] – Duration of the GC event, measured in different categories

Now let's explain the different categories:

  • user – The total CPU time that was consumed by Garbage Collector
  • sys – The time spent in OS calls or waiting for system events
  • real – This is all elapsed time including time slices used by other processes

Since we're running our example using the Serial Garbage Collector, which always uses just a single thread, real-time is equal to the sum of user and system times.

5.2. Interpreting a Full GC

In this penultimate example, we see that for a major collection (Full GC), which was triggered by our system call, the collector used was Tenured.

The final piece of additional information we see is a breakdown following the same pattern for the Metaspace:

[Metaspace: 2624K->2624K(1056768K)], 0.5580738 secs]

Metaspace is a new memory space introduced in Java 8 and is an area of native memory.

5.3. Java Heap Breakdown Analysis

The final part of the output includes a breakdown of the heap including a memory footprint summary for each part of memory.

We can see that Eden space had a 35% footprint and Tenured had a 52% footprint. A summary for Metadata space and class space is also included.

From the above examples, we can now understand exactly what was happening with memory consumption inside the JVM during the GC events.

6. Adding Date and Time Information

No good log is complete without date and time information.

This extra information can be highly useful when we need to correlate GC log data with data from other sources, or it can simply help facilitate searching.

We can add the following two arguments when we run our application to get date and time information to appear in our logs:

-XX:+PrintGCTimeStamps -XX:+PrintGCDateStamps

Each line now starts with the absolute date and time when it was written followed by a timestamp reflecting the real-time passed in seconds since the JVM started:

2018-12-11T02:55:23.518+0100: 2.601: [GC (Allocation ...

Please note that these tuning flags have been removed in Java 9. The new alternative is:

-Xlog:gc*::time

7. Logging to a File

As we've already seen, by default the GC log is written to stdout. A more practical solution is to specify an output file.

We can do this by using the argument -Xloggc: where file is the absolute path to our output file:

-Xloggc:/path/to/file/gc.log

Similar to other tuning flags, Java 9 deprecated the -Xloggc flag in favor of the new unified logging. To be more specific, now the alternative for logging to a file is:

-Xlog:gc:/path/to/file/gc.log

8. Java 9: Unified JVM Logging

As of Java 9, most of the GC related tuning flags have been deprecated in favor of the unified logging option -Xlog:gc. The verbose:gc option, however, still works in Java 9 and newer version.

For instance, as of Java 9, the equivalent of the -verbose:gc flag in the new unified logging system is:

-Xlog:gc

This will log all the info level GC logs to the standard output. It's also possible to use the -Xlog:gc= syntax to change the log level. For instance, to see all debug level logs:

-Xlog:gc=debug

As we saw earlier, we can change the output destination via the -Xlog:gc=: syntax. By default, the output is stdout, but we can change it to stderr or even a file:

-Xlog:gc=debug:file=gc.txt

Also, it's possible to add a few more fields to the output using decorators. For instance:

-Xlog:gc=debug::pid,time,uptime

Here we're printing the process id, uptime, and current timestamp in each log statement.

To see more examples of the Unified JVM Logging, see the JEP 158 standard.

9. A Tool to Analyze GC Logs

It can be time-consuming and quite tedious to analyze GC logs using a text editor. Depending on the JVM version and the GC algorithm that is used, the GC log format could differ.

Es gibt ein sehr gutes kostenloses grafisches Analysetool, das die Garbage Collection-Protokolle analysiert, viele Metriken zu potenziellen Garbage Collection-Problemen bereitstellt und sogar mögliche Lösungen für diese Probleme bietet.

Schauen Sie sich auf jeden Fall den Universal GC Log Analyzer an!

10. Schlussfolgerung

Zusammenfassend haben wir in diesem Tutorial die ausführliche Speicherbereinigung in Java ausführlich untersucht.

Zunächst stellten wir vor, was eine ausführliche Speicherbereinigung ist und warum wir sie möglicherweise verwenden möchten. Wir haben uns dann einige Beispiele mit einer einfachen Java-Anwendung angesehen. Wir haben zunächst die GC-Protokollierung in ihrer einfachsten Form aktiviert, bevor wir einige detailliertere Beispiele und die Interpretation der Ausgabe untersucht haben.

Schließlich haben wir verschiedene zusätzliche Optionen zum Protokollieren von Uhrzeit- und Datumsinformationen sowie zum Schreiben von Informationen in eine Protokolldatei untersucht.

Die Codebeispiele finden Sie auf GitHub.