Cette page explique comment déboguer les problèmes de performances et d'exactitude de la récupération de mémoire (GC) d'Android Runtime (ART). Il explique comment utiliser les options de validation de GC, identifier les solutions aux échecs de validation de GC, et mesurer et résoudre les problèmes de performances de GC.
Pour utiliser ART, consultez les pages de la section ART et Dalvik, ainsi que le format Dalvik Executable. Pour obtenir de l'aide supplémentaire pour vérifier le comportement des applications, consultez la section Vérifier le comportement des applications dans l'environnement d'exécution Android Runtime (ART).
Présentation de GC ART
ART propose plusieurs plans de récupération de mémoire qui consistent à exécuter différents collecteurs de déchets. À partir d'Android 8 (Oreo), le plan par défaut est la copie simultanée (CC). L'autre plan de GC est le Concurrent Mark Sweep (CMS).
Voici quelques-unes des principales caractéristiques de la récupération de mémoire par copie simultanée:
- La compilation continue permet d'utiliser un alloueur de pointeur de décalage appelé RegionTLAB. Cela alloue un tampon d'allocation thread-local (TLAB) à chaque thread d'application, qui peut ensuite allouer des objets en dehors de son TLAB en augmentant le pointeur "top", sans aucune synchronisation.
- La défragmentation de tas est effectuée par la copie simultanée d'objets sans suspendre les threads de l'application. Cela est possible grâce à une barrière de lecture qui intercepte les lectures de référence à partir de la pile, sans aucune intervention du développeur de l'application.
- La récupération de mémoire n'a qu'une petite pause, qui est constante dans le temps par rapport à la taille de la pile.
- La CC devient un GC générationnel sous Android 10 et versions ultérieures. Il permet de collecter des objets jeunes, qui deviennent souvent inaccessibles assez rapidement, avec peu d'effort. Cela permet d'augmenter le débit du GC et de retarder considérablement la nécessité d'effectuer un GC de tas complet.
L'autre GC compatible avec ART est CMS. Ce GC est également compatible avec le compactage, mais pas simultanément. La compaction est évitée jusqu'à ce que l'application passe en arrière-plan, auquel cas les threads de l'application sont mis en veille pour effectuer la compaction. La compaction 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 ne sont donc pas nécessairement contigus, il utilise un administrateur de mémoire 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 la pile Java peut être plus élevée pour CMS que pour CC.
Options de validation et de performances de GC
Modifier le type de GC
Les OEM peuvent modifier le type de GC. Le processus de modification implique de définir la variable d'environnement ART_USE_READ_BARRIER
au moment de la compilation.
La valeur par défaut est "true", ce qui active le collecteur de CC, car il utilise la barrière de lecture. Pour les CMS, cette variable doit être définie explicitement sur "false".
Par défaut, le collecteur de CC s'exécute en mode générationnel sous Android 10 ou version ultérieure. Pour désactiver le mode générationnel, vous pouvez utiliser l'argument de ligne de commande -Xgc:nogenerational_cc
. Vous pouvez également définir la propriété système comme suit:
adb shell setprop dalvik.vm.gctype nogenerational_cc
Vérifier la pile
La vérification de la pile est probablement l'option de GC la plus utile pour déboguer les erreurs liées au GC ou la corruption de la pile. L'activation de la validation de la pile entraîne la vérification de l'exactitude de la pile à quelques points pendant le processus de collecte des déchets. La validation de la pile partage les mêmes options que celles qui modifient le type de GC. Si elle est activée, la validation de la pile vérifie les racines et s'assure que les objets accessibles ne référencent que d'autres objets accessibles. La validation GC est activée en transmettant les valeurs -Xgc
suivantes:
- Si elle est activée,
[no]preverify
effectue la validation de la pile avant de démarrer le GC. - Si elle est activée,
[no]presweepingverify
effectue la vérification de la pile avant de démarrer le processus de balayage du garbage collector. - Si cette option est activée,
[no]postverify
effectue la validation de la pile une fois que le GC a terminé le balayage. [no]preverify_rosalloc
,[no]postsweepingverify_rosalloc
et[no]postverify_rosalloc
sont des options GC supplémentaires qui ne vérifient que l'état de la comptabilité interne de RosAlloc. Par conséquent, elles ne s'appliquent qu'au collecteur CMS, qui utilise l'outil d'allocation RosAlloc. Les principales vérifications consistent à vérifier que les valeurs magiques correspondent aux constantes attendues et que les blocs de mémoire libres sont tous enregistrés dans la cartefree_page_runs_
.
Performances
Il existe deux principaux outils pour mesurer les performances du GC : les vidages de temps de GC et Systrace. Il existe également une version avancée de Systrace, appelée Perfetto. Pour mesurer visuellement les problèmes de performances de GC, utilisez Systrace et Perfetto pour déterminer quels GC provoquent de longues pauses ou préemptent les threads d'application. Bien que le GC ART ait considérablement progressé au fil du temps, un mauvais comportement du mutator, comme une allocation excessive, peut toujours entraîner des problèmes de performances.
Stratégie de collecte
Le GC CC collecte en exécutant un GC jeune ou un GC de tas complet. Idéalement, le GC jeune est exécuté plus souvent. Le GC effectue des collectes de CC jeunes jusqu'à ce que le débit (calculé en octets libérés/seconde de la durée du GC) du cycle de collecte qui vient de se terminer soit inférieur au débit moyen des collectes de CC de tas complet. Dans ce cas, la CC de tas complet est choisie pour le prochain GC simultané au lieu de la CC jeune. Une fois la collecte de la mémoire tampon complète terminée, la collecte de mémoire suivante est rétablie sur la CC jeune. Un facteur clé qui fait fonctionner cette stratégie est que le CC jeune n'ajuste pas la limite d'empreinte de tas une fois qu'il est terminé. Cela entraîne une augmentation de la fréquence des CC jeunes jusqu'à ce que le débit soit inférieur à la CC de la pile complète, ce qui finit par augmenter la pile.
Utiliser SIGQUIT pour obtenir des informations sur les performances de GC
Pour obtenir les temps de GC pour les applications, envoyez SIGQUIT
aux applications déjà en cours d'exécution ou transmettez -XX:DumpGCPerformanceOnShutdown
à dalvikvm
lorsque vous démarrez un programme de ligne de commande. Lorsqu'une application reçoit le signal de requête ANR (SIGQUIT
), elle vide les informations liées à ses verrous, à ses piles de threads et aux performances du GC.
Pour obtenir des vidages de temps de GC, utilisez:
adb shell kill -s QUIT PID
Un fichier (avec la date et l'heure dans le nom, par exemple anr_2020-07-13-19-23-39-817) est créé dans /data/anr/
. Ce fichier contient des vidages ANR ainsi que des délais GC. Vous pouvez trouver les temps de GC en recherchant Dumping cumulative Gc timings (Vider les temps de GC cumulés). Ces délais indiquent quelques éléments qui peuvent être intéressants, y compris les informations d'histogramme pour les phases et les pauses de chaque type de GC. Les pauses sont généralement plus importantes à examiner. 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 frames manqués dans la plupart des applications et ne devrait pas poser de problème.
Un autre paramètre intéressant est le temps de suspension, qui mesure le temps nécessaire à un thread pour atteindre un point de suspension après les requêtes de GC qu'il suspend. Ce temps est inclus dans les pauses GC. Il est donc utile de déterminer si les pauses longues sont dues à la lenteur du GC ou à la suspension lente du thread. Voici un exemple de temps de suspension normal sur un Nexus 5:
suspend all histogram: Sum: 1.513ms 99% C.I. 3us-546.560us Avg: 47.281us Max: 601us
D'autres domaines d'intérêt sont disponibles, y compris la durée totale passée et le débit 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 vidage des temps de 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 délais de récupération de mémoire se trouvent dans anr_2020-07-13-19-23-39-817
. Voici un exemple de résultat 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 de correction de GC
Différents éléments peuvent entraîner des plantages dans ART. Les plantages qui se produisent lors de la lecture ou de l'écriture dans des champs d'objets peuvent indiquer une corruption de tas. Si le GC plante lorsqu'il s'exécute, cela peut également indiquer une corruption de tas. La cause la plus courante de la corruption de tas est un code d'application incorrect. Heureusement, il existe des outils pour déboguer les plantages liés au GC et à la pile, y compris les options de vérification de la pile spécifiées ci-dessus et CheckJNI.
CheckJNI
CheckJNI est un mode qui ajoute des vérifications JNI pour valider le comportement de l'application. Elles ne sont pas activées par défaut pour des raisons de performances. Les vérifications détectent quelques erreurs pouvant entraîner la corruption du tas de mémoire, telles que l'utilisation de références locales et globales non valides/obsolètes. Pour activer CheckJNI:
adb shell setprop dalvik.vm.checkjni true
Le mode forcecopy de CheckJNI est utile pour détecter les écritures au-delà de la fin des régions de tableaux. Lorsque cette option est activée, les fonctions JNI d'accès au tableau renvoient des copies avec des zones rouges. Une zone rouge est une région située à la fin/au début du pointeur renvoyé qui possède une valeur spéciale, qui est vérifiée lorsque le tableau est libéré. Si les valeurs de la zone rouge ne correspondent pas à ce qui est attendu, un dépassement ou un sous-dépassement de la mémoire tampon s'est produit. CheckJNI s'arrête alors. Pour activer le mode forcecopy:
adb shell setprop dalvik.vm.jniopts forcecopy
Un exemple d'erreur que CheckJNI doit détecter est l'écriture au-delà de la fin d'un tableau obtenu à partir de GetPrimitiveArrayCritical
. Cette opération peut corrompre la pile Java. Si l'écriture se trouve dans la zone rouge de CheckJNI, CheckJNI détecte le problème lorsque l'ReleasePrimitiveArrayCritical
correspondante est appelée. Sinon, l'écriture corrompt un objet aléatoire dans la pile Java et peut provoquer un plantage du GC à l'avenir. 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 contained by any spaces (Tentative de marquage de <ptr> comme non contenu dans des espaces).
Cette erreur se produit lorsque le GC tente de marquer un objet pour lequel il ne trouve pas d'espace. Une fois cette vérification échouée, le GC parcourt les racines et tente de déterminer si l'objet non valide est une racine. Vous avez alors deux options : l'objet est un objet racine ou non.
Exemple de racine non valide
Si l'objet est une racine non valide, il affiche 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
dans 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 non valide. 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 bug de compilateur dans le backend x86. Voici la liste de modifications qui a permis de résoudre le problème: https://android-review.googlesource.com/#/c/133932/
Exemple d'objet corrompu
Si l'objet n'est pas une racine, une sortie semblable à celle-ci s'affiche:
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 de tas n'est pas une racine non valide, le débogage est difficile. Ce message d'erreur indique qu'au moins un objet de la pile pointait vers l'objet non valide.