Depurar a coleta de lixo do ART

Esta página descreve como depurar a coleta de lixo do Android Runtime (ART) (GC). Explica como usar a verificação de GC identificar soluções para falhas na verificação de GC e medir e resolver problemas de desempenho do GC.

Para trabalhar com o ART, consulte as páginas desta página ART e Dalvik e o formato Dalvik Executable. Se precisar de mais ajuda para verificar o comportamento do app, consulte Verificando comportamento do app no Android Runtime (ART).

Visão geral da GC da ART

O ART tem alguns planos de GC diferentes que consistem em executar diferentes coletores. A partir do Android 8 (Oreo), o plano padrão é a cópia simultânea (CC, na sigla em inglês). O outro plano de coleta de lixo é a limpeza simultânea de marca (CMS, na sigla em inglês).

Algumas das principais características da GC de cópia simultânea são:

  • O CC permite o uso de um alocador de ponteiro de promoção chamado RegionTLAB. Isso aloca uma linha de execução local para cada linha de execução do app, que pode alocar objetos fora do TLAB batendo o "topo" sem qualquer sincronização.
  • O CC realiza a desfragmentação de heap copiando objetos simultaneamente sem pausar as linhas de execução do aplicativo. Isso é conseguido com a ajuda de uma barreira de leitura que intercepta leituras de referência do heap, sem a necessidade de qualquer intervenção do desenvolvedor do aplicativo.
  • A GC tem apenas uma pequena pausa, que é constante no tempo em relação ao tamanho da heap.
  • A CC se estende para ser uma GC geracional no Android 10 e versões mais recentes. Ele permite coletar objetos jovens, que muitas vezes se tornam inacessíveis rapidamente, com pouco esforço. Isso ajuda aumentando a capacidade de processamento de GC e atrasando consideravelmente a necessidade de realizar uma GC de heap completa.

O outro GC que o ART ainda aceita é o CMS. Isso O GC também oferece suporte à compactação, mas não simultaneamente. A compactação deve ser evitada até que o app entra em segundo plano, momento em que as linhas de execução do app são pausadas para realizar a compactação. A compactação também se torna necessária quando uma alocação de objeto falha devido à fragmentação. Neste caso o app possa parar de responder por algum tempo.

Como o CMS raramente se compacta e, portanto, os objetos livres podem não ser contíguos, ele usa uma alocador baseado em lista livre chamado RosAlloc. Ele tem um custo de alocação maior em comparação ao RegionTLAB. Por fim, devido à fragmentação interna, o uso de memória para a heap Java pode ser maior no CMS do que na CC.

Verificação de GC e opções de performance

Mudar o tipo de GC

OEMs podem mudar o tipo de GC. O processo de mudança envolve a configuração da variável de ambiente ART_USE_READ_BARRIER no tempo de build. O valor padrão é verdadeiro, o que ativa o coletor de CC porque usa a barreira de leitura. Para o CMS, deve ser definida explicitamente como falsa.

Por padrão, o coletor CC é executado no modo geracional no Android 10 e versões mais recentes. Para desativar o modo geracional, o argumento de linha de comando -Xgc:nogenerational_cc poderá ser usados. Como alternativa, a propriedade do sistema pode ser definida da seguinte maneira:

adb shell setprop dalvik.vm.gctype nogenerational_cc
O coletor de CMS sempre é executado no modo geracional.

Verificar a heap

A verificação de heap é provavelmente a opção de GC mais útil para depuração Erros relacionados a GC ou corrupção de heap. Ativar a verificação de heap faz com que a GC para verificar a exatidão da heap em alguns pontos durante a o processo de coleta de dados. A verificação de heap compartilha as mesmas opções que as alterar o tipo de GC. Se ativada, a verificação de heap verifica as raízes e garante que os objetos acessíveis façam referência apenas a outros objetos acessíveis. coleta de lixo (GC) a verificação é ativada transmitindo os seguintes valores -Xgc:

  • Se ativado, o [no]preverify executa a verificação de heap antes de iniciar a GC.
  • Se ativado, o [no]presweepingverify executa a verificação de heap antes de iniciar o processo de varredura do coletor de lixo.
  • Se ativado, o [no]postverify executa a verificação de heap após a coleta de lixo conclui a varredura.
  • [no]preverify_rosalloc, [no]postsweepingverify_rosalloc e [no]postverify_rosalloc são opções adicionais de GC que verificam somente o estado da contabilidade interna da RosAlloc. Portanto, elas são aplicáveis apenas o coletor de CMS, que usa o alocador RosAlloc. Os principais itens verificados são que os valores mágicos correspondam às constantes esperadas e que os blocos livres de memória sejam registrados no mapa free_page_runs_.

