ART ガベージコレクションのデバッグ

このページでは、Android ランタイム（ART）のガベージコレクション（GC）の正確性とパフォーマンスに関する問題をデバッグする方法を示します。GC 検証オプションの使用方法、GC 検証エラーの解決策の特定方法、GC パフォーマンスの測定方法と問題解決方法について説明します。

ART を使用する場合は、ART と Dalvik および Dalvik 実行可能ファイルの形式をご覧ください。アプリの動作確認について詳しくは、Android ランタイム（ART）でのアプリの動作確認をご覧ください。

ART GC の概要

ART には、異なるガベージコレクタを実行する GC プランが複数あります。Android 8（Oreo）以降、デフォルトのプランは同時コピー（CC）です。もう 1 つの GC プランは、同時マークスイープ（CMS）です。

同時コピー GC の主な特徴は次のとおりです。

CC では RegionTLAB と呼ばれるバンプポインタアロケータを使用できます。これにより、各アプリスレッドにスレッドローカル割り当てバッファ（TLAB）が割り当てられ、「先頭」のポインタを進めることで同期を行わずに TLAB からオブジェクトを割り当てることができます。
CC では、アプリスレッドを一時停止せずにオブジェクトを同時にコピーすることで、ヒープのデフラグが行われます。これは、ヒープからの参照読み取りをインターセプトする読み取りバリアを使用することで実現し、アプリデベロッパーが関与する必要はありません。
GC には 1 回だけ短い一時停止がありますが、その時間はヒープサイズに関して一定です。
Android 10 以降、CC は世代別 GC に拡張されます。世代別 GC では、通常はすぐにアクセスできなくなる最近のオブジェクトを容易に回収できます。これにより、GC のスループットが向上し、完全ヒープ GC を実行する必要性を大幅に遅らせることができます。

ART が引き続きサポートしているもう 1 つの GC は CMS です。この GC は圧縮もサポートしていますが、同時実行ではありません。アプリがバックグラウンドに移動するまで圧縮は回避され、アプリがバックグラウンドに移動した時点で、アプリスレッドが一時停止され圧縮を実行します。断片化によってオブジェクトの割り当てに失敗した場合も、圧縮が必要になります。この場合、アプリがしばらくの間応答しなくなる可能性があります。

CMS はほとんど圧縮を行わず空きオブジェクトが連続しない可能性があるため、RosAlloc というフリーリストベースのアロケータを使用しています。RosAlloc は RegionTLAB より、割り当てのコストが高くなります。最後に、内部の断片化が原因で、CMS の Java ヒープのメモリ使用量が CC より高くなることがあります。

GC の検証オプションとパフォーマンスオプション

GC タイプを変更する

OEM は GC タイプを変更できます。変更プロセスには、ビルド時の ART_USE_READ_BARRIER 環境変数の設定が含まれます。デフォルト値は true で、これにより、読み取りバリアを使用する際に CC コレクタが有効になります。CMS の場合、この変数は明示的に false に設定する必要があります。

Android 10 以降では、デフォルトで CC コレクタが世代別モードで実行されます。世代別モードを無効にするには、-Xgc:nogenerational_cc コマンドライン引数を使用します。または、次のようにシステムプロパティを設定することもできます。

adb shell setprop dalvik.vm.gctype nogenerational_cc

CMS コレクタは常に世代別モードで実行されます。

ヒープを検証する

ヒープ検証は、おそらく GC 関連の誤りやヒープの破損をデバッグするための最も有用な GC オプションです。ヒープ検証を有効にすると、GC はガベージコレクションプロセス中に、いくつかのポイントでヒープの正確性をチェックします。ヒープ検証では、GC タイプを変更するオプションと同じオプションを使用します。ヒープ検証が有効な場合、ルートを検証して、到達可能なオブジェクトが他の到達可能なオブジェクトのみを参照することを確認します。GC 検証を有効にするは、次の -Xgc 値を渡します。

