调试 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 只有一个很小的暂停，暂停时间相对于堆大小而言是恒定的。
  • 在 Android 10 及更高版本中，CC 扩展为分代 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 回收的平均吞吐量。 发生这种情况时，会选择完整堆 CC 进行下一次并发 GC，而不是年轻代 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

此时，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 检查以验证应用行为的模式；出于性能原因，默认情况下未启用这些检查。 这些检查会捕获一些可能导致堆损坏的错误，例如使用无效/过时的本地和全局引用。 要启用 CheckJNI

adb shell setprop dalvik.vm.checkjni true

CheckJNI 的 forcecopy 模式对于检测超出数组区域末尾的写入非常有用。 启用后，forcecopy 会导致数组访问 JNI 函数返回带有红色区域的副本。 红色区域是返回指针的末尾/开头的一个区域，该区域具有特殊值，在释放数组时会对其进行验证。 如果红色区域中的值与预期值不匹配，则会发生缓冲区溢出或下溢。 这会导致 CheckJNI 中止。 要启用 forcecopy 模式

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

当堆损坏不是无效根时，很难调试。 此错误消息表明堆中至少有一个对象指向无效对象。