Desempenho

Há duas ferramentas principais para medir o desempenho do GC, o tempo dele dumps e Systrace. Há também uma versão avançada do Systrace, chamada Perfetto. A forma visual de medir problemas de desempenho do GC é usar o Systrace e o Perfetto para determinar quais GCs estão causando pausas longas ou a forçar linhas de execução do app. Embora a coleta de lixo da ART tenha melhorado significativamente ao longo do tempo, uma má estrutura como alocação excessiva, ainda podem causar problemas de desempenho

Estratégia de coleta

O GC do CC é coletado executando uma GC nova ou de todo o heap. Idealmente, o coletor de lixo (GC) jovem seja executada com mais frequência. O GC realiza coletas novas de CC até a capacidade (calculada por bytes) liberados/segundo de duração da GC) do ciclo de coleta recém-finalizado é menor que a capacidade média de coleções de CC de todo o heap. Quando isso ocorre, o CC com heap completo é escolhido para o próximo GC simultânea em vez de CC jovem. Depois que a coleta de heap completa for concluída, O GC é alterado de volta para o CC jovem. Um fator importante que faz essa estratégia funcionar é que o jovem CC não ajusta o limite de consumo de heap após a conclusão. Isso faz com que o CC jovem aconteça mais e com mais frequência até que a capacidade de processamento seja menor do que a de CC com heap completa, o que acaba aumentando o heap.

Usar SIGQUIT para obter informações de desempenho do GC

Para acessar os tempos de desempenho da coleta de lixo para apps, envie SIGQUIT para já estão em execução ou transmitir -XX:DumpGCPerformanceOnShutdown como dalvikvm ao iniciar um programa de linha de comando. Quando um app recebe o indicador de solicitação de ANR (SIGQUIT), ele despeja informações relacionadas aos bloqueios, pilhas de linhas de execução e o desempenho do GC.

Para obter despejos de tempo de GC, use:

adb shell kill -s QUIT PID

Isso cria um arquivo (com a data e a hora no nome, por exemplo, anr_2020-07-13-19-23-39-817) em /data/anr/. Isso contém alguns despejos de ANR e marcações de tempo de GC. Você pode localizar Tempos de GC pesquisando por Tempos de Gc cumulativos. Esses tempos mostrar alguns itens que podem ser interessantes, incluindo as informações do histograma de as fases e pausas de cada tipo de GC. É mais importante analisar as pausas Exemplo:

young concurrent copying paused:	Sum: 5.491ms 99% C.I. 1.464ms-2.133ms Avg: 1.830ms Max: 2.133ms

Isso mostra que a pausa média foi de 1,83 ms, o que deve ser baixo o suficiente para ela não causa perda de frames na maioria dos apps e não deve ser uma preocupação.

Outra área de interesse é a hora da suspensão, o que mede quanto tempo uma linha de execução leva para chegar a um ponto de suspensão após o GC solicitar que ela é suspensa. Esse tempo está incluído nas pausas de GC, por isso é útil determinar se pausas longas são causadas pela GC lenta ou pelo thread suspendendo lentamente. Este é um exemplo de tempo normal para a suspensão em um Nexus 5:

suspend all histogram:	Sum: 1.513ms 99% C.I. 3us-546.560us Avg: 47.281us Max: 601us

Há outras áreas de interesse, incluindo o tempo total gasto e o GC e aumentar a capacidade de processamento. Exemplos:

Total time spent in GC: 502.251ms
Mean GC size throughput: 92MB/s
Mean GC object throughput: 1.54702e+06 objects/s

Confira um exemplo de como despejar os tempos de GC de um app que já está em execução:

adb shell kill -s QUIT PID
adb pull /data/anr/anr_2020-07-13-19-23-39-817

Nesse momento, os tempos da GC estão dentro de anr_2020-07-13-19-23-39-817. Confira um exemplo de saída do Google Maps:

Start Dumping histograms for 2195 iterations for concurrent copying
MarkingPhase:   Sum: 258.127s 99% C.I. 58.854ms-352.575ms Avg: 117.651ms Max: 641.940ms
ScanCardsForSpace:      Sum: 85.966s 99% C.I. 15.121ms-112.080ms Avg: 39.164ms Max: 662.555ms
ScanImmuneSpaces:       Sum: 79.066s 99% C.I. 7.614ms-57.658ms Avg: 18.014ms Max: 546.276ms
ProcessMarkStack:       Sum: 49.308s 99% C.I. 6.439ms-81.640ms Avg: 22.464ms Max: 638.448ms
ClearFromSpace: Sum: 35.068s 99% C.I. 6.522ms-40.040ms Avg: 15.976ms Max: 633.665ms
SweepSystemWeaks:       Sum: 14.209s 99% C.I. 3.224ms-15.210ms Avg: 6.473ms Max: 201.738ms
CaptureThreadRootsForMarking:   Sum: 11.067s 99% C.I. 0.835ms-13.902ms Avg: 5.044ms Max: 25.565ms
VisitConcurrentRoots:   Sum: 8.588s 99% C.I. 1.260ms-8.547ms Avg: 1.956ms Max: 231.593ms
ProcessReferences:      Sum: 7.868s 99% C.I. 0.002ms-8.336ms Avg: 1.792ms Max: 17.376ms
EnqueueFinalizerReferences:     Sum: 3.976s 99% C.I. 0.691ms-8.005ms Avg: 1.811ms Max: 16.540ms
GrayAllDirtyImmuneObjects:      Sum: 3.721s 99% C.I. 0.622ms-6.702ms Avg: 1.695ms Max: 14.893ms
SweepLargeObjects:      Sum: 3.202s 99% C.I. 0.032ms-6.388ms Avg: 1.458ms Max: 549.851ms
FlipOtherThreads:       Sum: 2.265s 99% C.I. 0.487ms-3.702ms Avg: 1.031ms Max: 6.327ms
VisitNonThreadRoots:    Sum: 1.883s 99% C.I. 45us-3207.333us Avg: 429.210us Max: 27524us
InitializePhase:        Sum: 1.624s 99% C.I. 231.171us-2751.250us Avg: 740.220us Max: 6961us
ForwardSoftReferences:  Sum: 1.071s 99% C.I. 215.113us-2175.625us Avg: 488.362us Max: 7441us
ReclaimPhase:   Sum: 490.854ms 99% C.I. 32.029us-6373.807us Avg: 223.623us Max: 362851us
EmptyRBMarkBitStack:    Sum: 479.736ms 99% C.I. 11us-3202.500us Avg: 218.558us Max: 13652us
CopyingPhase:   Sum: 399.163ms 99% C.I. 24us-4602.500us Avg: 181.851us Max: 22865us
ThreadListFlip: Sum: 295.609ms 99% C.I. 15us-2134.999us Avg: 134.673us Max: 13578us
ResumeRunnableThreads:  Sum: 238.329ms 99% C.I. 5us-2351.250us Avg: 108.578us Max: 10539us
ResumeOtherThreads:     Sum: 207.915ms 99% C.I. 1.072us-3602.499us Avg: 94.722us Max: 14179us
RecordFree:     Sum: 188.009ms 99% C.I. 64us-312.812us Avg: 85.653us Max: 2709us
MarkZygoteLargeObjects: Sum: 133.301ms 99% C.I. 12us-734.999us Avg: 60.729us Max: 10169us
MarkStackAsLive:        Sum: 127.554ms 99% C.I. 13us-417.083us Avg: 58.111us Max: 1728us
FlipThreadRoots:        Sum: 126.119ms 99% C.I. 1.028us-3202.499us Avg: 57.457us Max: 11412us
SweepAllocSpace:        Sum: 117.761ms 99% C.I. 24us-400.624us Avg: 53.649us Max: 1541us
SwapBitmaps:    Sum: 56.301ms 99% C.I. 10us-125.312us Avg: 25.649us Max: 1475us
(Paused)GrayAllNewlyDirtyImmuneObjects: Sum: 33.047ms 99% C.I. 9us-49.931us Avg: 15.055us Max: 72us
(Paused)SetFromSpace:   Sum: 11.651ms 99% C.I. 2us-49.772us Avg: 5.307us Max: 71us
(Paused)FlipCallback:   Sum: 7.693ms 99% C.I. 2us-32us Avg: 3.504us Max: 32us
(Paused)ClearCards:     Sum: 6.371ms 99% C.I. 250ns-49753ns Avg: 207ns Max: 188000ns
Sweep:  Sum: 5.793ms 99% C.I. 1us-49.818us Avg: 2.639us Max: 93us
UnBindBitmaps:  Sum: 5.255ms 99% C.I. 1us-31us Avg: 2.394us Max: 31us
Done Dumping histograms
concurrent copying paused:      Sum: 315.249ms 99% C.I. 49us-1378.125us Avg: 143.621us Max: 7722us
concurrent copying freed-bytes: Avg: 34MB Max: 54MB Min: 2062KB
Freed-bytes histogram: 0:4,5120:5,10240:19,15360:69,20480:167,25600:364,30720:529,35840:405,40960:284,46080:311,51200:38
concurrent copying total time: 569.947s mean time: 259.657ms
concurrent copying freed: 1453160493 objects with total size 74GB
concurrent copying throughput: 2.54964e+06/s / 134MB/s  per cpu-time: 157655668/s / 150MB/s
Average major GC reclaim bytes ratio 0.486928 over 2195 GC cycles
Average major GC copied live bytes ratio 0.0894662 over 2199 major GCs
Cumulative bytes moved 6586367960
Cumulative objects moved 127490240
Peak regions allocated 376 (94MB) / 2048 (512MB)
Start Dumping histograms for 685 iterations for young concurrent copying
ScanCardsForSpace:      Sum: 26.288s 99% C.I. 8.617ms-77.759ms Avg: 38.377ms Max: 432.991ms
ProcessMarkStack:       Sum: 21.829s 99% C.I. 2.116ms-71.119ms Avg: 31.868ms Max: 98.679ms
ClearFromSpace: Sum: 19.420s 99% C.I. 5.480ms-50.293ms Avg: 28.351ms Max: 507.330ms
ScanImmuneSpaces:       Sum: 9.968s 99% C.I. 8.155ms-30.639ms Avg: 14.552ms Max: 46.676ms
SweepSystemWeaks:       Sum: 6.741s 99% C.I. 3.655ms-14.715ms Avg: 9.841ms Max: 22.142ms
GrayAllDirtyImmuneObjects:      Sum: 4.466s 99% C.I. 0.584ms-14.315ms Avg: 6.519ms Max: 24.355ms
FlipOtherThreads:       Sum: 3.672s 99% C.I. 0.631ms-16.630ms Avg: 5.361ms Max: 18.513ms
ProcessReferences:      Sum: 2.806s 99% C.I. 0.001ms-9.459ms Avg: 2.048ms Max: 11.951ms
EnqueueFinalizerReferences:     Sum: 1.857s 99% C.I. 0.424ms-8.609ms Avg: 2.711ms Max: 24.063ms
VisitConcurrentRoots:   Sum: 1.094s 99% C.I. 1.306ms-5.357ms Avg: 1.598ms Max: 6.831ms
SweepArray:     Sum: 711.032ms 99% C.I. 0.022ms-3.502ms Avg: 1.038ms Max: 7.307ms
InitializePhase:        Sum: 667.346ms 99% C.I. 303us-2643.749us Avg: 974.227us Max: 3199us
VisitNonThreadRoots:    Sum: 388.145ms 99% C.I. 103.911us-1385.833us Avg: 566.635us Max: 5374us
ThreadListFlip: Sum: 202.730ms 99% C.I. 18us-2414.999us Avg: 295.956us Max: 6780us
EmptyRBMarkBitStack:    Sum: 132.934ms 99% C.I. 8us-1757.499us Avg: 194.064us Max: 8495us
ResumeRunnableThreads:  Sum: 109.593ms 99% C.I. 6us-4719.999us Avg: 159.989us Max: 11106us
ResumeOtherThreads:     Sum: 86.733ms 99% C.I. 3us-4114.999us Avg: 126.617us Max: 19332us
ForwardSoftReferences:  Sum: 69.686ms 99% C.I. 14us-2014.999us Avg: 101.731us Max: 4723us
RecordFree:     Sum: 58.889ms 99% C.I. 0.500us-185.833us Avg: 42.984us Max: 769us
FlipThreadRoots:        Sum: 58.540ms 99% C.I. 1.034us-4314.999us Avg: 85.459us Max: 10224us
CopyingPhase:   Sum: 52.227ms 99% C.I. 26us-728.749us Avg: 76.243us Max: 2060us
ReclaimPhase:   Sum: 37.207ms 99% C.I. 7us-2322.499us Avg: 54.316us Max: 3826us
(Paused)GrayAllNewlyDirtyImmuneObjects: Sum: 23.859ms 99% C.I. 11us-98.917us Avg: 34.830us Max: 128us
FreeList:       Sum: 20.376ms 99% C.I. 2us-188.875us Avg: 29.573us Max: 998us
MarkZygoteLargeObjects: Sum: 18.970ms 99% C.I. 4us-115.749us Avg: 27.693us Max: 122us
(Paused)SetFromSpace:   Sum: 12.331ms 99% C.I. 3us-94.226us Avg: 18.001us Max: 109us
SwapBitmaps:    Sum: 11.761ms 99% C.I. 5us-49.968us Avg: 17.169us Max: 67us
ResetStack:     Sum: 4.317ms 99% C.I. 1us-64.374us Avg: 6.302us Max: 190us
UnBindBitmaps:  Sum: 3.803ms 99% C.I. 4us-49.822us Avg: 5.551us Max: 70us
(Paused)ClearCards:     Sum: 3.336ms 99% C.I. 250ns-7000ns Avg: 347ns Max: 7000ns
(Paused)FlipCallback:   Sum: 3.082ms 99% C.I. 1us-30us Avg: 4.499us Max: 30us
Done Dumping histograms
young concurrent copying paused:        Sum: 229.314ms 99% C.I. 37us-2287.499us Avg: 334.764us Max: 6850us
young concurrent copying freed-bytes: Avg: 44MB Max: 50MB Min: 9132KB
Freed-bytes histogram: 5120:1,15360:1,20480:6,25600:1,30720:1,35840:9,40960:235,46080:427,51200:4
young concurrent copying total time: 100.823s mean time: 147.187ms
young concurrent copying freed: 519927309 objects with total size 30GB
young concurrent copying throughput: 5.15683e+06/s / 304MB/s  per cpu-time: 333152554/s / 317MB/s
Average minor GC reclaim bytes ratio 0.52381 over 685 GC cycles
Average minor GC copied live bytes ratio 0.0512109 over 685 minor GCs
Cumulative bytes moved 1542000944
Cumulative objects moved 28393168
Peak regions allocated 376 (94MB) / 2048 (512MB)
Total time spent in GC: 670.771s
Mean GC size throughput: 159MB/s per cpu-time: 177MB/s
Mean GC object throughput: 2.94152e+06 objects/s
Total number of allocations 1974199562
Total bytes allocated 104GB
Total bytes freed 104GB
Free memory 10MB
Free memory until GC 10MB
Free memory until OOME 442MB
Total memory 80MB
Max memory 512MB
Zygote space size 2780KB
Total mutator paused time: 544.563ms
Total time waiting for GC to complete: 117.494ms
Total GC count: 2880
Total GC time: 670.771s
Total blocking GC count: 1
Total blocking GC time: 86.373ms
Histogram of GC count per 10000 ms: 0:259879,1:2828,2:24,3:1
Histogram of blocking GC count per 10000 ms: 0:262731,1:1
Native bytes total: 30599192 registered: 8947416
Total native bytes at last GC: 30344912

