調試 ART 垃圾回收

本頁介紹如何調試 Android 運行時 (ART) 垃圾回收 (GC) 正確性和性能問題。它解釋瞭如何使用 GC 驗證選項、確定 GC 驗證失敗的解決方案以及測量和解決 GC 性能問題。

要使用 ART,請參閱此ART 和 Dalvik部分中的頁面以及Dalvik 可執行文件格式。有關驗證應用行為的更多幫助,請參閱在 Android 運行時 (ART) 上驗證應用行為

ART GC 概述

ART 有幾個不同的 GC 計劃,包括運行不同的垃圾收集器。從 Android 8 (Oreo) 開始,默認計劃是並發複製 (CC)。另一個 GC 計劃是並發標記掃描 (CMS)。

並發複製 GC 的一些主要特徵是:

  • CC 允許使用稱為 RegionTLAB 的凹凸指針分配器。這會為每個應用程序線程分配一個線程本地分配緩衝區(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。

默認情況下,CC 收集器在 Android 10 及更高版本中以分代模式運行。要禁用分代模式,可以使用-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 隨著時間的推移有了顯著改善,但不良的 mutator 行為,例如過度分配,仍然會導致性能問題

收款策略

CC GC 通過運行年輕 GC 或全堆 GC 來收集。理想情況下,年輕 GC 運行得更頻繁。 GC 執行年輕 CC 收集,直到剛剛完成的收集週期的吞吐量(按釋放的字節數/秒的 GC 持續時間計算)小於全堆 CC 收集的平均吞吐量。發生這種情況時,會為下一次並發 GC 選擇全堆 CC 而不是年輕 CC。全堆回收完成後,下一次GC切換回young CC。使這一策略奏效的一個關鍵因素是年輕 CC 在完成後不會調整堆佔用限制。這導致年輕CC越來越頻繁地發生,直到吞吐量低於全堆CC,最終導致堆增長。

使用 SIGQUIT 獲取 GC 性能信息

要獲取應用程序的 GC 性能計時,請在啟動命令行程序時向已運行的應用程序發送SIGQUIT或將-XX:DumpGCPerformanceOnShutdowndalvikvm 。當應用程序收到 ANR 請求信號 ( SIGQUIT ) 時,它會轉儲與其鎖、線程堆棧和 GC 性能相關的信息。

要獲取 GC 計時轉儲,請使用:

adb shell kill -s QUIT PID

這將在/data/anr/中創建一個文件(名稱中包含日期和時間,例如 anr_2020-07-13-19-23-39-817)。該文件包含一些 ANR 轉儲以及 GC 計時。您可以通過搜索Dumping累積 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

此時 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。

檢查JNI

CheckJNI 是一種添加 JNI 檢查以驗證應用行為的模式;出於性能原因,這些默認情況下未啟用。檢查會捕獲一些可能導致堆損壞的錯誤,例如使用無效/陳舊的本地和全局引用。要啟用 CheckJNI:

adb shell setprop dalvik.vm.checkjni true

CheckJNI 的 forcecopy 模式對於檢測超出數組區域末尾的寫入非常有用。啟用後,forcecopy 會導致陣列訪問 JNI 函數返回帶有紅色區域的副本。紅色區域是返回指針的結束/開始處具有特殊值的區域,該值在釋放數組時進行驗證。如果紅色區域中的值與預期值不匹配,則發生緩衝區溢出或欠載。這會導致 CheckJNI 中止。要啟用強制複製模式:

adb shell setprop dalvik.vm.jniopts forcecopy

CheckJNI 應該捕獲的錯誤示例是寫入從GetPrimitiveArrayCritical獲得的數組的末尾。此操作可能會損壞 Java 堆。如果寫入在 CheckJNI 紅色區域內,則 CheckJNI 會在調用相應的ReleasePrimitiveArrayCritical時捕獲問題。否則,寫入會破壞 Java 堆中的一些隨機對象,並可能導致未來的 GC 崩潰。如果損壞的內存是引用字段,則 GC 可能會捕獲錯誤並打印錯誤Tried to mark <ptr> not contain 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.corp.collections.JavaReadableJsArray.get(int)' at dex PC 0x0002
(native PC 0xf19609d9) vreg=1

在這種情況下, com.google.gwt.corp.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

當堆損壞不是無效的根時,很難調試。此錯誤消息表明堆中至少有一個對象指向無效對象。