偵錯 ART 垃圾收集

本頁面說明如何偵錯 Android 執行階段 (ART) 垃圾收集 (GC) 正確性和效能問題。本文將說明如何使用 GC 驗證選項、找出 GC 驗證失敗的解決方案，以及評估及解決 GC 效能問題。

如要使用 ART，請參閱這個「ART 和 Dalvik」專區的頁面，以及 Dalvik Executable 格式。如需驗證應用程式行為的其他說明，請參閱「在 Android 執行階段 (ART) 驗證應用程式行為」。

ART GC 總覽

ART 有幾個不同的 GC 計畫，其中包含執行不同垃圾收集器。從 Android 8 (Oreo) 開始，預設方案為並行複製 (CC)。另一個 GC 計畫是並行標記清除 (CMS)。

並行複製 GC 的一些主要特徵如下：

  • CC 可讓您使用名為 RegionTLAB 的 bump-pointer 配置器。這會為每個應用程式執行緒分配執行緒本機分配緩衝區 (TLAB)，然後透過提前「頂端」指標，從 TLAB 中分配物件，而無需任何同步處理。
  • CC 會同時複製物件，而不會暫停應用程式執行緒，藉此執行堆積區的去碎片化作業。這項功能是透過讀取緩衝區實現，該緩衝區會攔截堆積區的參照讀取作業，無須應用程式開發人員介入。
  • GC 只會暫停一次，且暫停時間會根據堆積大小而定。
  • CC 會在 Android 10 以上版本中擴充為世代 GC。這可讓您輕鬆收集新物件，這些物件通常很快就會變得無法存取。這有助於提高 GC 吞吐量，並大幅延後執行完整堆 GC 的必要性。

ART 支援的另一個 GC 是 CMS。這項 GC 也支援壓縮，但不支援並行壓縮。在應用程式進入背景之前，系統會避免執行壓縮作業，並在應用程式進入背景時暫停執行壓縮作業。當物件分配因碎片化而失敗時，也必須進行壓縮。在這種情況下，應用程式可能會在一段時間內沒有回應。

由於 CMS 很少壓縮，因此釋放的物件可能不會連續，因此會使用名為 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 類型的選項相同。啟用堆積驗證後，系統會驗證根目錄，並確保可存取的物件只參照其他可存取的物件。您可以傳入下列 -Xgc 值，啟用 GC 驗證功能：

  • 如果已啟用，[no]preverify 會在啟動 GC 前執行堆積驗證。
  • 如果已啟用，[no]presweepingverify 會在啟動垃圾收集器掃描程序前執行堆積驗證。
  • 如果啟用，[no]postverify 會在 GC 完成掃描後執行堆積驗證。
  • [no]preverify_rosalloc、[no]postsweepingverify_rosalloc 和 [no]postverify_rosalloc 是額外的 GC 選項，只會驗證 RosAlloc 的內部會計狀態。因此，這些方法只適用於使用 RosAlloc 配置器的 CMS 收集器。主要驗證項目是確認魔術值與預期常數相符，且記憶體的空閒區塊都已登錄在 free_page_runs_ 對應項目中。

成效

評估 GC 效能的兩個主要工具是 GC 時間傾印和 Systrace。另外還有一個進階版的 Systrace，稱為 Perfetto。如要以視覺化方式評估 GC 效能問題，請使用 Systrace 和 Perfetto，判斷哪些 GC 導致長時間暫停或搶先處理應用程式執行緒。雖然 ART GC 隨著時間的推移而大幅改善，但不良的轉換器行為 (例如過度配置) 仍可能導致效能問題

收集策略

CC GC 會執行年輕 GC 或完整記憶體 GC 來收集資料。理想情況下，新 GC 會執行得更頻繁。GC 會執行年輕 CC 收集作業，直到剛完成的收集週期吞吐量 (以 GC 時間長度/每秒釋放的位元組計算) 低於完整堆積 CC 收集作業的平均吞吐量為止。發生這種情況時，系統會為下一次並行 GC 選擇完整記憶體 CC，而不是年輕 CC。全堆收集完成後，下一次 GC 會切換回年輕的 CC。這項策略能發揮作用的關鍵因素之一，是新 CC 在完成後不會調整堆積空間足跡限制。這會導致年輕 CC 發生的次數越來越多，直到吞吐量低於完整堆疊 CC 為止，最終會導致堆疊增加。

使用 SIGQUIT 取得 GC 效能資訊

如要取得應用程式的 GC 效能時間，請將 SIGQUIT 傳送至已在執行的應用程式，或是在啟動指令列程式時將 -XX:DumpGCPerformanceOnShutdown 傳入 dalvikvm。當應用程式收到 ANR 要求信號 (SIGQUIT) 時，就會轉儲與鎖定、執行緒堆疊和 GC 效能相關的資訊。

如要取得 GC 時間排空，請使用：

adb shell kill -s QUIT PID

這會在 /data/anr/ 中建立檔案 (名稱中含有日期和時間，例如 anr_2020-07-13-19-23-39-817)。這個檔案包含部分 ANR 傾印內容和 GC 時間。您可以搜尋「Dumping cumulative Gc timings」，找出 GC 時間。這些時間資訊會顯示一些可能感興趣的內容，包括每個 GC 類型的階段和暫停的直方圖資訊。通常，您更應留意影片的暫停時間。例如：

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

這表示平均暫停時間為 1.83 毫秒，這個值應足夠低，不會導致大多數應用程式遺漏影格，因此不必擔心。

另一個值得關注的領域是暫停時間，這會評估 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

此時，垃圾資訊收集時間會位於 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 檢查來驗證應用程式行為；基於效能考量，這些檢查預設為停用。這些檢查可偵測出可能導致堆積毀損的錯誤，例如使用無效/過時的本機和全域參照。如何啟用 CheckJNI：

adb shell setprop dalvik.vm.checkjni true

CheckJNI 的強制複製模式可用於偵測寫入陣列區域結尾後的資料。啟用後，forcecopy 會導致陣列存取 JNI 函式，以便傳回帶有紅色區的副本。紅色區域是指傳回指標結尾/開頭的區域，該區域具有特殊值，會在陣列釋放時進行驗證。如果紅色區域中的值與預期值不符，就表示發生緩衝區溢位或不足的情況。這會導致 CheckJNI 中止。如何啟用強制複製模式：

adb shell setprop dalvik.vm.jniopts forcecopy

舉例來說，CheckJNI 應擷取的錯誤包括寫入超過從 GetPrimitiveArrayCritical 取得的陣列結尾。這項作業可能會損毀 Java 堆積。如果寫入作業位於 CheckJNI 紅色區域內，則 CheckJNI 會在呼叫對應的 ReleasePrimitiveArrayCritical 時偵測到問題。否則，寫入作業會損毀 Java 堆積中的部分隨機物件，並可能導致日後 GC 異常終止。如果損毀的記憶體是參照欄位，GC 可能會擷取錯誤，並顯示「Tried to mark <ptr> not contained by any spaces」錯誤訊息。

當 GC 嘗試標記無法找到空間的物件時，就會發生這個錯誤。這項檢查失敗後，GC 會逐一檢查根目錄，並嘗試查看無效物件是否為根目錄。接著有兩個選項：物件是根物件或非根物件。

無效根目錄示例

如果物件是無效的根目錄，則會列印一些實用資訊：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

如果堆積的損毀並非無效的根源，就很難進行偵錯。這則錯誤訊息表示堆積中至少有一個物件指向無效物件。