风控服务被 Full GC 拖出的长尾
2021 年 1 月底,风控服务的 P99 突然变差。这个服务是同步调用链路上的一环,上游给的超时是 800 ms,一旦它慢了,整个下单流程都会受影响。
当时的配置:JDK 8u272,8 G 堆,CMS + ParNew。
$ jstat -gcutil 12871 1000
S0 S1 E O M CCS YGC YGCT FGC FGCT GCT
0.00 12.34 87.21 78.45 94.12 91.03 48213 1823.411 47 142.882 1966.293
47 次 Full GC,总耗时 142.882 秒,平均每次 3.04 秒。也就是说从启动到现在,有 142 秒这个服务是完全没响应的。
摘一段 GC 日志:
2021-01-28T14:22:07.318+0800: 328941.221: [GC (Allocation Failure) 328941.221:
[ParNew (promotion failed): 3145728K->3145728K(3145728K), 1.8423010 secs]
[CMS: 5242891K->5242890K(5242880K), 4.6712030 secs]
8388603K->7340032K(8388608K), [Metaspace: 162341K->162341K(1181696K)],
6.5139980 secs] [Times: user=8.91 sys=0.14, real=6.51 secs]
promotion failed 是老问题了:老年代用的是 CMS,标记-清除算法,不做压缩,时间长了全是碎片。年轻代要晋升一个大对象上来,找不到连续空间,退化成 Serial Old 的单线程 Full GC,6.51 秒。
我们有个临时方案是每天凌晨定时重启,很丢人但有效。
为什么不选 G1
先试了 G1,这是最稳妥的选择:
-XX:+UseG1GC -Xmx8g -Xms8g -XX:MaxGCPauseMillis=200
G1 表现好很多,碎片问题没了(G1 会做 Evacuation,等于在整理)。但 P99 的毛刺依然在:
[GC pause (G1 Evacuation Pause) (young), 0.1873410 secs]
[GC pause (G1 Evacuation Pause) (mixed), 0.2918820 secs]
[GC pause (G1 Evacuation Pause) (young) (initial-mark), 0.3120490 secs]
单次 187 ms 到 312 ms,超过我们 200 ms 的目标。原因是 G1 的停顿时间和存活对象数量、Region 数量正相关,它不是"不管堆多大都快",只是把大停顿拆成了多次小停顿。
风控这个服务有个特点:堆里长期存活的规则对象很多(我们缓存了大约 180 万个规则节点在堆里),每次 Mixed GC 都要处理大量存活对象,所以停顿压不下去。
这时候我想起 ZGC。JDK 11 里它是实验特性,生产上用的团队不多,我决定先在压测环境验证一周。
ZGC 的两个核心机制
染色指针
ZGC 把对象的状态信息存在指向对象的指针里,而不是存在对象头里。在 64 位平台上,它从地址里借了高 4 位做标记位:
6 4 4 4 4 4 4 0
3 6 5 4 3 2 1 0
+--------------------+-+----+-+-----------------------------------------------+
|00000000 00000000 0 |0|1111|1|1 00000000 00000000 00000000 00000000 00000000 |
+--------------------+-+----+-+-----------------------------------------------+
| | |
| | * 47-43 地址位(JDK 11 支持 4 TB 堆)
| | * 45-42 unused
| * 46 Remapped
| * ... Marked1 / Marked0 / Finalizable
借位的直接后果:ZGC 不支持压缩指针(CompressedOops)。64 位 JVM 默认开启的 -XX:+UseCompressedOops 在 ZGC 下无效,所有对象引用从 4 字节变回 8 字节。我们这个服务堆里引用特别多,实测同样的堆大小,ZGC 模式下对象占用多了约 22%。
读屏障
对象被移动了,指针怎么更新?ZGC 不暂停所有线程去修指针,而是在应用线程读取对象引用时加一段代码(读屏障),检查指针的颜色位,如果对象已被移动,就根据转发表(forwarding table)把指针修正成新地址。
// 伪代码,实际是 JIT 生成的一段汇编
Object loadBarrier(Object* ref) {
if (isGoodColor(ref)) {
return ref; // 快路径,就几个指令
}
return slowPath(ref); // 慢路径:查转发表,自愈指针
}
这就是 ZGC 停顿只有几毫秒的原因:最耗时的"移动对象 + 修正所有引用"这一步是并发做的,分摊到了应用线程身上。STW 阶段只剩扫描 GC Roots,而 Roots 的数量跟堆大小基本无关(主要是线程栈和 JNI 引用)。
代价也很直接:读屏障是每次读引用都要执行的额外指令,这是 ZGC 吞吐量损失的主要来源。
压测数据
压测环境:4 核 8 G 容器,JDK 11.0.9,用生产流量回放,QPS 1200。
# CMS(基线)
-XX:+UseConcMarkSweepGC -Xmx6g -Xms6g
# G1
-XX:+UseG1GC -Xmx6g -Xms6g -XX:MaxGCPauseMillis=200
# ZGC(JDK 11 是实验特性,必须解锁)
-XX:+UnlockExperimentalVMOptions -XX:+UseZGC -Xmx6g -Xms6g
跑 30 分钟,结果:
| 指标 | CMS | G1 | ZGC |
|---|---|---|---|
| 平均停顿 | 112 ms | 94 ms | 0.42 ms |
| P99 停顿 | 1240 ms | 218 ms | 0.87 ms |
| 最大停顿 | 4310 ms | 312 ms | 1.71 ms |
| GC 总耗时占比 | 3.8% | 4.2% | 9.1% |
| 接口 P99 | 810 ms | 342 ms | 271 ms |
| CPU 使用率 | 41% | 44% | 58% |
| 堆占用(同样负载) | 3.9 GB | 3.6 GB | 4.8 GB |
停顿时间的改善是压倒性的:最大 4310 ms 降到 1.71 ms,2500 倍。
但代价一眼可见:
- CPU 从 44% 涨到 58%,涨了 14 个百分点。这是读屏障和并发 GC 线程的开销。
- 堆占用从 3.6 GB 涨到 4.8 GB,涨 33%。两个原因:没有压缩指针,以及 ZGC 的并发标记需要"标记期间新分配的对象都算存活",等于人为放大了存活集合。
- 吞吐量确实有损失。我单独用 SPECjbb2015 风格的纯计算压测(无 GC 压力)测过,ZGC 的吞吐比 G1 低约 8%~12%,跟官方公布的数据吻合。
一次完整 GC 要经历哪些阶段
把日志按阶段拆开看,能更清楚为什么 STW 那么短:
| 阶段 | 是否 STW | 干什么 | 我们的实测耗时 |
|---|---|---|---|
| Pause Mark Start | 是 | 扫描 GC Roots(线程栈、JNI),标记根直达对象 | 0.34 ms |
| Concurrent Mark | 否 | 从 Roots 出发并发遍历整个对象图 | 84 ms |
| Pause Mark End | 是 | 处理 SATB 队列,结束标记 | 0.42 ms |
| Concurrent Process Non-Strong | 否 | 处理软/弱/虚引用、终结队列 | 118 ms |
| Concurrent Select Relocation Set | 否 | 选要整理的 Region(ZGC 里叫 page) | 96 ms |
| Pause Relocate Start | 是 | 转移根直达对象 | 0.39 ms |
| Concurrent Relocate | 否 | 并发移动对象,靠读屏障自愈指针 | 264 ms |
三个 STW 阶段加起来 1.15 ms,而并发阶段一共 562 ms。这就是全部的秘密:耗时的活全搬到并发阶段去了。
对比一下 G1:G1 的 Evacuation 阶段必须 STW,因为它要把存活对象复制到新 Region,同时更新所有指向它们的引用。ZGC 的染色指针 + 读屏障让这一步能并发做,这是架构级的差异,不是参数调优能追上的。
和 Shenandoah 的简要对比
顺便说一下 Red Hat 的 Shenandoah,它也是低延迟收集器,思路不同:用 Brooks Pointer(对象头里加一个转发指针)而不是染色指针,配读屏障 + 写屏障。
我们没选它的原因很实际:Shenandoah 在 Oracle 官方的 OpenJDK 构建里默认不提供,只有 Red Hat 的发行版(比如 CentOS 上的 java-11-openjdk)才带。我们的基础镜像用的是 openjdk:11-jre-slim(Docker Hub 官方镜像,基于 Oracle 的 OpenJDK 构建),里面没有 Shenandoah,只有 ZGC。
两者性能上差别不大,都是毫秒级停顿,都能做到停顿时间与堆大小无关。选哪个更多是看你的 JDK 来源。
灰度上线
2 月初,我先拿一个实例做灰度,观察 3 天。
-XX:+UnlockExperimentalVMOptions
-XX:+UseZGC
-Xmx10g -Xms10g
-XX:ConcGCThreads=2
-XX:ParallelGCThreads=6
-Xlog:gc*:file=/data/logs/gc-zgc.log:time,uptime,level,tags:filecount=10,filesize=64m
三个参数的理由:
-Xmx = -Xms。ZGC 的堆扩容需要触发 GC,代价不小。固定堆大小能让 GC 节奏更平稳。ConcGCThreads=2。并发 GC 线程默认是 CPU 核数的 1/8,4 核机器只给 1 个。我们 CPU 有余量,给 2 个加快回收,避免分配速率跟不上。Xlog而不是PrintGCDetails。JDK 9 之后统一日志框架,老参数在 JDK 11 上会告警。
ZGC 的日志长这样,和 CMS 完全不同:
[2021-02-03T11:22:41.318+0800][info][gc] GC(1234) Pause Mark Start 0.341ms
[2021-02-03T11:22:41.402+0800][info][gc] GC(1234) Concurrent Mark 84.221ms
[2021-02-03T11:22:41.403+0800][info][gc] GC(1234) Pause Mark End 0.418ms
[2021-02-03T11:22:41.521+0800][info][gc] GC(1234) Concurrent Process Non-Strong References 118.402ms
[2021-02-03T11:22:41.522+0800][info][gc] GC(1234) Concurrent Reset Relocation Set 0.021ms
[2021-02-03T11:22:41.618+0800][info][gc] GC(1234) Concurrent Select Relocation Set 96.118ms
[2021-02-03T11:22:41.620+0800][info][gc] GC(1234) Pause Relocate Start 0.394ms
[2021-02-03T11:22:41.884+0800][info][gc] GC(1234) Concurrent Relocate 263.882ms
注意 Pause 开头的都是 STW,全部是 0.3~0.5 ms。Concurrent 开头的耗时长(几百毫秒),但不暂停应用线程。
踩到的一个坑:Allocation Stall
灰度第二天早上,监控出现一次 P99 尖刺,1.8 秒。查日志找到了:
[2021-02-04T09:14:22.118+0800][info][gc] Allocation Stall (main) 1243.882ms
[2021-02-04T09:14:22.119+0800][info][gc] GC(2891) Pause Mark Start 0.412ms
Allocation Stall 的意思是:对象分配速度太快,GC 来不及回收,新线程分配内存被阻塞了。这不是 STW,但效果一样——线程卡住等着内存。
触发原因是早上 9 点有大促预热,缓存批量加载,瞬间产生大量对象。ZGC 不像 G1 那样在堆占用到一定比例就提前开始 GC,它靠预测模型(ZAllocationSpikeTolerance)决定何时启动。
解决办法有两个,我们都用了:
# 1. 调大 spike tolerance,让 ZGC 对分配尖刺更敏感,提前启动 GC
-XX:ZAllocationSpikeTolerance=4 # 默认 2
# 2. 加大堆,给 GC 更多缓冲空间
-Xmx12g -Xms12g
另外把缓存加载改成了错峰,一次只加载 5000 条。改完之后 Allocation Stall 没有再出现过。
什么场景该上 ZGC
全量铺开三个月后的一些判断:
| 场景 | 建议 | 理由 |
|---|---|---|
| 同步接口,延迟敏感,堆 > 8 G | 适合 | 停顿从百毫秒降到 1 ms 内 |
| 堆 < 4 G | 不划算 | 没有压缩指针,内存反而更紧张;G1 停顿本来也不高 |
| 离线批处理、报表计算 | 不适合 | 吞吐掉 8%~12%,这类任务只看总耗时 |
| CPU 已经跑满的服务 | 不适合 | 读屏障 + 并发 GC 线程再加 14 个点的 CPU |
| 对象分配速率极高且平稳 | 谨慎 | 容易 Allocation Stall,要留足堆余量 |
我们最后只有风控和商品详情两个服务用 ZGC,都是同步链路、堆 10~12 G。对账和报表服务保留 G1,因为它们是吞吐优先的。
小结
- ZGC 把对象状态存在指针里(染色指针),代价是不支持压缩指针,我们实测堆占用多 22%。
- 读屏障让"移动对象 + 修引用"能并发做,STW 只剩扫 GC Roots,所以停顿跟堆大小基本无关。我们最大停顿从 4310 ms 降到 1.71 ms。
- 代价是三项:CPU 涨 14 个百分点、堆占用涨 33%、吞吐掉 8%~12%。
- JDK 11 上必须加
-XX:+UnlockExperimentalVMOptions。建议-Xmx等于-Xms。 - 盯日志里的
Allocation Stall,它不等于 STW 但一样会让线程卡住。我们靠ZAllocationSpikeTolerance=4和大堆解决。 - 小堆和吞吐优先的任务别上 ZGC,G1 更合适。
还有一句提醒:ZGC 在 JDK 11 是实验特性(experimental),到 JDK 15 才转正。我们敢上是因为风控服务挂了有降级兜底,而且灰度观察了三天。如果你的服务是那种"停 5 分钟就上新闻"的,建议等 ZGC 转正、或者先把降级兜底做扎实再动。