Administrator
发布于 2020-07-23 / 2371 阅读
65

G1 收集器调优实战:从 CMS 迁移的得与失

为什么要从 CMS 迁到 G1

我们在 JDK 8 上跑 CMS 跑了两年多,一直相安无事。真正推动迁移的是两件事。

第一件是碎片问题终于爆了。四月份的一个凌晨,promotion failed 触发了 Serial Old 单线程 Full GC,整个应用 STW 了 11.4 秒:

2020-04-17T02:31:08.442+0800: 2384712.114: [GC (Allocation Failure) 2384712.114: [ParNew
Desired survivor size 17432576 bytes, new threshold 6 (max 6)
- age   1:    2183400 bytes,    2183400 total
: 314560K->34944K(314560K), 0.0382140 secs]
2384712.152: [CMS2020-04-17T02:31:19.884+0800: 2384723.556: [CMS-concurrent-mark: 10.021/11.442 secs]
 (concurrent mode failure): 2096128K->2097151K(2097152K), 11.3981100 secs]
 2384723.556: [Rescan (parallel) , 0.0128840 secs] 2410688K->2410688K(2410688K),
 [CMS Perm : 132104K->132096K(262144K)], 11.4370210 secs]

老年代 2GB,用了 2096128K 但已经没有连续空间放晋升的对象了。堆里明明有空闲(总共才用了 2.3GB / 4GB),就是散成了一块块小的。这次事故之后我们给 CMS 加了 -XX:+UseCMSCompactAtFullCollection -XX:CMSFullGCsBeforeCompaction=0,每次 Full GC 都压缩,能续命但治不了本。

第二件是运维成本。CMS 那套参数是真的难调:-XX:CMSInitiatingOccupancyFraction 设低了触发频繁、CPU 白烧,设高了又容易 concurrent mode failure。我们有 6 个微服务,每个业务对象的生命周期不同,就得配 6 套参数。新人接手根本不敢动。

于是六月份开始做 G1 迁移的评估,七月初灰度上线,到现在跑了三周。这篇把过程中的数据和我踩的坑记下来。

G1 和 CMS 的结构性差异

Region 划分:不是固定的三代

CMS 的新生代、老年代是两块连续的地址空间,边界固定,靠 -Xmn-XX:NewRatio 划分。G1 把整个堆切成 N 个大小相等的 Region(1MB~32MB,必须是 2 的幂),每个 Region 在运行时动态地扮演 Eden / Survivor / Old / Humongous 其中一种角色。

Region 大小由堆大小决定:
  -XX:G1HeapRegionSize  可显式指定,否则 JVM 按堆大小算,目标是 2048 个 Region 左右

4GB 堆 -> RegionSize = 2MB, 共 2048 个 Region
8GB 堆 -> RegionSize = 4MB, 共 2048 个 Region

可以用下面这条命令看实际的 Region 划分:

$ jcmd 1 GC.heap_info
 garbage-first heap   total 4194304K, used 2413421K [0x00000006c0000000, ...)
  region size 2048K, 1 young (2048K), 0 survivors (0K)
 Metaspace  used 132104K, capacity 145320K, committed 147456K, reserved 1179648K

这种结构带来两个直接好处:回收时按 Region 的性价比排序选回收集(CSet),不用每次都扫整个老年代对象在 Region 之间复制,天然完成了压缩,从根上解决了碎片。这也就是 G1 能宣称"低延迟且不需要 Full GC"的底气。

MaxGCPauseMillis 是软目标,不是承诺

G1 的核心卖点是 -XX:MaxGCPauseMillis=200,我一开始理解成"保证 200ms 以内",被现实教育了。

实际机制是:G1 会根据历史回收数据(每个 Region 的垃圾占比、复制耗时)建立一个衰减均值模型,然后预测"选多少个 Region 能在 200ms 内回收完",据此决定这次 CSet 的大小。预测错了就超时。

上线第一周的数据(4GB 堆,200ms 目标,压测 QPS 3200):

分位Young GC 耗时Mixed GC 耗时
P5028ms74ms
P9996ms310ms
Max184ms640ms

P99 是 310ms,超了目标 55%。所以我现在的说法是:MaxGCPauseMillis 是给 G1 的吞吐量/延迟权衡旋钮,不是 SLA 保证。真正要卡延迟,得靠减小单次回收的对象量(调小 Region、控制晋升速度)而不是单靠这个参数。

