Utilisation des informations produites par l'option verbose:gc (AIX, Linux uniquement)

Vous pouvez utiliser l'option -verbose:gc avec l'option -Xgc:verboseGCCycleTime=N pour écrire des informations dans la console sur l'activité du récupérateur de place Metronome. Les propriétés XML de la sortie -verbose:gc de la machine JVM standard ne sont pas toutes créées ou s'appliquent à la sortie du récupérateur de place Metronome.

Utilisez l'option -verbose:gc pour afficher l'espace libre minimal, maximal et moyen dans le tas. De cette manière, vous pouvez vérifier le niveau d'activité et d'utilisation du tas et ajuster les valeurs si nécessaires. L'option -verbose:gc écrit les statistiques Metronome sur la console.

L'option -Xgc:verboseGCCycleTime=N contrôle la fréquence d'extraction des informations. Elle détermine l'intervalle, en millisecondes, séparant deux vidages consécutifs des informations récapitulatives. La valeur par défaut de N est de 1000 millisecondes. L'instant précis auquel a lieu le vidage peut varier, car pour qu'il ait lieu, il faut attendre que le dernier événement de récupération de place soit passé. Il faut du temps au récupérateur de place Metronome pour collecter et afficher ces statistiques. Plus N est petit, plus les vidages sont fréquents et tendent à allonger les temps de pause introduits par le récupérateur de place.

Un quantum est une période d'activité du récupérateur de place Metronome, qui provoque une interruption ou un temps de pause dans l'exécution de l'application.

Exemple de sortie verbose:gc

Entrez :

java -Xgcpolicy:metronome -verbose:gc -Xgc:verboseGCCycleTime=N myApplication

Au déclenchement d'une récupération de place, un événement trigger start se produit, suivi d'un nombre indéterminé d'événements heartbeat (pulsation), puis d'un événement trigger end lorsque le déclencheur est satisfait. Cet exemple montre un cycle de récupération de place déclenché en tant que sortie verbose:gc :

<trigger-start id="25" timestamp="2011-07-12T09:32:04.503" /> 

<cycle-start id="26" type="global" contextid="26" timestamp="2011-07-12T09:32:04.503" intervalms="984.285" /> 

<gc-op id="27" type="heartbeat" contextid="26" timestamp="2011-07-12T09:32:05.209">   
  <quanta quantumCount="321" quantumType="mark" minTimeMs="0.367" meanTimeMs="0.524" maxTimeMs="1.878" 
    maxTimestampMs="598704.070" />   
  <exclusiveaccess-info minTimeMs="0.006" meanTimeMs="0.062" maxTimeMs="0.147" />   
  <free-mem type="heap" minBytes="99143592" meanBytes="114374153" maxBytes="134182032" />   
  <thread-priority maxPriority="11" minPriority="11" />
</gc-op> 

<gc-op id="28" type="heartbeat" contextid="26" timestamp="2011-07-12T09:32:05.458">   
  <quanta quantumCount="115" quantumType="sweep" minTimeMs="0.430" meanTimeMs="0.471" maxTimeMs="0.511" 
    maxTimestampMs="599475.654" />   
  <exclusiveaccess-info minTimeMs="0.007" meanTimeMs="0.067" maxTimeMs="0.173" />   
  <classunload-info classloadersunloaded=9 classesunloaded=156  />     
  <references type="weak" cleared="660" />   
  <free-mem type="heap" minBytes="24281568" meanBytes="55456028" maxBytes="87231320" />   
  <thread-priority maxPriority="11" minPriority="11" />
</gc-op> 

<gc-op id="29" type="syncgc" timems="136.945" contextid="26" timestamp="2011-07-12T09:32:06.046">   
  <syncgc-info reason="out of memory" exclusiveaccessTimeMs="0.006" threadPriority="11" />   
  <free-mem-delta type="heap" bytesBefore="21290752" bytesAfter="171963656" />
</gc-op> 

<cycle-end id="30" type="global" contextid="26" timestamp="2011-07-12T09:32:06.046" /> 

<trigger-end id="31" timestamp="2011-07-12T09:32:06.046" />

Les types d'événements suivants peuvent se produire :

