Depurar a coleta de lixo do ART

Mantenha tudo organizado com as coleções Salve e categorize o conteúdo com base nas suas preferências.

Esta página descreve como depurar problemas de desempenho e precisão da coleta de lixo (GC) do Android Runtime (ART). Ele explica como usar as opções de verificação do GC, identificar soluções para falhas de verificação do GC e medir e resolver problemas de desempenho do GC.

Para trabalhar com o ART, consulte as páginas desta seção ART e Dalvik e o Formato executável do Dalvik. Para mais ajuda na verificação do comportamento do app, consulte Como verificar o comportamento do app no Android Runtime (ART).

Visão geral do GC do ART

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

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

• O CC permite o uso de um alocador de ponteiro de incremento chamado RegionTLAB. Isso aloca um buffer de alocação local da linha de execução (TLAB, na sigla em inglês) para cada linha de execução do app, que pode alocar objetos fora do TLAB ao tocar no ponteiro "superior", sem nenhuma sincronização.
• O CC realiza a desfragmentação do heap copiando objetos simultaneamente sem pausar as linhas de execução do app. Isso é feito com a ajuda de uma barreira de leitura, que intercepta leituras de referência da pilha, sem a necessidade de intervenção do desenvolvedor do app.
• A GC tem apenas uma pequena pausa, que é constante no tempo em relação ao tamanho do heap.
• O CC se estende para ser um GC de geração no Android 10 e versões mais recentes. Ele permite coletar objetos novos, que geralmente se tornam inacessíveis rapidamente, com pouco esforço. Isso ajuda a aumentar o rendimento do GC e a atrasar consideravelmente a necessidade de realizar um GC de pilha completa.

O outro GC que o ART ainda oferece suporte é o CMS. Esse GC também oferece suporte à compactação, mas não simultaneamente. A compactação é evitada até que o app entre 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. Nesse caso, o app pode deixar de responder por algum tempo.

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

Opções de verificação e desempenho do GC

Mudar o tipo de GC

Os OEMs podem mudar o tipo de GC. O processo de mudança envolve definir a variável de ambiente ART_USE_READ_BARRIER no momento do build. O valor padrão é "true", o que ativa o coletor de CC porque ele usa a barreira de leitura. Para CMS, essa variável precisa ser definida explicitamente como "false".

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

adb shell setprop dalvik.vm.gctype nogenerational_cc

Verificar a pilha

A verificação de heap é provavelmente a opção de GC mais útil para depurar erros relacionados ao GC ou corrupção de heap. Ativar a verificação de heap faz com que o GC verifique a correção do heap em alguns pontos durante o processo de coleta de lixo. A verificação de heap compartilha as mesmas opções que mudam 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. A verificação do GC é ativada transmitindo os seguintes valores -Xgc:

• Se ativada, [no]preverify realiza a verificação do heap antes de iniciar o GC.
• Se ativada, [no]presweepingverify realiza a verificação de heap antes de iniciar o processo de varredura do coletor de lixo.
• Se ativado, o [no]postverify vai realizar a verificação do heap depois que o GC terminar a varredura.
• [no]preverify_rosalloc, [no]postsweepingverify_rosalloc e [no]postverify_rosalloc são outras opções de GC que verificam apenas o estado da contabilidade interna do RosAlloc. Portanto, elas só são aplicáveis ao coletor do CMS, que usa o alocador RosAlloc. As principais coisas verificadas são que os valores mágicos correspondem às constantes esperadas, e blocos de memória livres são registrados no mapa free_page_runs_.

Desempenho

Há duas ferramentas principais para medir o desempenho do GC, despejos de tempo do GC e Systrace. Há também uma versão avançada do Systrace, chamada Perfetto. A maneira visual de medir problemas de desempenho do GC é usar o Systrace e o Perfetto para determinar quais GCs estão causando pausas longas ou interrompendo linhas de execução do app. Embora o GC do ART tenha melhorado significativamente ao longo do tempo, um comportamento de mutador ruim, como a alocação excessiva, ainda pode causar problemas de desempenho.

Estratégia de cobrança

O GC de CC coleta executando um GC jovem ou um GC de pilha total. O ideal é que o GC jovem seja executado com mais frequência. O GC faz coletas de CC jovens até que a taxa de transferência (calculada por bytes liberados/segundo da duração do GC) do ciclo de coleta acabado seja menor que a taxa de transferência média de coletas de CC de heap completo. Quando isso ocorre, a CC de pilha cheia é escolhida para o próximo GC simultâneo em vez da CC jovem. Depois que a coleta de pilha completa é concluída, a próxima GC é alternada de volta para a CC jovem. Um dos principais fatores que fazem essa estratégia funcionar é que o CC jovem não ajusta o limite de espaço de heap depois de concluído. Isso faz com que a CC jovem aconteça com mais frequência até que a taxa de transferência seja menor que a CC de pilha completa, o que acaba aumentando a pilha.

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

