Utilización de la información de verbose:gc (solo AIX, Linux)

Puede utilizar la opción -verbose:gc con la opción -Xgc:verboseGCCycleTime=N para escribir información en la consola sobre la actividad del recopilador de basura Metronome. No todas las propiedades XML de la salida de -verbose:gc de la JVM estándar se crean o son aplicables a la salida del recopilador de basura Metronome.

Utilice la opción -verbose:gc para ver el espacio libre mínimo, máximo y medio en el almacenamiento dinámico. De este modo, podrá comprobar el nivel de actividad y uso del almacenamiento dinámico y luego ajustar los valores, si fuese necesario. La opción -verbose:gc escribe estadísticas de Metronome en la consola.

La opción -Xgc:verboseGCCycleTime=N controla la frecuencia de recuperación de la información. Determina el tiempo en milisegundos en el que se vuelcan los resúmenes. El valor predeterminado para N es 1000 milisegundos. El tiempo de ciclo no implica que el resumen se vuelque exactamente a dicha hora, sino cuando pasa el último suceso de recogida de basura que satisface este criterio temporal. La recogida y visualización de estas estadísticas pueden aumentar los objetivos de tiempo de pausa del recopilador de basura Metronome y, a medida que N se reduce, los tiempos de las pausas pueden ser grandes.

Una cantidad es un único periodo de actividad del recopilador de basura Metronome, que provoca una interrupción o un tiempo de pausa para una aplicación.

Ejemplo de salida de verbose:gc

Especifique:

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

Cuando se desencadena la recogida de basura, se produce un suceso trigger start, seguido de varios sucesos heartbeat y, por último, un suceso trigger end cuando se satisface el desencadenante. Este ejemplo muestra un ciclo de recogida de basura desencadenado como salida de 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" />

Se pueden producir los siguientes tipos de sucesos:

< desencadenante-inicio ... >: El inicio de un ciclo de recogida de basura, cuando la cantidad de memoria usada llega a ser mayor que el umbral del desencadenante. El umbral predeterminado es el 50% del almacenamiento dinámico. El atributo intervalms es el intervalo entre el suceso trigger end anterior (con id-1) y este suceso trigger start.
< desencadenante ... >: Un ciclo de recogida de basura ha reducido correctamente la cantidad de memoria utilizada por debajo del umbral desencadenante. Si un ciclo de recogida de basura ha terminado, pero la memoria utilizada no ha caído por debajo del umbral desencadenante, se iniciará un nuevo ciclo de recogida de basura con el mismo ID de contexto. Para cada suceso de trigger start, hay un suceso trigger end coincidente con el mismo ID de contexto. El atributo intervalms es el intervalo entre el suceso trigger start anterior y el suceso trigger end actual. Durante este tiempo, se habrán completado una o varias recogidas de basura hasta que la memoria utilizada esté por debajo del umbral desencadenante.
<gc-op id="28" type="heartbeat"...>: Suceso periódico que recopila información (sobre la memoria y el tiempo) acerca de todas las cantidades de la recogida de basura del tiempo que cubre. Un suceso de pulsación solo puede producirse entre un par coincidente de sucesos trigger start y trigger end, es decir, mientras está en proceso un ciclo de recopilación de basura activo. El atributo intervalms es el intervalo entre el suceso de pulsación anterior (con id -1) y este suceso de pulsación.
<gc-op id="29" type="syncgc"...>: Suceso de recogida de basura síncrono (no determinante). Consulte Recogidas de basura síncronas

Las etiquetas XML de este ejemplo tienen los significados siguientes:

< quanta ... >: Resumen de las pausas de cantidad durante el intervalo de pulsaciones, incluyendo la longitud de las pausas, en milisegundos.
< free mem type = "heap " ... >: Resumen de la cantidad de espacio libre de almacenamiento dinámico durante el intervalo de pulsaciones, con la muestra tomada al final de cada cantidad de recogida de basura.
<classunload-info classloadersunloaded=9 classesunloaded=156 />: Número de cargadores de clase y clases descargadas durante el intervalo de pulsaciones.
<references type="weak" cleared="660 />: Número y tipo de objetos de referencia de Java™ que se han borrado durante el intervalo de pulsaciones.

Nota:

Si solo se ha producido una cantidad de recogida de basura en el intervalo entre dos pulsaciones, se toma una muestra de la memoria libre solo al final de esta cantidad. Por lo que las cantidades mínima, máxima y media que se ofrecen en el resumen de la pulsación son todas iguales.
El intervalo entre dos sucesos de pulsación podría ser significativamente mayor que el tiempo de ciclo especificado si el almacenamiento dinámico no está suficientemente completo como para precisar de la actividad de recogida de basura. Por ejemplo, si su programa necesita una actividad de recogida de basura solo una vez cada pocos segundos, es probable que vea una pulsación solo una vez cada pocos segundos.
Es posible que el intervalo sea significativamente mayor que el tiempo del ciclo especificado porque la recogida de basura no tiene trabajo en un almacenamiento dinámico que no está lo suficientemente lleno como para garantizar la actividad de la recogida de basura. Por ejemplo, si su programa necesita una actividad de recogida de basura solo una vez cada pocos segundos, es probable que vea una pulsación solo una vez cada pocos segundos.
Si se produce un suceso, como la recogida de basura síncrona o un cambio en la prioridad, los detalles del suceso y todos los sucesos pendientes, como pulsaciones, se generan como salida de inmediato.
Si la cantidad máxima de recogida de basura para un periodo determinado es demasiado grande, puede ser deseable reducir la utilización de destino mediante la opción -Xgc:targetUtilization. Esta acción proporciona a la recogida de basura más tiempo para trabajar. También puede ser deseable aumentar el tamaño de almacenamiento dinámico con la opción -Xmx. Del mismo modo, si su aplicación puede tolerar retardos más largos de los que se están notificando actualmente, puede aumentar la utilización objetivo o reducir el tamaño de almacenamiento dinámico.
La salida se puede redirigir a un archivo de registro en lugar de la consola con la opción -Xverbosegclog:<file>; por ejemplo, -Xverbosegclog:out escribe la salida -verbose:gc en el archivo out.
La prioridad listada en thread-priority es la prioridad de hebra del sistema operativo subyacente, no una prioridad de hebra Java.

Recogidas de basura síncronas

También se graba una entrada en el registro de -verbose:gc cuando se produce una recogida de basura síncrona (no determinista). Este suceso tiene tres causas posibles:

Una llamada explícita de System.gc() en el código.
La JVM se queda sin memoria y ejecuta una recogida de basura síncrona para evitar una condición de tipo OutOfMemoryError.
La JVM se apaga durante una recogida de basura continua. La JVM no puede cancelar la recogida, por lo que completa la recogida de forma síncrona y luego sale.

Un ejemplo de una entrada de System.gc() es:

<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>

Este es un ejemplo de una entrada de recogida de basura síncrona como resultado del cierre 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>

Los atributos y etiquetas XML de este ejemplo tienen los significados siguientes:

<gc-op id="9" type="syncgc" timems="6.439" ...: La línea indica que el tipo de suceso es una recogida de basura síncrona. El atributo timems es la duración de la recogida de basura síncrona en milisegundos.
< syncgc-info razón=" ... " />: El motivo de la recogida de basura síncrona.
<free-mem-delta.../>: La memoria de almacenamiento dinámico de Java libre antes y después de la recogida de basura síncrona en bytes.
<finalization .../>: Número de objetos pendientes de finalización.
<classunload-info .../>: Número de cargadores de clase y clases descargadas durante el intervalo de pulsaciones.
<references type="weak" cleared="53" .../>: Número y tipo de objetos de referencia Java que se han borrado durante el intervalo de pulsaciones.

La recogida de basura síncrona debida a condiciones de falta de memoria o al cierre de la máquina virtual solo se puede producir si el recopilador de basura está activo. Tiene que ir precedida por un suceso trigger start, aunque no es necesario que sea de inmediato. Algunos sucesos de pulsación pueden ocurrir entre un suceso trigger start y el suceso synchgc. La recogida de basura síncrona provocada por System.gc() puede producirse en cualquier momento.

Rastreo de todas las cantidades del recopilador de basura

Se puede realizar un seguimiento de las distintas cantidades de la recogida de basura habilitando los puntos de rastreo GlobalGCStart y GlobalGCEnd. Estos puntos de rastreo se producen al principio y al final de toda la actividad del recopilador de basura Metronome, incluidas las recogidas de basura síncronas. La salida de estos puntos de rastreo tendrá un aspecto similar al siguiente:

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

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

Entradas de falta de memoria

Cuando el almacenamiento dinámico se queda sin espacio libre, se graba una entrada en el registro de -verbose:gc antes de que se genere la excepción OutOfMemoryError. Este es un ejemplo de esta salida:

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

De forma predeterminada, el volcado Java se produce como resultado de una excepción OutOfMemoryError. Este volcado contiene información sobre la memoria utilizada por el programa.

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