<trigger-start ...>: Début d'un cycle de récupération de place lorsque la quantité de mémoire utilisée est devenue supérieure au seuil du déclencheur. Ce seuil est, par défaut, fixé à 50 % du tas. L'attribut intervalms est l'intervalle entre l'événement trigger end précédent (avec id-1) et cet événement trigger start.
<trigger-end ...>: Un cycle de récupération de place est parvenu à ramener la quantité de mémoire utilisée sous le seuil du déclencheur. Si un cycle de récupération de place s'est terminé et que la mémoire utilisée n'est pas retombée en dessous du seuil du déclencheur, un nouveau cycle de récupération de place est démarré avec le même ID de contexte. Pour chaque événement trigger start, il existe un événement trigger end correspondant avec le même ID de contexte. L'attribut intervalms est l'intervalle entre l'événement trigger start précédent et l'événement trigger end en cours. Pendant ce laps de temps, un ou plusieurs cycles de récupération de place auront été exécutés jusqu'à ce que la mémoire utilisée retombe en dessous du seuil du déclencheur.
<gc-op id="28" type="heartbeat"...>: Evénement périodique recueillant des informations (mesures de quantité de mémoire et de temps) sur tous les quanta de récupération de place pour la période couverte. Un événement de signal de présence peut se produire uniquement entre une paire correspondante d'événements trigger start et trigger end, c'est-à-dire qu'un cycle actif de récupération de place est en cours de traitement. L'attribut intervalms est l'intervalle entre l'événement de signal de présence précédent (avec id -1) et cet événement de signal de présence.
<gc-op id="29" type="syncgc"...>: Evénement de récupération de place synchrone (non déterministe). Voir Récupérations de place synchrones

Les balises XML dans cet exemple ont la signification suivante :

<quanta ...>: Résumé de la durée de pause de quantum au cours de l'intervalle de pulsation, incluant la longueur des pauses en millisecondes.
<free-mem type="heap" ...>: Résumé de la quantité d'espace de tas libre au cours de l'intervalle de pulsation. Valeur échantillonnée à la fin de chaque quantum de récupération de place.
<classunload-info classloadersunloaded=9 classesunloaded=156 />: Nombre de chargeurs de classes et de classes déchargées au cours de l'intervalle de pulsation.
<references type="weak" cleared="660 />: Nombre et type d'objets de référence Java™ qui ont été effacés pendant l'intervalle des pulsations.

Remarque :

Si un seul quantum de récupération de place s'est produit dans l'intervalle entre deux pulsations, la mémoire libre est échantillonnée uniquement à la fin de ce quantum. Par conséquent, les quantités minimale, maximale et moyenne données dans le résumé des pulsations sont toutes égales.
Il se peut que l'intervalle entre deux événements de pulsation soit sensiblement plus long que le temps de cycle spécifié si le tas n'est pas suffisamment plein pour nécessiter une activité de récupération de place. Par exemple, si votre programme nécessite une récupération de place une seule fois toutes les quelques secondes, une pulsation n'apparaîtra vraisemblablement qu'une seule fois toutes les quelques secondes.
Il se peut que l'intervalle soit sensiblement plus long que le temps de cycle spécifié, car la récupération de place n'a rien à faire sur un tas qui n'est pas suffisamment plein pour garantir le bénéfice d'une telle récupération. Par exemple, si votre programme nécessite une récupération de place une seule fois toutes les quelques secondes, une pulsation n'apparaîtra vraisemblablement qu'une seule fois toutes les quelques secondes.
Si un événement tel qu'une récupération de place synchrone ou un changement de priorité se produit, les détails de l'événement et de tout événement en attente (par exemple, les pulsations) sont produits immédiatement en sortie.
Si la quantité maximale de récupération de place pour une période donnée est trop importante, vous pouvez réduire l'utilisation de la cible à l'aide de l'option -Xgc:targetUtilization. Cette action laisse au récupérateur de place plus de temps pour travailler. Vous pouvez également augmenter la taille de segment avec l'option -Xmx. De même, si l'application peut tolérer des retards plus longs que ceux qui sont rapportés, vous pouvez augmenter l'utilisation cible ou réduire la taille du tas.
La sortie peut être redirigée vers un fichier journal à la place de la console avec l'option -Xverbosegclog:<file>. Par exemple, -Xverbosegclog:out écrit la sortie -verbose:gc dans le fichier out.
La priorité indiquée dans thread-priority correspond à la priorité d'unité d'exécution du système d'exploitation sous-jacent et non à une priorité d'unité d'exécution Java.

Récupérations de place synchrones

