Mensagens de log de coleta de lixo Java

96

Eu configurei o java para despejar informações de coleta de lixo nos logs ( verbose GC ). Não tenho certeza do que significam as entradas de coleta de lixo nos logs. Uma amostra dessas entradas está postada abaixo. Eu pesquisei no Google e não encontrei explicações sólidas.

Tenho alguns palpites razoáveis, mas estou procurando respostas que forneçam definições estritas do que significam os números nas entradas, apoiadas por fontes confiáveis. Um +1 automático para todas as respostas que citam documentação solar. Minhas perguntas são:

  1. A que PSYoungGen se refere? Presumo que tenha algo a ver com a geração anterior (mais jovem?), Mas o que exatamente?
  2. Qual é a diferença entre o segundo trio de números e o primeiro?
  3. Por que um nome (PSYoungGen) é especificado para o primeiro trio de números, mas não para o segundo?
  4. O que significa cada número (tamanho da memória) no trio. Por exemplo, em 109884K-> 14201K (139904K), é a memória anterior a GC 109884k e então é reduzida para 14201K. Como o terceiro número é relevante? Por que exigiríamos um segundo conjunto de números?

8109.128: [GC [PSYoungGen: 109884K-> 14201K (139904K)] 691015K-> 595332K (1119040K), 0,0454530 s]

8112.111: [GC [PSYoungGen: 126649K-> 15528K (142336K)] 707780K-> 605892K (1121472K), 0,0934560 segs]

8112,802: [GC [PSYoungGen: 130344K-> 3732K (118592K)] 720708K-> 607895K (1097728K), 0,0682690 segundos]

Ethan Heilman
fonte
heap inteiro, geração jovem parte do heap, gc menor para saber como funciona o gc, verifique, por exemplo, cubrid.org/blog/dev-platform/…
MarianP

Respostas:

90

A maior parte é explicada no Guia de ajuste do GC (que você faria bem em ler de qualquer maneira).

A opção de linha de comando -verbose:gcfaz com que as informações sobre o heap e a coleta de lixo sejam impressas em cada coleta. Por exemplo, aqui está a saída de um grande aplicativo de servidor:

[GC 325407K->83000K(776768K), 0.2300771 secs]
[GC 325816K->83372K(776768K), 0.2454258 secs]
[Full GC 267628K->83769K(776768K), 1.8479984 secs]

Aqui vemos duas coleções menores seguidas por uma coleção principal. Os números antes e depois da seta (por exemplo, 325407K->83000Kda primeira linha) indicam o tamanho combinado dos objetos ativos antes e depois da coleta de lixo, respectivamente. Após coleções secundárias, o tamanho inclui alguns objetos que são lixo (não estão mais vivos), mas que não podem ser recuperados. Esses objetos estão contidos na geração titular ou referenciados nas gerações titulares ou permanentes.

O próximo número entre parênteses (por exemplo, (776768K)novamente na primeira linha) é o tamanho confirmado do heap: a quantidade de espaço utilizável para objetos java sem solicitar mais memória do sistema operacional. Observe que este número não inclui um dos espaços sobreviventes, já que apenas um pode ser usado em um determinado momento, e também não inclui a geração permanente, que contém os metadados usados ​​pela máquina virtual.

O último item da linha (por exemplo, 0.2300771 secs) indica o tempo necessário para realizar a coleta; neste caso, aproximadamente um quarto de segundo.

O formato da coleção principal da terceira linha é semelhante.

O formato da saída produzida por -verbose:gcestá sujeito a alterações em versões futuras.

Eu não tenho certeza porque há um PSYoungGen no seu; você mudou o coletor de lixo?

Michael Myers
fonte
Onde encontrar os arquivos de log gc?
Sr. Lou de
7
Essa resposta realmente não aborda as perguntas originais. Acho que a resposta de Michaeljoseph é melhor. Ele aborda as perguntas feitas por Ethan e faz um trabalho melhor ao analisar o exemplo original. Embora haja dois problemas em sua resposta (seu link agora está morto e rafa.ferreria apontou o outro), ela não regurgita apenas um documento Oracle.
Dirk
127
  1. PSYoungGen refere-se ao coletor de lixo em uso para a coleta secundária. PS significa Parallel Scavenge.
  2. O primeiro conjunto de números são os tamanhos antes / depois da geração jovem e o segundo conjunto é para todo o heap. ( Diagnosticar um problema de coleta de lixo detalha o formato)
  3. O nome indica a geração e o coletor em questão, o segundo conjunto é para todo o heap.

Um exemplo de um GC completo associado também mostra os coletores usados ​​para as gerações antigas e permanentes:

3.757: [Full GC [PSYoungGen: 2672K->0K(35584K)] 
            [ParOldGen: 3225K->5735K(43712K)] 5898K->5735K(79296K) 
            [PSPermGen: 13533K->13516K(27584K)], 0.0860402 secs]

Finalmente, quebrando uma linha de sua saída de registro de exemplo:

8109.128: [GC [PSYoungGen: 109884K->14201K(139904K)] 691015K->595332K(1119040K), 0.0454530 secs]
  • 107Mb usado antes do GC, 14Mb usado depois do GC, tamanho máximo da geração jovem 137Mb
  • Heap de 675 MB usado antes do GC, heap de 581 MB usado depois do GC, tamanho máximo de heap de 1 Gb
  • GC menor ocorreu em 8.109,128 segundos desde o início do JVM e levou 0,04 segundos
michaeljoseph
fonte
8
apenas um pequeno comentário, o valor entre '()' não é o tamanho máximo, para sempre, é o tamanho máximo no momento. Se o GC não puder liberar o heap menos, esse limite, mais espaço será necessário para o sistema operacional e esse valor aumentará. Respeitando claro o limite definido em: -Xmx
rafa.ferreira 03/03/11
@ rafa.ferreira Acho que o valor entre parênteses, ou seja, 1119040K é o tamanho de heap confirmado. Eu não acho que o GC imprime o tamanho do 'heap máximo' em qualquer lugar. Referência 1 e Referência 2
rohitmohta
23

Eu só queria mencionar que é possível obter o log detalhado do GC com o

-XX:+PrintGCDetails 

parâmetro. Então você vê a saída PSYoungGen ou PSPermGen como na resposta.

Também -Xloggc:gc.logparece gerar a mesma saída, -verbose:gcmas você pode especificar um arquivo de saída no primeiro.

Exemplo de uso:

java -Xloggc:./memory.log -XX:+PrintGCDetails Memory

Para visualizar melhor os dados, você pode tentar o gcviewer (uma versão mais recente pode ser encontrada no github ).

Tome cuidado para escrever os parâmetros corretamente, esqueci o "+" e meu JBoss não ligava, sem nenhuma mensagem de erro!

Andrei
fonte
3
Observe que gc.log será sobrescrito quando o java for reiniciado (por exemplo, se você reiniciar seu tomcat porque ele estava tendo problemas de memória e você adoraria ver esse gc.log). Ou pelo menos irá se você girar os logs do GC. Existem muitas outras opções controlando o registro gc. Consulte oracle.com/technetwork/articles/java/vmoptions-jsp-140102.html . Em particular, considere-XX:+PrintGCDateStamps -XX:+PrintGCTimeStamps -XX:+UseGCLogFileRotation -XX:NumberOfGCLogFiles=<some number of files> -XX:GCLogFileSize=<some size> -XX:+PrintTenuringDistribution
Dan Pritts