Utilizando informações de verbose:gc (somente AIX e Linux)

É possível usar a opção -verbose:gc com a opção -Xgc:verboseGCCycleTime=N para gravar no console informações sobre a atividade do Metronome Garbage Collector. Nem todas as propriedades XML na saída de -verbose:gc da JVM padrão são criadas ou aplicadas à saída do Metronome Garbage Collector.

Use a opção -verbose:gc para visualizar o espaço livre mínimo, máximo e médio no heap. Dessa forma, é possível verificar o nível de atividade e de uso do heap e, em seguida, ajustar os valores, se necessário. A opção -verbose:gc grava as estatísticas do Metronome no console.

A opção -Xgc:verboseGCCycleTime=N controla a frequência de recuperação das informações. Ela determina o tempo, em milissegundos, em que os resumos são coletados. O valor padrão para N é de 1.000 milissegundos. A existência de um ciclo operacional não significa que o resumo é feito precisamente naquele momento, mas sim quando o último evento de coleta de lixo que atende a esse critério é transmitido. A coleta e a exibição dessas estatísticas podem aumentar os períodos de pausa do Metronome Garbage Collector e, à medida em que N diminui, os períodos de pausa podem aumentar.

Um quantum é um período único de atividade do Metronome Garbage Collector, que causa uma interrupção ou um período de pausa de um aplicativo.

Exemplo da saída de verbose:gc

Insira:

java -Xgcpolicy:metronome -verbose:gc -Xgc:verboseGCCycleTime=N myApplication
Quando a coleta de lixo é acionada, ocorre um evento trigger start, seguido por qualquer número de eventos heartbeat e, em seguida, um evento trigger end quando o acionador fica satisfeito. Esse exemplo mostra um ciclo de coleta de lixo acionado como a saída 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" />

Podem ocorrer os tipos de eventos a seguir:

< trigger-start ...>
O início de um ciclo de coleta de lixo, quando a quantidade de memória utilizada torna-se maior do que o limite do acionador. O limite padrão é 50% do heap. O atributo intervalms é o intervalo entre o evento trigger end anterior (com id-1) e este evento trigger start.
< trigger-end ...>
Um ciclo de coleta de lixo reduziu com êxito a quantidade de memória utilizada, deixando-a abaixo do limite do acionador. Se um ciclo de coleta de lixo for encerrado, mas a quantidade de memória utilizada não ficar abaixo do limite do acionador, um novo ciclo de coleta de lixo será iniciado com o mesmo ID de contexto. Para cada evento trigger start, há um evento trigger end correspondente com o mesmo ID de contexto. O atributo intervalms é o intervalo entre o evento trigger start anterior e o evento trigger end atual. Durante esse tempo, um ou mais ciclos de coleta de lixo serão concluídos, até que a memória utilizada fique abaixo do limite do acionador.
< gc-op id="28 "type="heartbeat" ...>
Um evento periódico que reúne informações (de memória e tempo) sobre a quantidade de coleta de lixo para o tempo coberto. Um evento de pulsação pode ocorrer somente entre um par correspondente de eventos trigger start e trigger end; ou seja, enquanto um ciclo de coleta de lixo ativo está em andamento. O atributo intervalms é o intervalo entre o evento de pulsação anterior (com id -1) e este evento de pulsação.
< gc-op id="29 "type="syncgc" ...>
Um evento de coleta de lixo síncrono (não determinístico). Consulte Coletas de lixo síncrona
As identificações XML nesse exemplo têm os seguintes significados:
< quanta ...>
Um resumo dos tempos de pausa significativos durante o intervalo de pulsação, incluindo a duração da pausa em milissegundos.
< free mem type = "heap " ...>
Um resumo da quantidade de espaço de heap livre durante o intervalo de pulsação, recolhido no final de cada quantum de coleta de lixo.
< classunload-info classloadersunloaded=9 classesunloaded=156 />
O número de carregadores de classe e classes descarregados durante o intervalo de pulsação.
< references type="weak " cleared="660 />
O número e tipo de objetos de referência Java™ que foram limpos durante o intervalo de pulsação.
Nota:
  • Se apenas um quantum de coleta de lixo ocorrer no intervalo entre duas pulsações, a quantidade de memória livre será fornecida apenas ao final desse único quantum. Portanto, as quantidades mínima, máxima e média fornecidas no resumo da pulsação serão todas iguais.
  • O intervalo entre dois eventos de pulsação pode ser significativamente maior do que o ciclo operacional especificado, se o heap não estiver suficientemente cheio para exigir a atividade de coleta de lixo. Por exemplo, se o programa requer que a atividade de coleta de lixo ocorra apenas uma vez a cada alguns segundos, você provavelmente verá uma pulsação apenas uma vez a cada poucos segundos.
  • É possível que o intervalo seja significativamente maior do que o ciclo operacional especificado porque a coleta de lixo é desnecessária em um heap que não está suficientemente cheio para justificar a atividade de coleta de lixo. Por exemplo, se o programa requer que a atividade de coleta de lixo ocorra apenas uma vez a cada alguns segundos, você provavelmente verá uma pulsação apenas uma vez a cada poucos segundos.

    Caso ocorra um evento como uma coleta de lixo síncrona ou uma mudança de prioridade, os detalhes do evento e quaisquer eventos pendentes, como pulsações, serão imediatamente produzidos como saída.

  • Se o quantum máximo de coleta de lixo para um determinado período for muito grande, você talvez queira reduzir a utilização do destino, usando a opção -Xgc:targetUtilization. Essa ação permite que o Coletor de Lixo tenha mais tempo para trabalhar. Como alternativa, você talvez queira aumentar o tamanho de heap com a opção -Xmx. Da mesma forma, caso o aplicativo possa tolerar atrasos mais longos do que os que estão sendo relatados atualmente, é possível aumentar a utilização do destino ou diminuir o tamanho do heap.
  • A saída pode ser redirecionada para um arquivo de log em vez de para o console, usando a opção -Xverbosegclog:<file>; por exemplo, -Xverbosegclog:out grava a saída de -verbose:gc no arquivo out.
  • A prioridade listada em thread-priority é a prioridade de encadeamento do sistema operacional subjacente, e não uma prioridade de encadeamento Java