Ferramentas para analisar problemas de correção de GC

Várias coisas podem causar falhas no ART. Falhas que ocorrer leitura ou gravação em campos de objeto podem indicar corrupção de heap. Se o O GC trava quando está em execução e também pode apontar para corrupção da pilha. A causa mais comum de corrupção de heap é o código incorreto do app. Felizmente, existem ferramentas para depurar GC e falhas relacionadas à heap, incluindo as opções de verificação especificadas acima e CheckJNI.

CheckJNI

CheckJNI é um modo que adiciona verificações de JNI para conferir o comportamento do app. eles não são ativados pelo padrão por motivos de desempenho. As verificações capturam alguns erros que podem corromper a heap, como o uso de referências locais e globais inválidas/desatualizadas. Para ativar o CheckJNI:

adb shell setprop dalvik.vm.checkjni true

O modo forcecopy do CheckJNI é útil para detectar grava após o final das regiões da matriz. Quando ativado, "forcecopy" faz com que a matriz acessar funções JNI para retornar cópias com zonas vermelhas. Um vermelho zona é uma região no final/início do ponteiro retornado que tem um valor especial, que é verificado quando a matriz é liberada. Se os valores em a zona vermelha não corresponde ao esperado, um buffer excedido ou insuficiente. Isso faz com que CheckJNI seja cancelado. Para ativar modo forcecopy:

adb shell setprop dalvik.vm.jniopts forcecopy

Um exemplo de erro que o CheckJNI deve detectar é gravar após o fim do uma matriz recebida de GetPrimitiveArrayCritical. Essa operação pode corromper a heap Java. Se a gravação for dentro da área da zona vermelha do CheckJNI, o CheckJNI detectará o problema quando o ReleasePrimitiveArrayCritical correspondente é chamado. Caso contrário, a gravação corrompe algum objeto aleatório na heap Java e pode causar uma futura falha do GC. Se a memória corrompida é um campo de referência, o GC pode capturar o erro e imprimir o erro Tried to marcar <ptr> não incluídos em espaços.

Esse erro ocorre quando o GC tenta marcar um objeto que não pode encontrar um espaço. Quando a verificação falha, a GC passa pelas raízes e tenta verifique se o objeto inválido é uma raiz. A partir daqui, há duas opções: O objeto é uma raiz ou um objeto não raiz.

Exemplo de raiz inválido

No caso de o objeto ser uma raiz inválida, será gerado um informações úteis: art E 5955 5955 art/runtime/gc/collector/mark_sweep.cc:383] Tried to mark 0x2 not contained by any spaces

art E  5955  5955 art/runtime/gc/collector/mark_sweep.cc:384] Attempting see if
it's a bad root
art E  5955  5955 art/runtime/gc/collector/mark_sweep.cc:485] Found invalid
root: 0x2
art E  5955  5955 art/runtime/gc/collector/mark_sweep.cc:486]
Type=RootJavaFrame thread_id=1 location=Visiting method 'java.lang.Object
com.google.gwt.collections.JavaReadableJsArray.get(int)' at dex PC 0x0002
(native PC 0xf19609d9) vreg=1

Neste caso, vreg=1 com.google.gwt.collections.JavaReadableJsArray.get é deve conter uma referência de heap, mas contém um ponteiro inválido do endereço 0x2. Essa é uma raiz inválida. Para depure esse problema, use oatdump no arquivo oat e procure no método com a raiz inválida. Nesse caso, o erro ocorreu ser um bug do compilador no back-end x86. Esta é a lista de mudanças que corrigiu o problema: https://android-review.googlesource.com/#/c/133932/

Exemplo de objeto corrompido

Se o objeto não for uma raiz, gere uma saída semelhante a esta impressões:

01-15 12:38:00.196  1217  1238 E art     : Attempting see if it's a bad root
01-15 12:38:00.196  1217  1238 F art     :
art/runtime/gc/collector/mark_sweep.cc:381] Can't mark invalid object

Quando a corrupção da heap não é uma raiz inválida, é difícil depurar. Esta mensagem de erro indica que havia pelo menos um objeto na heap que apontava para o objeto inválido.