Déboguer le garbage collection ART

Cette page décrit comment déboguer les problèmes d'exactitude et de performances du garbage collection (GC) d'Android Runtime (ART). Il explique comment utiliser les options de vérification du GC, identifier les solutions aux échecs de vérification du GC, ainsi que mesurer et résoudre les problèmes de performances du GC.

Pour travailler avec ART, consultez les pages de cette section ART et Dalvik , ainsi que le format Dalvik Executable . Pour obtenir une aide supplémentaire sur la vérification du comportement de l'application, consultez Vérification du comportement de l'application sur le runtime Android (ART) .

Aperçu de l'ART GC

ART a quelques plans GC différents qui consistent à exécuter différents éboueurs. À partir d'Android 8 (Oreo), le plan par défaut est Concurrent Copying (CC). L’autre plan GC est Concurrent Mark Sweep (CMS).

Certaines des principales caractéristiques de Concurrent Copying GC sont :

• CC permet d'utiliser un allocateur de pointeur de déplacement appelé RegionTLAB. Cela alloue un tampon d'allocation local de thread (TLAB) à chaque thread d'application, qui peut ensuite allouer des objets hors de son TLAB en déplaçant le pointeur « top », sans aucune synchronisation.
• CC effectue une défragmentation du tas en copiant simultanément les objets sans interrompre les threads de l'application. Ceci est réalisé à l'aide d'une barrière de lecture qui intercepte les lectures de référence à partir du tas, sans aucune intervention du développeur de l'application.
• GC n'a qu'une petite pause, constante dans le temps en fonction de la taille du tas.
• CC s'étend pour devenir un GC générationnel dans Android 10 et supérieur. Il permet de récupérer des objets jeunes, qui deviennent souvent inaccessibles assez rapidement et avec peu d'effort. Cela aide en augmentant le débit du GC et en retardant considérablement la nécessité d'effectuer un GC complet.

L’autre GC que ART prend toujours en charge est CMS. Ce GC prend également en charge le compactage, mais pas simultanément. Le compactage est évité jusqu'à ce que l'application passe en arrière-plan, moment auquel les threads de l'application sont mis en pause pour effectuer le compactage. Le compactage devient également nécessaire lorsqu'une allocation d'objet échoue en raison d'une fragmentation. Dans ce cas, l’application peut ne plus répondre pendant un certain temps.

Étant donné que le CMS compacte rarement et que les objets libres peuvent donc ne pas être contigus, il utilise un allocateur basé sur une liste libre appelé RosAlloc. Son coût d’allocation est plus élevé que celui de RegionTLAB. Enfin, en raison de la fragmentation interne, l'utilisation de la mémoire pour le tas Java peut être plus élevée pour CMS que pour CC.

Options de vérification et de performances GC

Changer le type de GC

Les OEM peuvent modifier le type de GC. Le processus de modification implique la définition de la variable d'environnement ART_USE_READ_BARRIER au moment de la construction. La valeur par défaut est true, ce qui active le collecteur CC lorsqu'il utilise la barrière de lecture. Pour CMS, cette variable doit être explicitement définie sur false.

Par défaut, le collecteur CC s'exécute en mode générationnel sous Android 10 et versions ultérieures. Pour désactiver le mode générationnel, l'argument de ligne de commande -Xgc:nogenerational_cc peut être utilisé. Alternativement, la propriété système peut être définie comme suit :

adb shell setprop dalvik.vm.gctype nogenerational_cc

Le collecteur CMS s'exécute toujours en mode générationnel.

Vérifier le tas

La vérification du tas est probablement l'option GC la plus utile pour déboguer les erreurs liées au GC ou la corruption du tas. L'activation de la vérification du tas amène le GC à vérifier l'exactitude du tas à quelques moments du processus de récupération de place. La vérification du tas partage les mêmes options que celles qui modifient le type GC. Si elle est activée, la vérification du tas vérifie les racines et garantit que les objets accessibles font référence uniquement à d'autres objets accessibles. La vérification GC est activée en transmettant les valeurs -Xgc suivantes :