[no]preverify: 有効にすると、GC を開始する前にヒープ検証を実行します。
[no]presweepingverify: 有効にすると、ガベージコレクタのスイーププロセスを開始する前にヒープ検証を実行します。
[no]postverify: 有効にすると、GC がスイープを完了した後にヒープ検証を実行します。
[no]preverify_rosalloc、[no]postsweepingverify_rosalloc、[no]postverify_rosalloc: RosAlloc の内部アカウンティングの状態のみを確認する GC オプションです。そのため、適用されるのは RosAlloc アロケータを使用する CMS コレクタのみです。主な検証事項には、マジック値が期待される定数と一致するか、メモリの空きブロックがすべて free_page_runs_ マップに登録されているかなどの項目があります。

パフォーマンス

GC パフォーマンスの測定に使用できる主なツールは 2 つあります。GC 時間情報ダンプと Systrace です。Perfetto という Systrace の進化版もあります。GC パフォーマンスの問題を測定する視覚的な手段は、Systrace と Perfetto を使用して、どの GC が長い一時停止またはアプリスレッドのプリエンプションを引き起こしているかを調べることです。ART GC は時間の経過とともに大幅に改善されていますが、過度の割り当てなどの不適切なミューテータの動作によって、パフォーマンスの問題が発生することもあります。

コレクションの戦略

CC GC は、若い GC または完全ヒープ GC のどちらかを実行することでコレクションを行います。若い GC の実行頻度が高くなることが理想的です。GC は、最後のコレクションサイクルのスループット（解放されたバイト数を GC 実行時間の秒数で割ることで計算される）が、完全ヒープ CC コレクションの平均スループットを下回るまで、若い CC コレクションを実行します。そうなった場合、次回の同時実行 GC に若い CC ではなく完全ヒープ CC が選択されます。完全ヒープコレクションが完了すると、次回の GC は若い CC に戻ります。この戦略が機能するための重要な要因の 1 つは、若い CC が、完了後にヒープのフットプリント制限を調整しないことです。そうしないと、スループットが完全ヒープ CC を下回るまで若い CC がさらに頻繁に発生し、結果的にヒープが増加します。

SIGQUIT を使用して GC パフォーマンス情報を取得する

アプリの GC のパフォーマンスと時間情報を取得するには、すでに実行中のアプリに SIGQUIT を送信するか、コマンドラインプログラムの起動時に -XX:DumpGCPerformanceOnShutdown を dalvikvm に渡します。アプリは ANR リクエストシグナル（SIGQUIT）を受け取ると、ロック、スレッドスタック、GC パフォーマンスに関する情報をダンプします。

GC 時間情報ダンプを取得するには、次のコマンドを使用します。

adb shell kill -s QUIT PID

これにより、/data/anr/ にファイル（ar_2020-07-13-19-23-39-817 のように、名前に日時を含む）が作成されます。このファイルには、GC 時間情報だけでなく ANR ダンプも含まれています。GC 時間情報を見つけるには、「Dumping cumulative Gc timings」を検索します。これらの時間情報から、各 GC タイプのフェーズと一時停止のヒストグラム情報など、興味深い情報が得られます。通常調べる価値があるのは、一時停止のデータです。次に例を示します。

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

これは、平均の一時停止時間が 1.83 ミリ秒であったことを示しています。この値は、ほとんどのアプリでフレームの欠落が発生しない程度に低いため問題ありません。

もう 1 つの興味深いデータは中断時間です。これは、GC が中断をリクエストしてからスレッドが中断ポイントに到達するまでに要した時間です。この時間は GC の一時停止に含まれるため、GC が遅いことまたはスレッドの中断が遅いことが、長い一時停止を発生させる原因になっているのかを判断するうえで有用です。次の例は、Nexus 5 での正常な中断時間を示しています。

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

また、合計所要時間や GC スループットなども興味深い情報です。例:

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