Coletas de lixo síncronas

Uma entrada também é gravada no log -verbose:gc quando ocorre uma coleta de lixo síncrona (não determinística). Existem três causas possíveis para esse evento:
  • Uma chamada System.gc() explícita no código.
  • A JVM fica sem memória e, em seguida, executa uma coleta de lixo síncrona para evitar uma condição OutOfMemoryError.
  • A JVM é encerrada durante uma coleta de lixo contínua. A JVM não pode cancelar a coleta, portanto, ela conclui a coleta de forma síncrona e, em seguida, sai.
Um exemplo de uma entrada 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>
Um exemplo de uma entrada de coleta de lixo síncrona como resultado do encerramento da 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>
As identificações XML e os atributos neste exemplo têm os seguintes significados:
< gc-op id="9 "type="syncgc" timems= "6.439" ...
Essa linha indica que o tipo de evento é uma coleta de lixo síncrona. O atributo timems é a duração da coleta de lixo síncrona em milissegundos.
< syncgc-info reason=" ... " />
A causa da coleta de lixo síncrona.
< free-mem-delta .../>
A memória de heap Java livre antes e após a coleta de lixo síncrona em bytes
< finalização .../>
O número de objetos que estão aguardando a finalização.
< classunload-informações .../>
O número de carregadores de classe e classes descarregados durante o intervalo de pulsação.
< references type="weak " cleared="53" .../>
O número e o tipo de objetos de referência Java que foram limpos durante o intervalo de pulsação

A coleta de lixo síncrona devido a condições de falta de memória ou ao encerramento da máquina virtual pode ocorrer apenas quando o Coletor de Lixo está ativo. Ela deve ser precedida por um evento trigger start, embora isso não precise ocorrer imediatamente. Provavelmente ocorrerão alguns eventos de pulsação entre um evento trigger start e o evento synchgc. A coleta de lixo síncrona causada por System.gc() pode ocorrer a qualquer momento.

Rastreando toda as unidades de coleta de lixo

É possível rastrear as unidades de coletas de lixo individuais por meio da ativação dos pontos de rastreio GlobalGCStart e GlobalGCEnd. Esses pontos de rastreio são produzidos no início e no final de toda a atividade do Metronome Garbage Collector, incluindo coletas de lixo síncronas. A saída desses pontos de rastreio é semelhante a:
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 memória

Quando o heap fica sem espaço livre, uma entrada é gravada no log -verbose:gc antes do lançamento da exceção OutOfMemoryError. Um exemplo dessa saída é:
<out-of-memory id="71" timestamp="2011-07-12T10:21:50.135" memorySpaceName="Metronome" 
  memorySpaceAddress="0806DFDC"/>

Por padrão, um Javadump é produzido como resultado de uma exceção OutOfMemoryError. Esse dump contém informações sobre a memória usada pelo programa.

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