Mixed GC:G1 独有的阶段

CMS 只有 Minor GC 和 Full GC 两种。G1 多了 Mixed GC:并发标记完成后,G1 知道哪些老年代 Region 垃圾多(回收性价比高),就在接下来的几次 Young GC 里,顺带把这些老年代 Region 一起回收了。

这是 G1 防止 CMS 那种"老年代涨到 90% 才慌忙回收"的关键——它把老年代回收拆散到多次停顿里,每次只收一小批。

相关参数:

-XX:InitiatingHeapOccupancyPercent=45       # 堆占用 45% 触发并发标记(默认)
-XX:G1MixedGCLiveThresholdPercent=85        # 存活对象超过 85% 的 Region 不选入 CSet
-XX:G1MixedGCCountTarget=8                  # 一次标记后最多做 8 次 Mixed GC
-XX:G1HeapWastePercent=5                    # 可回收空间低于堆的 5% 就停止 Mixed

迁移后的第一个坑:Evacuation Failure

灰度第一台机器上跑了 6 小时,出现这个:

2020-07-08T14:22:41.331+0800: 12884.221: [GC pause (G1 Evacuation Pause) (young)
(to-space exhausted), 0.4123410 secs]
   [Parallel Time: 380.1 ms, GC Workers: 8]
      [GC Worker Start (ms): Min: 12884.2, Avg: 12884.3, Max: 12884.4, Diff: 0.2]
      [Ext Root Scanning (ms): Min: 0.3, Avg: 1.2, Max: 4.1, Diff: 3.8]
      [Update RS (ms): Min: 12.1, Avg: 18.4, Max: 24.8, Diff: 12.7]
      [Scan RS (ms): Min: 0.0, Avg: 2.1, Max: 5.3, Diff: 5.3]
      [Object Copy (ms): Min: 340.2, Avg: 356.8, Max: 371.2, Diff: 31.0]
      [Termination (ms): Min: 0.0, Avg: 0.1, Max: 0.2, Diff: 0.2]
   [Eden: 2048.0M(2048.0M)->0.0B(1808.0M) Survivors: 112.0M->96.0M Heap: 3802.4M(4096.0M)->3801.1M(4096.0M)]
 [Times: user=3.02 sys=0.08, real=0.41 secs]

to-space exhausted 是说:回收时需要把存活对象复制到新的 Region,但找不到空 Region 了。堆用了 3.8GB / 4GB,几乎满了。

根因是我把 -Xmx 从 CMS 时代的 4GB 原样搬了过来,但没考虑 G1 自己要占的开销。G1 需要维护 Remembered Set(每个 Region 一份,记录谁引用了我)、Card Table、还有并发标记期间的 SATB 队列,这些都在堆外或者堆内占地方。同时 G1 为了保证 to-space 有地方,要求堆留有一定的空闲 Region。

处理办法:把堆提到 6GB(容器内存从 6GB 加到 8GB),并把 -XX:G1ReservePercent 从默认 10 提到 15,预留更多空间给 to-space:

-XX:G1ReservePercent=15

改完之后再没出现过 to-space exhausted。这条经验是:从 CMS 迁 G1,堆至少要加 30%,别指望平迁。

第二个坑:Humongous 对象把老年代撑爆

第二个问题是老年代涨得不对劲。用 jstat -gcutil 观察,Mixed GC 之后老年代只降下去一点点,几个小时后 IHOP 就被触发。

$ jstat -gcutil 1 5000
  S0     S1     E      O      M     CCS    YGC     YGCT    FGC    FGCT     GCT
  0.00   0.00  68.42  71.33  94.12  91.02   8421  412.331     0   0.000  612.884

jmap -histo:live 看了下,排第一的是 byte[]

 num     #instances         #bytes  class name