次の例は、すでに実行中のアプリの GC 時間情報をダンプする方法を示しています。

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

この時点では、GC 時間情報は anr_2020-07-13-19-23-39-817 内にあります。Google マップからの出力例を次に示します。

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

GC の正確性の問題を分析するためのツール

ART の内部でクラッシュが発生する原因はさまざまです。オブジェクトフィールドの読み取りまたは書き込みの際に発生するクラッシュは、ヒープの破損を示唆していることがあります。GC が実行中にクラッシュした場合も、ヒープが破損している可能性があります。ヒープの破損の最も一般的な原因は、アプリコードが間違っていることです。幸いなことに、GC とヒープに関連するクラッシュをデバッグするツールがあります。前述のヒープ検証オプションや CheckJNI です。

CheckJNI

CheckJNI は、JNI チェックを追加してアプリの動作を検証するモードです。パフォーマンス上の理由により、JNI チェックはデフォルトでは有効になっていません。このチェックでは、無効な（または最新ではない）ローカル参照とグローバル参照の使用など、ヒープの破損を引き起こす可能性がある誤りの一部が捕捉されます。CheckJNI を有効にするには、次のコマンドを実行します。

adb shell setprop dalvik.vm.checkjni true

CheckJNI の強制コピーモードは、配列領域の終わりを越えた書き込みを検出するのに有用です。強制コピーを有効にすると、配列アクセス JNI 関数はレッドゾーン付きのコピーを返します。レッドゾーンは、返されるポインタの終了位置 / 開始位置にある領域です。このポインタは、配列が解放されたときに検証される特別な値を持っています。レッドゾーン内の値が想定と一致しない場合、バッファのオーバーランまたはアンダーランが発生しています。この場合、CheckJNI が中止されます。強制コピーモードを有効にするには、次のコマンドを実行します。

adb shell setprop dalvik.vm.jniopts forcecopy

CheckJNI が捕捉する誤りの 1 つの例は、GetPrimitiveArrayCritical から取得される配列の終わりを越えた書き込みです。この操作により、Java ヒープが破損することがあります。書き込みが CheckJNI のレッドゾーン領域内にある場合、CheckJNI は、対応する ReleasePrimitiveArrayCritical が呼び出されたときに問題を捕捉します。そうしないと、書き込みによって Java ヒープ内のオブジェクトが無作為に破損し、将来 GC のクラッシュを引き起こす可能性があります。破損したメモリが参照フィールドである場合、GC は誤りを捕捉して、「Tried to mark <ptr> not contained by any spaces」というエラーを出力します。

このエラーは、GC がマークしようとしているオブジェクトに対してスペースを見つけることができない場合に発生します。このチェックがエラーで終了すると、GC はルートを走査して、無効なオブジェクトがルートかどうかの確認を試みます。ここからは 2 つの場合があります。オブジェクトがルートである場合とルートでない場合です。

無効なルートの例

オブジェクトが無効なルートである場合、次のような有益な情報が出力されます。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

この場合、com.google.gwt.collections.JavaReadableJsArray.get 内の vreg=1 にはヒープ参照が含まれるはずですが、アドレス 0x2 の無効なポインタが含まれています。これは無効なルートです。この問題をデバッグするには、oat ファイルに oatdump を使用して、無効なルートを持つメソッドを調べます。この例では、誤りは x86 バックエンド内のコンパイラのバグであると判明しました。この誤りの修正に関する変更リストは、https://android-review.googlesource.com/#/c/133932/ にあります。

破損したオブジェクトの例

オブジェクトがルートでない場合、次のように表示されます。

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

ヒープの破損の原因が無効なルートでない場合、デバッグは困難です。このエラーメッセージは、無効なオブジェクトを指しているオブジェクトがヒープ内に少なくとも 1 つ存在したことを示しています。

ART ガベージ コレクションのデバッグ