• S'il est activé, [no]preverify effectue une vérification du tas avant de démarrer le GC.
• S'il est activé, [no]presweepingverify effectue une vérification du tas avant de démarrer le processus de balayage du garbage collector.
• S'il est activé, [no]postverify effectue une vérification du tas une fois le balayage du GC terminé.
• [no]preverify_rosalloc , [no]postsweepingverify_rosalloc et [no]postverify_rosalloc sont des options GC supplémentaires qui vérifient uniquement l'état de la comptabilité interne de RosAlloc. Par conséquent, ils ne sont applicables qu’avec le collecteur CMS, qui utilise l’allocateur RosAlloc. Les principales choses vérifiées sont que les valeurs magiques correspondent aux constantes attendues et que les blocs de mémoire libres sont tous enregistrés dans la carte free_page_runs_ .

Performance

Il existe deux outils principaux pour mesurer les performances du GC : les vidages de synchronisation du GC et Systrace. Il existe également une version avancée de Systrace, appelée Perfetto. La manière visuelle de mesurer les problèmes de performances du GC consiste à utiliser Systrace et Perfetto pour déterminer quels GC provoquent de longues pauses ou préemptent les threads d'application. Bien que l'ART GC se soit considérablement amélioré au fil du temps, un mauvais comportement du mutateur, tel qu'une allocation excessive, peut toujours entraîner des problèmes de performances.

Stratégie de collecte

Le CC GC collecte en exécutant un jeune GC ou un GC complet. Idéalement, le jeune GC est exécuté plus souvent. Le GC effectue de jeunes collections CC jusqu'à ce que le débit (calculé en octets libérés/seconde de durée du GC) du cycle de collecte qui vient de se terminer soit inférieur au débit moyen des collections CC complètes. Lorsque cela se produit, le CC complet est choisi pour le prochain GC concurrent au lieu du jeune CC. Une fois la collecte complète du tas terminée, le GC suivant revient au jeune CC. Un facteur clé qui fait que cette stratégie fonctionne est que le jeune CC n'ajuste pas la limite d'empreinte du tas une fois son exécution terminée. Cela amène les jeunes CC à se produire de plus en plus souvent jusqu'à ce que le débit soit inférieur à celui du CC complet, ce qui finit par faire croître le tas.

Utilisez SIGQUIT pour obtenir des informations sur les performances du GC

Pour obtenir les délais de performances GC pour les applications, envoyez SIGQUIT aux applications déjà en cours d'exécution ou transmettez -XX:DumpGCPerformanceOnShutdown à dalvikvm lors du démarrage d'un programme de ligne de commande. Lorsqu'une application reçoit le signal de requête ANR ( SIGQUIT ), elle supprime les informations relatives à ses verrous, ses piles de threads et les performances du GC.

Pour obtenir des vidages de synchronisation GC, utilisez :

adb shell kill -s QUIT PID