----------------------------------------------
   1:         18432     1932735488  [B
   2:       1044123      133647744  [C

18432 个 byte[] 占了 1.8GB,平均每个 100KB。这是我们的一个导出接口,把查询结果一次性序列化成 Excel 的字节数组放内存里。

在 G1 里,大小超过 Region 一半的对象叫 Humongous 对象,直接分配在连续的 Humongous Region 里,且有以下特性:

  • 只在并发标记的 cleanup 阶段和 Full GC 时被回收,Mixed GC 不会回收它(G1 早期版本的行为,JDK 8u 之后有所优化但依然受限)。
  • 因为要连续空间,加速了堆碎片化。
  • 频繁创建会造成老年代占用快速上涨。

解决办法:把 100KB 的 Excel 字节数组改成流式写出,边查边写,不再攒整个数组:

// 改造前:全量查出来再序列化,峰值 100MB+
List<OrderExportVO> list = orderMapper.exportAll(query);
byte[] bytes = EasyExcel.write(...).sheet().doWrite(list);

// 改造后:分页查,直接写 OutputStream
response.setContentType("application/vnd.ms-excel");
try (ExcelWriter writer = EasyExcel.write(response.getOutputStream()).build()) {
    WriteSheet sheet = EasyExcel.writerSheet("订单").head(OrderExportVO.class).build();
    int page = 1;
    while (true) {
        List<OrderExportVO> chunk = orderMapper.exportPage(query, page++, 2000);
        if (chunk.isEmpty()) break;
        writer.write(chunk, sheet);
    }
}

另外把 RegionSize 从 2MB 提到 4MB,让 50KB~2MB 这个区间的对象不再是 Humongous:

-XX:G1HeapRegionSize=4M

注意 RegionSize 变大意味着单次回收的粒度变粗,小堆(< 4GB)别这么干。

第三个坑:Mixed GC 太保守

堆调大、Humongous 解决之后,出现新的情况:老年代一直维持在 60% 左右降不下来,Mixed GC 触发了但每次只回收很少。

看 GC 日志:

2020-07-12T09:14:22.118+0800: 48221.331: [GC pause (G1 Evacuation Pause) (mixed) 3.4G->3.3G(6.0G), 0.0884120 secs]
2020-07-12T09:14:31.204+0800: 48230.417: [GC pause (G1 Evacuation Pause) (mixed) 3.4G->3.3G(6.0G), 0.0912233 secs]

每次只回收 100MB,但耗时才 90ms——远没到 200ms 的目标。说明 G1 低估了自己的回收能力,选的 CSet 太小

这是 -XX:G1MixedGCLiveThresholdPercent=85 在起作用:存活对象超过 85% 的 Region 被排除。我们的老年代里很多是长期存活的缓存对象(Guava Cache 的本地缓存),这些 Region 存活率接近 100%,被排除了;剩下可选的 Region 太少。

调整方向有两个,我选了后者:

# 方案一:放宽阈值,让更多 Region 能进 CSet(回收利润低,耗时变长)
-XX:G1MixedGCLiveThresholdPercent=90

# 方案二:提高单次 Mixed GC 的数量目标,让回收持续更久
-XX:G1MixedGCCountTarget=16

改成 16 之后,Mixed GC 一轮能回收 800MB 左右,老年代稳定在 3.2GB~3.6GB 之间波动,不再单调上涨。

第四个坑:GC 日志读不懂,等于瞎调

G1 的日志信息量比 CMS 大得多,一开始我看那一大坨分段时间完全抓不住重点。慢慢摸索出三个必看的指标。

第一,Object Copy 的耗时占比。这是真正干活的时间(把存活对象复制到新 Region)。如果它占 Parallel Time 的 80% 以上,说明配置合理;如果 Update RS(更新 Remembered Set)或者 Scan RS(扫描 Remembered Set)占比高,说明跨 Region 引用太多。我们有个服务的 Update RS 一度占到 45%,排查下来是一个巨大的 ConcurrentHashMap 缓存——里面的对象互相引用,每次回收都要更新大量的 card 标记。后来把缓存拆成了几个独立的、内部自包含的结构,Update RS 降到 12%。

[Parallel Time: 380.1 ms, GC Workers: 8]
   [GC Worker Start (ms): Min: 12884.2, Avg: 12884.3, Max: 12884.4, Diff: 0.2]
   [Ext Root Scanning (ms): Min: 0.3, Avg: 1.2, Max: 4.1, Diff: 3.8]
   [Update RS (ms): Min: 12.1, Avg: 18.4, Max: 24.8, Diff: 12.7]     # 看这个
   [Scan RS (ms): Min: 0.0, Avg: 2.1, Max: 5.3, Diff: 5.3]           # 和这个
   [Object Copy (ms): Min: 340.2, Avg: 356.8, Max: 371.2, Diff: 31.0] # 应该占大头
   [Termination (ms): Min: 0.0, Avg: 0.1, Max: 0.2, Diff: 0.2]

第二,Diff 这一列。它是 Max 减 Min,反映 8 个 GC 工作线程的负载是否均衡。Object Copy 的 Diff 有 31ms(371 - 340),说明有线程干得多有线程干得少。G1 有工作窃取机制,但如果 Diff 持续超过平均值的 30%,通常是某些 Region 特别"重"。这个我们最后没进一步优化,1.8 秒的平均停顿已经达标了。

第三,Times 里的 real 和 user 之比

[Times: user=3.02 sys=0.08, real=0.41 secs]

8 个线程 user 时间 3.02 秒,real 只用了 0.41 秒,并行度 7.4(接近 8 核的理论值),说明并行正常。如果 user ≈ real,说明实际是单线程在跑,通常是容器 CPU 被限制了(我们 K8s 的 cpu limit 一开始设成了 1,导致 G1 以为有 8 核、实际只有 1 核可用,并行度暴跌)。这个用 Runtime.availableProcessors() 验证:

$ jcmd 1 VM.flags | grep -i 'ParallelGCThreads\|ConcGCThreads'
-XX:ConcGCThreads=4 -XX:ParallelGCThreads=8

$ jcmd 1 SystemProperties | grep processors
java.lang.Runtime.availableProcessors=8

JDK 8 的 availableProcessors() 不认 cgroup 限制,会读到宿主机的核数。JDK 8u191 之后加了 -XX:+UseContainerSupport(默认开启),但仍然值得手动确认。我们最后是显式指定 -XX:ParallelGCThreads=8 并让容器 limit 也是 8 核,对齐了就没问题。

最终配置和效果

# JDK 8u241
-Xms6g -Xmx6g
-XX:+UseG1GC
-XX:MaxGCPauseMillis=200
-XX:G1HeapRegionSize=4M
-XX:InitiatingHeapOccupancyPercent=45
-XX:G1MixedGCCountTarget=16
-XX:G1HeapWastePercent=5
-XX:G1ReservePercent=15
-XX:ConcGCThreads=4                    # 并发标记线程,默认 ParallelGCThreads/4
-XX:ParallelGCThreads=8                # STW 阶段并行线程,8 核容器
-XX:+ParallelRefProcEnabled            # 并行处理引用,减少 Ref Proc 阶段耗时
-XX:+PrintGCDetails -XX:+PrintGCDateStamps
-Xloggc:/data/logs/gc.log
-XX:+UseGCLogFileRotation -XX:NumberOfGCLogFiles=5 -XX:GCLogFileSize=100M

迁移前后对比(同一压测场景,QPS 3200,跑 30 分钟):

指标CMS(4GB 堆)G1(6GB 堆)
Minor/Young GC 平均42ms31ms
老年代回收 P991280ms310ms
最大停顿11400ms(Serial Old)640ms
Full GC 次数3 次/天0
GC 总耗时占比4.8%3.1%
内存开销4GB6GB

得与失

得到的:最大停顿从 11 秒降到 640 毫秒,Full GC 彻底消失,再也不用半夜起来处理 promotion failed。参数也统一了——6 个服务除了堆大小和暂停目标不同,其余参数完全一致,运维负担小了很多。碎片问题从原理上消失了,不用再配压缩相关的参数。

失去的:内存要多给 50%(4GB → 6GB),一年下来机器成本涨了大概两万块。G1 的 CPU 开销比 CMS 高一点(Remembered Set 的维护是持续的写屏障开销),我们观察到 CPU 平均上涨 2~3 个百分点。另外 G1 的日志比 CMS 难读得多,一开始看那一大坨 [Update RS]、[Scan RS]、[Object Copy] 的分段时间,我愣是看了两天才顺过来。

还有一个必须提的点:如果你的应用还在 JDK 8 早期版本,别急着上 G1。G1 在 8u40 之后才算真正成熟,我们用的是 8u241。JDK 11 上的 G1 又有很多改进(比如并行 Full GC、更快的 Remembered Set 处理),有条件的话升 JDK 11 收益更大。

下篇预告

这篇先把《G1 收集器调优实战:从 CMS 迁移的得与失》里的坑列了,下一篇写我们当时是怎么在线上工程里真正落地的——包括那次让领导拍桌的故障复盘。

参考