Esta página descreve como depurar problemas de correção e desempenho da coleta de lixo (GC) do Android Runtime (ART). Ele explica como usar opções de verificação de GC, identificar soluções para falhas de verificação de GC e medir e resolver problemas de desempenho de GC.
Para trabalhar com ART, consulte as páginas desta seção ART e Dalvik , e o formato Dalvik Executable . Para obter ajuda adicional para verificar o comportamento do aplicativo, consulte Verificando o comportamento do aplicativo no tempo de execução do Android (ART) .
Visão geral do ART GC
O ART possui alguns planos de GC diferentes que consistem na execução de diferentes coletores de lixo. A partir do Android 8 (Oreo), o plano padrão é Cópia Simultânea (CC). O outro plano de GC é Concurrent Mark Sweep (CMS).
Algumas das principais características do GC de cópia simultânea são:
- CC permite o uso de um alocador de ponteiro de colisão chamado RegionTLAB. Isso aloca um buffer de alocação local de thread (TLAB) para cada thread do aplicativo, que pode então alocar objetos fora de seu TLAB batendo no ponteiro "superior", sem qualquer sincronização.
- CC executa a desfragmentação de heap copiando objetos simultaneamente sem pausar os threads do aplicativo. Isto é 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.
- O GC tem apenas uma pequena pausa, que é constante no tempo em relação ao tamanho do heap.
- CC se estende para ser um GC geracional no Android 10 e superior. Permite recolher objetos jovens, que muitas vezes se tornam inacessíveis rapidamente e com pouco esforço. Isso ajuda a aumentar o rendimento do GC e a atrasar consideravelmente a necessidade de executar um GC de heap completo.
O outro GC que o ART ainda suporta é o CMS. Este GC também suporta compactação, mas não simultaneamente. A compactação é evitada até que o aplicativo entre em segundo plano, momento em que os threads do aplicativo são pausados para realizar a compactação. A compactação também se torna necessária quando a alocação de um objeto falha devido à fragmentação. Nesse caso, o aplicativo pode parar de responder por algum tempo.
Como o CMS raramente compacta e, portanto, os objetos livres podem não ser contíguos, ele usa um alocador baseado em lista livre chamado RosAlloc. Possui um custo de alocação maior em comparação ao RegionTLAB. Finalmente, devido à fragmentação interna, o uso de memória para o heap Java pode ser maior para CMS do que para CC.
Verificação de GC e opções de desempenho
Alterando o tipo de GC
Os OEMs podem alterar o tipo de GC. O processo de mudança envolve a configuração da variável de ambiente ART_USE_READ_BARRIER no momento da construção. O valor padrão é verdadeiro, o que ativa o coletor CC, pois utiliza a barreira de leitura. Para CMS esta variável deve ser explicitamente definida como falsa.
Por padrão, o coletor CC é executado em modo geracional no Android 10 e versões posteriores. Para desativar o modo geracional, o argumento de linha de comando -Xgc:nogenerational_cc pode ser usado. Alternativamente, a propriedade do sistema pode ser definida da seguinte forma:
adb shell setprop dalvik.vm.gctype nogenerational_ccO coletor CMS sempre é executado no modo geracional.
Verificando 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. Habilitar a verificação de heap faz com que o GC verifique a exatidão do heap em alguns pontos durante o processo de coleta de lixo. A verificação de heap compartilha as mesmas opções daquelas que alteram 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 é habilitada passando os seguintes valores -Xgc :
- Se ativado,
[no]preverifyexecuta a verificação de heap antes de iniciar o GC. - Se ativado,
[no]presweepingverifyexecuta a verificação de heap antes de iniciar o processo de varredura do coletor de lixo. - Se ativado,
[no]postverifyexecuta a verificação de heap após o GC terminar a varredura. -
[no]preverify_rosalloc,[no]postsweepingverify_rosalloce[no]postverify_rosallocsão opções adicionais de GC que verificam apenas o estado da contabilidade interna do RosAlloc. Portanto, eles são aplicáveis apenas com o coletor CMS, que utiliza o alocador RosAlloc. As principais coisas verificadas são que os valores mágicos correspondem às constantes esperadas e os blocos livres de memória são todos registrados no mapafree_page_runs_.
Desempenho
Existem duas ferramentas principais para medir o desempenho do GC: dumps de temporização do GC e Systrace. Existe também uma versão avançada do Systrace, chamada Perfetto. A maneira visual de medir problemas de desempenho de GC é usar Systrace e Perfetto para determinar quais GCs estão causando longas pausas ou antecipando threads de aplicativos. Embora o ART GC tenha melhorado significativamente ao longo do tempo, o mau comportamento do mutador, como a alocação excessiva, ainda pode causar problemas de desempenho
Estratégia de cobrança
O CC GC coleta executando um GC jovem ou um GC full-heap. Idealmente, o GC jovem é executado com mais frequência. O GC faz coletas CC jovens até que o rendimento (calculado por bytes liberados/segundo de duração do GC) do ciclo de coleta recém-concluído seja menor que o rendimento médio das coleções CC de heap completo. Quando isso ocorre, o CC de heap completo é escolhido para o próximo GC simultâneo em vez do CC jovem. Após a conclusão da coleta de heap completo, o próximo GC volta para o jovem CC. Um fator-chave que faz essa estratégia funcionar é que o CC jovem não ajusta o limite de área ocupada do heap após sua conclusão. Isso faz com que o CC jovem aconteça cada vez com mais frequência até que a taxa de transferência seja menor que o CC de heap completo, o que acaba aumentando o heap.
Usando SIGQUIT para obter informações de desempenho do GC
Para obter os tempos de desempenho do GC para aplicativos, envie SIGQUIT para aplicativos já em execução ou passe -XX:DumpGCPerformanceOnShutdown para dalvikvm ao iniciar um programa de linha de comando. Quando um aplicativo recebe o sinal de solicitação ANR ( SIGQUIT ), ele despeja informações relacionadas a seus bloqueios, pilhas de threads e desempenho de GC.
Para obter dumps de tempo do GC, use:
adb shell kill -s QUIT PID
Isso cria um arquivo (com a data e hora no nome, como anr_2020-07-13-19-23-39-817) em /data/anr/ . Este arquivo contém alguns dumps ANR, bem como tempos de GC. Você pode localizar os tempos de GC pesquisando Dumping cumulativo de tempos de Gc . 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 de se observar. Por 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 não causar perda de frames na maioria dos aplicativos e não deve ser uma preocupação.
Outra área de interesse é o tempo de suspensão, que mede quanto tempo leva para um thread atingir um ponto de suspensão após o GC solicitar a suspensão. Esse tempo está incluído nas pausas do GC, portanto, é útil determinar se pausas longas são causadas pela lentidão do GC ou pela suspensão lenta do thread. Aqui está um exemplo de horário normal para suspensão em um Nexus 5:
suspend all histogram: Sum: 1.513ms 99% C.I. 3us-546.560us Avg: 47.281us Max: 601us
Existem outras áreas de interesse, incluindo o tempo total gasto e o rendimento 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
Aqui está um exemplo de como despejar os tempos de GC de um aplicativo já em execução:
adb shell kill -s QUIT PIDadb pull /data/anr/anr_2020-07-13-19-23-39-817
Neste ponto, os tempos do GC estão dentro de anr_2020-07-13-19-23-39-817 . Aqui está 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 travamentos dentro do ART. Falhas que ocorrem na leitura ou gravação em campos de objeto podem indicar corrupção de heap. Se o GC travar durante a execução, isso também poderá indicar corrupção de heap. A causa mais comum de corrupção de heap é o código do aplicativo incorreto. Felizmente, existem ferramentas para depurar falhas de GC e relacionadas ao heap, incluindo as opções de verificação de heap especificadas acima e CheckJNI.
Verifique JNI
CheckJNI é um modo que adiciona verificações JNI para verificar o comportamento do aplicativo; eles não estão habilitados por padrão por motivos de desempenho. As verificações detectam alguns erros que podem causar corrupção de heap, como o uso de referências locais e globais inválidas/obsoletas. 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 do array. Quando ativado, forcecopy faz com que as funções JNI de acesso ao array retornem cópias com zonas vermelhas. Uma zona vermelha é uma região no final/início do ponteiro retornado que possui um valor especial, que é verificado quando o array é liberado. Se os valores na zona vermelha não corresponderem ao esperado, ocorreu uma sobrecarga ou insuficiência de buffer. Isso faz com que CheckJNI seja abortado. Para ativar o modo de cópia forçada:
adb shell setprop dalvik.vm.jniopts forcecopy
Um exemplo de erro que CheckJNI deve detectar é escrever após o final de um array obtido de GetPrimitiveArrayCritical . Esta operação pode corromper o heap Java. Se a gravação estiver dentro da área da zona vermelha CheckJNI, CheckJNI 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 futura do GC. Se a memória corrompida for um campo de referência, o GC poderá detectar o erro e imprimir o erro Tryed to mark <ptr> not contains by any space .
Este erro ocorre quando o GC tenta marcar um objeto para o qual não consegue encontrar espaço. Após esta verificação falhar, o GC percorre as raízes e tenta ver se o objeto inválido é uma raiz. A partir daqui, existem duas opções: O objeto é raiz ou não raiz.
Exemplo de raiz inválida
Caso o objeto seja uma raiz inválida, ele imprime 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, vreg=1 dentro de com.google.gwt.collections.JavaReadableJsArray.get deve conter uma referência de heap, mas contém um ponteiro inválido de endereço 0x2 . Esta é uma raiz inválida. Para depurar esse problema, use oatdump no arquivo oat e observe o método com a raiz inválida. Nesse caso, o erro acabou sendo um bug do compilador no backend x86. Aqui está a lista de alterações 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 do heap não é uma raiz inválida, é difícil depurar. Esta mensagem de erro indica que havia pelo menos um objeto no heap apontando para o objeto inválido.