Para receber os tempos de desempenho do GC para apps, envie SIGQUIT para apps em execução ou transmita -XX:DumpGCPerformanceOnShutdown para dalvikvm ao iniciar um programa de linha de comando. Quando um app recebe o sinal de solicitação de ANR (SIGQUIT), ele descarta informações relacionadas a bloqueios, pilhas de linhas de execução e desempenho do GC.

Para acessar despejos de tempo do GC, use:

adb shell kill -s QUIT PID

Isso cria um arquivo (com a data e a hora no nome, como anr_2020-07-13-19-23-39-817) em /data/anr/. Esse arquivo contém alguns despejos de ANR e tempos de GC. Você pode localizar os tempos de GC pesquisando Dumping cumulative Gc timings. Esses tempos mostram algumas coisas que podem ser interessantes, incluindo as informações do histograma para as fases e pausas de cada tipo de GC. As pausas geralmente são mais importantes para analisar. 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 é baixo o suficiente para não causar frames perdidos na maioria dos apps e não deve ser uma preocupação.

Outra área de interesse é o tempo de suspensão, que mede quanto tempo uma linha de execução leva para alcançar um ponto de suspensão após as solicitações de GC que ela suspende. Esse tempo é incluído nas pausas do GC. Por isso, é útil determinar se pausas longas são causadas pela lentidão do GC ou pela suspensão lenta da linha de execução. Confira um exemplo de tempo normal para suspender 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 a taxa de transferência do GC. 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 ponto, os tempos de 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 do GC

Várias coisas podem causar falhas na ART. As falhas que ocorrem ao ler ou gravar em campos de objetos podem indicar corrupção do heap. Se o GC falhar durante a execução, isso também poderá indicar corrupção do heap. A causa mais comum de corrupção de heap é um código de app incorreto. Felizmente, há ferramentas para depurar falhas relacionadas ao GC e ao heap, incluindo as opções de verificação de heap especificadas acima e o CheckJNI.

CheckJNI

O CheckJNI é um modo que adiciona verificações da JNI para verificar o comportamento do app. Elas não são ativadas por padrão por motivos de desempenho. As verificações detectam alguns erros que podem causar corrupção do 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ções após o final das regiões de matriz. Quando ativada, a força de cópia faz com que as funções JNI de acesso à matriz retornem cópias com zonas vermelhas. Uma zona vermelha é uma região no início/final do ponteiro retornado que tem um valor especial, que é verificado quando a matriz é liberada. Se os valores na zona vermelha não corresponderem ao esperado, ocorreu um estouro de buffer ou uma execução insuficiente. Isso faz com que o CheckJNI seja abortado. Para ativar o modo de cópia forçada:

adb shell setprop dalvik.vm.jniopts forcecopy

Um exemplo de erro que o CheckJNI precisa detectar é gravar após o fim de uma matriz obtida em GetPrimitiveArrayCritical. Essa operação pode corromper o heap do Java. Se a gravação estiver na área da zona vermelha do CheckJNI, o CheckJNI vai detectar o problema quando o ReleasePrimitiveArrayCritical correspondente for chamado. Caso contrário, a gravação corrompe algum objeto aleatório no heap Java e pode causar uma falha de GC futura. Se a memória corrompida for um campo de referência, o GC poderá detectar o erro e imprimir o erro Tried to mark <ptr> not contained by any spaces.

Esse erro ocorre quando o GC tenta marcar um objeto para o qual não é possível encontrar um espaço. Depois que essa verificação falha, o GC percorre as raízes e tenta verificar se o objeto inválido é uma raiz. Aqui, há duas opções: O objeto é raiz ou não raiz.

Exemplo de raiz inválida

No caso em que o objeto é uma raiz inválida, ele mostra algumas 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

Nesse caso, o vreg=1 dentro de com.google.gwt.collections.JavaReadableJsArray.get precisa ter uma referência de heap, mas contém um ponteiro inválido do endereço 0x2. Raiz inválida. Para depurar esse problema, use oatdump no arquivo oat e procure o método com a raiz inválida. Nesse caso, o erro era um bug do compilador no back-end x86. Confira 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, a saída será semelhante às seguintes 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 de heap não é uma raiz inválida, é difícil depurar. Essa mensagem de erro indica que pelo menos um objeto na pilha estava apontando para o objeto inválido.