Lire un log GC en Java : chaque chiffre expliqué

Activer le log du GC est facile. Le lire l’est moins : une ligne de G1 contient une dizaine d’informations, et les mots changent d’une version de Java à l’autre.

Cet article lit de vraies lignes, produites par trois petits programmes du dépôt public java-gc-lab : une charge normale, des objets très gros, et un heap presque plein.

Activer le log

java -Xlog:gc*:file=gc.log:time,uptime,level,tags -jar app.jar

• gc* : tous les messages du GC (gc seul donne une ligne par GC) ;
• file=gc.log : dans un fichier, avec une rotation déjà intégrée (5 fichiers d’environ 20 Mo par défaut) ;
• time,uptime,level,tags : les « décorations » au début de chaque ligne : la date et l’heure, le temps depuis le démarrage de la JVM, le niveau et les tags. Sans rien préciser, la JVM met uptime, level et tags.

Une ligne de pause, avec ces décorations :

[2026-10-22T23:23:46.842+0200][0.356s][info][gc          ] GC(1) Pause Young (Normal) (G1 Evacuation Pause) 117M->24M(256M) 1.660ms

L’heure exacte (time) sert à relier une pause à un événement de l’application, par exemple une requête lente dans un autre log.

Une ligne, mot par mot

Les mots young, mixed et full sont expliqués dans l’article sur les générations.

Les 4 chiffres à suivre

Voici le début et la fin du log de NormalLoad.java, une application qui garde environ 16 Mo de données et crée des objets temporaires en continu :

java -Xmx256m -Xlog:gc gc-logs/NormalLoad.java
[0.341s][info][gc] GC(0) Pause Young (Normal) (G1 Evacuation Pause) 47M->18M(256M) 3.090ms
[0.469s][info][gc] GC(1) Pause Young (Normal) (G1 Evacuation Pause) 117M->23M(256M) 5.790ms
[0.646s][info][gc] GC(2) Pause Young (Normal) (G1 Evacuation Pause) 149M->24M(256M) 4.129ms
…
[3.240s][info][gc] GC(15) Pause Young (Normal) (G1 Evacuation Pause) 171M->24M(256M) 0.635ms
[3.478s][info][gc] GC(16) Pause Young (Normal) (G1 Evacuation Pause) 171M->24M(256M) 12.874ms

1. La fréquence des GC : 17 GC en un peu plus de 3 secondes, environ 5 par seconde. Elle monte quand l’application crée plus d’objets ou quand le heap est trop petit.
2. La durée des pauses : de 0,4 à 12,9 ms ici. On regarde surtout les plus longues : ce sont elles que voient les utilisateurs.
3. Le heap après le GC : 23 à 24 Mo, stable. C’est à peu près la taille des données vivantes. S’il monte d’un GC à l’autre, c’est une fuite (voir l’article sur les OutOfMemoryError).
4. Le débit d’allocation : le heap avant un GC moins le heap après le GC précédent, divisé par le temps entre les deux. Entre GC(0) et GC(1) : (117 − 18) Mo en 0,128 s, soit environ 770 Mo/s. Aucune ligne ne le donne directement : il faut le calculer.

Ce qui doit alerter

Des objets humongous

java -Xmx256m -Xlog:gc gc-logs/Humongous.java
[0.306s][info][gc] GC(0) Pause Young (Concurrent Start) (G1 Humongous Allocation) 146M->9M(256M) 1.583ms

Pour G1, un objet « humongous » fait au moins la moitié d’une région. Il ne passe pas par l’Eden : il reçoit ses propres régions, directement dans la Old. Ici, le programme crée des tableaux de 2 Mo avec des régions de 1 Mo (Heap Region Size: 1M au démarrage avec -Xlog:gc*), et c’est l’allocation elle-même qui lance le GC. Beaucoup de lignes G1 Humongous Allocation indiquent de gros tableaux ou de gros buffers créés souvent.

Un échec d’évacuation, puis Pause Full

java -Xmx64m -Xlog:gc gc-logs/NearTheLimit.java
[0.295s][info][gc] GC(5) Pause Young (Prepare Mixed) (G1 Evacuation Pause) (Evacuation Failure: Allocation) 61M->47M(64M) 0.250ms
[1.348s][info][gc] GC(175) Pause Full (G1 Compaction Pause) 62M->45M(64M) 5.691ms

Le programme garde environ 30 Mo de données dans un heap de 64 Mo. G1 ne trouve plus assez de place pour copier les objets vivants : c’est un échec d’évacuation. La raison est Allocation (pas de place) ou Pinned (un objet bloqué par du code natif). Si un GC ne libère plus rien, G1 lance un Full GC, qui compacte tout le heap et peut être très lent.

Avant Java 18 : l’échec d’évacuation s’appelait to-space exhausted. En Java 11 et 17, c’était une ligne à part (GC(7) To-space exhausted) ; en Java 8, la fin de la ligne de pause. Java 21 écrit (Evacuation Failure), et Java 25 ajoute la raison.

Une ligne Pause Full avec G1, quand elle ne vient pas de System.gc(), est toujours à regarder : le heap est trop petit pour les données vivantes, ou il y a une fuite.

Des pauses qui s’allongent

Si le dernier chiffre des lignes monte au fil des heures, avec le même type de pause, le GC a de plus en plus de travail : plus de données vivantes à copier, ou un heap qui se remplit. C’est un signe à suivre de près.

Les outils

• JFR (Java Flight Recorder), dans le JDK : on le lance avec -XX:StartFlightRecording, et on lit l’enregistrement avec JDK Mission Control. Il montre les pauses du GC avec le reste de l’application. Les détails sont dans l’article sur les outils.
• Des outils tiers lisent aussi les fichiers de log et en font des graphiques, par exemple GCeasy (un service en ligne) ou GCViewer (open source).

Ce qui a changé

Testé avec Java 8 (Corretto 8u504), 11, 17, 21 et 25 (Temurin 11.0.32, 17.0.20, 21.0.9, 25.0.4), sur macOS, avec G1.

Sources : la documentation de la commande java (JDK 25, -Xlog), le chapitre G1 du guide d’Oracle sur le GC (objets humongous, échec d’évacuation, Full GC), JDK-8269022 (le nouveau nom de l’échec d’évacuation).

Pour aller plus loin

• Générations et cycles de GC : Young, Old, Minor, Major, Full
• OutOfMemoryError en Java : chaque message, reproduit
• Les options JVM qui comptent, et celles qui ne marchent plus
• Garbage collector Java : le guide à jour (Java 25)