Collecte de la mémoire détaillée en Java

1. Vue d'ensemble

Dans ce didacticiel, nous verrons comment activer le garbage collection détaillé dans une application Java . Nous commencerons par présenter ce qu'est le garbage collection détaillé et pourquoi il peut être utile.

Ensuite, nous examinerons plusieurs exemples différents et nous découvrirons les différentes options de configuration disponibles. De plus, nous allons également nous concentrer sur la façon d'interpréter la sortie de nos journaux détaillés.

Pour en savoir plus sur Garbage Collection (GC) et les différentes implémentations disponibles, consultez notre article sur Java Garbage Collectors.

2. Brève introduction au nettoyage de la mémoire détaillé

L'activation de la journalisation détaillée du garbage collection est souvent nécessaire lors du réglage et du débogage de nombreux problèmes , en particulier des problèmes de mémoire. En fait, certains diront qu'afin de surveiller strictement la santé de nos applications, nous devrions toujours surveiller les performances de Garbage Collection de la JVM.

Comme nous le verrons, le journal GC est un outil très important pour révéler les améliorations potentielles du tas et de la configuration GC de notre application. Pour chaque événement GC, le journal GC fournit des données exactes sur ses résultats et sa durée.

Au fil du temps, l'analyse de ces informations peut nous aider à mieux comprendre le comportement de notre application et à optimiser les performances de notre application. De plus, il peut aider à optimiser la fréquence GC et les temps de collecte en spécifiant les meilleures tailles de tas, d'autres options JVM et d'autres algorithmes GC.

2.1. Un programme Java simple

Nous utiliserons un programme Java simple pour montrer comment activer et interpréter nos journaux GC:

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!"); } }

Comme nous pouvons le voir dans l'exemple ci-dessus, ce programme simple charge 3 millions d' instances String dans un objet Map . Nous faisons ensuite un appel explicite au garbage collector en utilisant System.gc () .

Enfin, nous supprimons 2 millions d' instances String de la carte . Nous utilisons également explicitement System.out.println pour faciliter l'interprétation de la sortie.

Dans la section suivante, nous verrons comment activer la journalisation GC.

3. Activation de la journalisation GC «simple»

Commençons par exécuter notre programme et activer le GC détaillé via nos arguments de démarrage JVM:

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

L'argument important ici est -verbose: gc , qui active la journalisation des informations de récupération de place dans sa forme la plus simple . Par défaut, le journal GC est écrit dans stdout et doit afficher une ligne pour chaque GC de jeune génération et chaque GC complet.

Pour les besoins de notre exemple, nous avons spécifié le ramasse-miettes en série, l'implémentation GC la plus simple, via l'argument -XX: + UseSerialGC .

Nous avons également défini une taille de tas minimale et maximale de 1024 Mo, mais il y a, bien sûr, plus de paramètres JVM que nous pouvons régler.

3.1. Compréhension de base de la sortie verbeuse

Jetons maintenant un œil à la sortie de notre programme simple:

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!

Dans la sortie ci-dessus, nous pouvons déjà voir de nombreuses informations utiles sur ce qui se passe à l'intérieur de la JVM.

Au début, cette sortie peut sembler assez intimidante, mais passons maintenant en revue étape par étape.

Tout d'abord, nous pouvons voir que quatre collectes ont eu lieu, une Full GC et trois nettoyage Jeunes générations.

3.2. La sortie verbeuse plus en détail

Décomposons les lignes de sortie plus en détail pour comprendre exactement ce qui se passe:

  1. GC ou Full GC - Le type de garbage collection, GC ou Full GC pour distinguer un garbage collection mineur ou complet
  2. (Allocation Failure) ou (System.gc ()) - La cause de la collecte - Allocation Failure indique qu'il ne restait plus d'espace dans Eden pour allouer nos objets
  3. 279616K-> 146232K - La mémoire de tas occupée avant et après le GC, respectivement (séparés par une flèche)
  4. (1013632K) - La capacité actuelle du tas
  5. 0.3318607 sec - La durée de l'événement GC en secondes

Ainsi, si nous prenons la première ligne, 279616K-> 146232K (1013632K) signifie que le GC a réduit la mémoire de tas occupée de 279616K à 146232K . La capacité du tas au moment du GC était de 1013632K et le GC prenait 0,3318607 secondes.

Cependant, bien que le format d'enregistrement GC simple puisse être utile, il fournit des détails limités. Par exemple, nous ne pouvons pas dire si le GC a déplacé des objets de la jeune à la vieille génération ou quelle était la taille totale de la jeune génération avant et après chaque collection .

Pour cette raison, la journalisation détaillée du GC est plus utile que la simple.

4. Activation de la journalisation GC «détaillée»

Pour activer la journalisation détaillée du GC, nous utilisons l'argument -XX: + PrintGCDetails . Cela nous donnera plus de détails sur chaque CG, tels que:

  • Taille de la jeune et vieille génération avant et après chaque GC
  • Le temps qu'il faut pour qu'un GC se produise chez les jeunes et les moins jeunes
  • La taille des objets promus à chaque GC
  • Un résumé de la taille du tas total

Dans l'exemple suivant, nous verrons comment capturer des informations encore plus détaillées dans nos journaux en combinant -verbose: gc avec cet argument supplémentaire.

Veuillez noter que l' indicateur -XX: + PrintGCDetails est obsolète dans Java 9, au profit du nouveau mécanisme de journalisation unifié (nous en parlerons plus tard). Quoi qu'il en soit, le nouvel équivalent de -XX: + PrintGCDetails est l' option -Xlog: gc * .

5. Interprétation de la sortie verbeuse «détaillée»

Exécutons à nouveau notre exemple de programme:

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

Cette fois, la sortie est plutôt plus détaillée:

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

Nous devrions être en mesure de reconnaître tous les éléments du simple journal GC. Mais il y a plusieurs nouveautés.

Considérons maintenant les nouveaux éléments de la sortie qui sont surlignés en bleu dans la section suivante:

5.1. Interpréter un GC mineur dans la jeune génération

Nous commencerons par analyser les nouvelles pièces dans un GC mineur:

  • [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.

Il existe un très bon outil d'analyse graphique gratuit qui analyse les journaux de récupération de place, fournit de nombreuses mesures sur les problèmes potentiels de récupération de place et fournit même des solutions potentielles à ces problèmes.

Jetez un œil à l'Analyseur de journaux universel GC!

10. Conclusion

Pour résumer, dans ce didacticiel, nous avons exploré en détail le garbage collection détaillé en Java.

Tout d'abord, nous avons commencé par présenter ce qu'est le garbage collection détaillé et pourquoi nous pourrions vouloir l'utiliser. Nous avons ensuite examiné plusieurs exemples utilisant une simple application Java. Nous avons commencé par activer la journalisation GC dans sa forme la plus simple avant d'explorer plusieurs exemples plus détaillés et comment interpréter la sortie.

Enfin, nous avons exploré plusieurs options supplémentaires pour enregistrer les informations d'heure et de date et comment écrire des informations dans un fichier journal.

Les exemples de code peuvent être trouvés sur GitHub.