Une entrée est également écrite dans le journal -verbose:gc lorsqu'une récupération de place synchrone (non déterministe) se produit. Cet événement a trois causes possibles :

Un appel System.gc() explicite dans le code.
A court de mémoire, la JVM exécute une récupération de place synchrone pour éviter une condition OutOfMemoryError.
La JVM se ferme pendant un récupération de place continue. Ne pouvant annuler la récupération de place, elle la termine de manière synchrone, puis se ferme.

Voici un exemple d'entrée System.gc() :

<gc-op id="9" type="syncgc" timems="12.92" contextid="8" timestamp=
"2011-07-12T09:41:40.808">
  <syncgc-info reason="system GC" totalBytesRequested="260" exclusiveaccessTimeMs="0.009" 
  threadPriority="11" />
  <free-mem-delta type="heap" bytesBefore="22085440" bytesAfter="136023450" />
  <classunload-info classloadersunloaded="54" classesunloaded="234" />
  <references type="soft" cleared="21" dynamicThreshold="29" maxThreshold="32" />
  <references type="weak" cleared="523" />
  <finalization enqueued="124" />
</gc-op>

Exemple d'entrée de récupération de place synchrone résultant de l'arrêt de la JVM :

<gc-op id="24" type="syncgc" timems="6.439" contextid="19" timestamp="2011-07-12T09:43:14.524">   
  <syncgc-info reason="VM shut down" exclusiveaccessTimeMs="0.009" threadPriority="11" />   
  <free-mem-delta type="heap" bytesBefore="56182430" bytesAfter="151356238" />   
  <classunload-info classloadersunloaded="14" classesunloaded="276" />   
  <references type="soft" cleared="154" dynamicThreshold="29" maxThreshold="32" /> 
  <references type="weak" cleared="53" />   
  <finalization enqueued="34" />
</gc-op>

Les balises XML et les attributs dans cet exemple ont la signification suivante :

<gc-op id="9" type="syncgc" timems="6.439" ...: Cette ligne indique que le type d'événement est une récupération de place synchrone. L'attribut timems est la durée de la récupération de place synchrone en millisecondes.
<syncgc-info reason="..."/>: Cause de la récupération de place synchrone.
<free-mem-delta.../>: Mémoire dynamique Java disponible avant et après la récupération de place synchrone, en octets.
<finalization .../>: Nombre d'objets en attente de finalisation.
<classunload-info .../>: Nombre de chargeurs de classes et de classes déchargées au cours de l'intervalle de pulsation.
<references type="weak" cleared="53" .../>: Nombre et type d'objets de référence Java qui ont été effacés au cours de l'intervalle des pulsations.

Une récupération de place synchrone suite à un manque de mémoire ou l'arrêt de la machine virtuelle peut se produire uniquement lorsque le récupérateur de place est actif. Elle doit être précédée d'un événement trigger start, mais pas nécessairement immédiatement. Certains événement de pulsation se produisent probablement entre un événement trigger start et l'événement synchgc. La récupération de place synchrone provoquée par System.gc() peut se produire à tout moment.

Suivi de tous les quanta de récupération de place

Chaque quanta GC peut être suivi en activant les points de trace GlobalGCStart et GlobalGCEnd. Ces points de trace sont produits au début et à la fin de toutes les activités de récupération de place Metronome, y compris les récupérations de place synchrones. La sortie de ces points de trace ressemble à ceci :

03:44:35.281 0x833cd00 j9mm.52 - GlobalGC start: globalcount=3

03:44:35.284 0x833cd00 j9mm.91 - GlobalGC end: workstackoverflow=0 overflowcount=0

Entrées de manque de mémoire

Lorsque le tas vient à manquer d'espace libre, une entrée est écrite dans le journal -verbose:gc avant l'émission de l'exception OutOfMemoryError. Exemple de sortie :

<out-of-memory id="71" timestamp="2011-07-12T10:21:50.135" memorySpaceName="Metronome" 
  memorySpaceAddress="0806DFDC"/>

Par défaut, un vidage Java est généré consécutivement à l'émission d'une exception OutOfMemoryError. Ce vidage contient des informations sur la mémoire utilisée par votre programme.

NULL
1STSEGTOTAL    Total memory:           4066080 (0x003E0B20)
1STSEGINUSE    Total memory in use:    3919440 (0x003BCE50)
1STSEGFREE     Total memory free:       146640 (0x00023CD0)