Cela crée un fichier (avec la date et l'heure dans le nom tel que anr_2020-07-13-19-23-39-817) dans /data/anr/ . Ce fichier contient des dumps ANR ainsi que des timings GC. Vous pouvez localiser les timings GC en recherchant Dumping cumulative Gc timings . Ces horaires affichent quelques éléments susceptibles d'être intéressants, notamment les informations d'histogramme pour les phases et les pauses de chaque type de GC. Les pauses sont généralement plus importantes à regarder. Par exemple:

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

Cela montre que la pause moyenne était de 1,83 ms, ce qui devrait être suffisamment faible pour ne pas entraîner de trames manquées dans la plupart des applications et ne devrait pas poser de problème.

Un autre domaine d'intérêt est le temps de suspension, qui mesure le temps nécessaire à un thread pour atteindre un point de suspension après que le GC a demandé sa suspension. Ce temps est inclus dans les pauses du GC, il est donc utile de déterminer si les longues pauses sont causées par la lenteur du GC ou par la suspension lente du thread. Voici un exemple d'heure normale de suspension sur un Nexus 5 :

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

Il existe d'autres domaines d'intérêt, notamment le temps total passé et le débit du GC. Exemples:

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

Voici un exemple de la façon de vider les timings GC d'une application déjà en cours d'exécution :

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

À ce stade, les horaires du GC se situent à l'intérieur de anr_2020-07-13-19-23-39-817 . Voici un exemple de résultat de 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

Outils d'analyse des problèmes d'exactitude du GC

Diverses choses peuvent provoquer des plantages à l’intérieur d’ART. Les plantages qui se produisent lors de la lecture ou de l'écriture dans des champs d'objet peuvent indiquer une corruption du tas. Si le GC plante pendant son exécution, cela peut également indiquer une corruption du tas. La cause la plus courante de corruption du tas est un code d’application incorrect. Heureusement, il existe des outils pour déboguer les plantages liés au GC et au tas, notamment les options de vérification du tas spécifiées ci-dessus et CheckJNI.

VérifierJNI

CheckJNI est un mode qui ajoute des vérifications JNI pour vérifier le comportement de l'application ; ceux-ci ne sont pas activés par défaut pour des raisons de performances. Les vérifications détectent quelques erreurs susceptibles de provoquer une corruption du tas, telles que l'utilisation de références locales et globales non valides/périmées. Pour activer CheckJNI :

adb shell setprop dalvik.vm.checkjni true

Le mode forcecopy de CheckJNI est utile pour détecter les écritures après la fin des régions du tableau. Lorsqu'elle est activée, forcecopy oblige les fonctions JNI d'accès au tableau à renvoyer des copies avec des zones rouges. Une zone rouge est une région à la fin/au début du pointeur renvoyé qui a une valeur spéciale, qui est vérifiée lorsque le tableau est libéré. Si les valeurs dans la zone rouge ne correspondent pas à ce qui est attendu, un dépassement ou un sous-épuisement de la mémoire tampon s'est produit. Cela provoque l’abandon de CheckJNI. Pour activer le mode copie forcée :

adb shell setprop dalvik.vm.jniopts forcecopy

Un exemple d'erreur que CheckJNI devrait détecter est l'écriture au-delà de la fin d'un tableau obtenu à partir de GetPrimitiveArrayCritical . Cette opération peut corrompre le tas Java. Si l'écriture se situe dans la zone rouge de CheckJNI, CheckJNI détecte le problème lorsque le ReleasePrimitiveArrayCritical correspondant est appelé. Sinon, l'écriture corrompt un objet aléatoire dans le tas Java et peut provoquer un futur crash du GC. Si la mémoire corrompue est un champ de référence, le GC peut détecter l'erreur et imprimer l'erreur Tried to mark <ptr> not contain by any space .

Cette erreur se produit lorsque le GC tente de marquer un objet pour lequel il ne trouve pas d'espace. Après l'échec de cette vérification, le GC parcourt les racines et essaie de voir si l'objet non valide est une racine. À partir de là, il existe deux options : L'objet est un objet racine ou non racine.

Exemple de racine invalide

Dans le cas où l'objet est une racine invalide, il imprime des informations utiles : 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

Dans ce cas, vreg=1 à l'intérieur de com.google.gwt.collections.JavaReadableJsArray.get est censé contenir une référence de tas, mais contient un pointeur d'adresse 0x2 non valide. Il s'agit d'une racine invalide. Pour déboguer ce problème, utilisez oatdump sur le fichier oat et examinez la méthode avec la racine non valide. Dans ce cas, l'erreur s'est avérée être un bogue du compilateur dans le backend x86. Voici la liste des modifications qui a corrigé le problème : https://android-review.googlesource.com/#/c/133932/

Exemple d'objet corrompu

Si l'objet n'est pas une racine, affichez un résultat similaire à celui suivant :

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

Lorsque la corruption du tas n'est pas une racine invalide, il est difficile de déboguer. Ce message d'erreur indique qu'il y avait au moins un objet dans le tas qui pointait vers l'objet non valide.