十月的一个早晨:Full GC 每小时 40 次
十月二十六号一早,监控群里机器人在刷告警。报表服务的 Full GC 频率从平时的每小时 0~1 次,涨到了 40 次。
$ jstat -gcutil 1 2000 10
S0 S1 E O M CCS YGC YGCT FGC FGCT GCT
0.00 99.80 88.42 99.87 94.12 91.02 48213 812.331 412 2841.220 3653.551
0.00 99.80 92.11 99.91 94.12 91.02 48214 812.348 413 2848.104 3660.452
0.00 99.80 96.33 99.94 94.12 91.02 48215 812.361 414 2855.338 3667.699
老年代(O)常年 99.8% 以上,每次 Young GC 之后又迅速涨回来。Full GC 平均单次耗时 6.9 秒(2841 秒 / 412 次)。Young GC 才 4.8 万次,说明对象根本没在新生代被回收掉,直接进了老年代。
看 GC 日志(我们用的 CMS,JDK 8):
2020-10-26T08:12:41.882+0800: 88421.331: [GC (Allocation Failure) 88421.331: [ParNew: 314528K->34928K(314560K), 0.0412280 secs]
2410688K->2409888K(4194304K), 0.0419120 secs] [Times: user=0.32 sys=0.01, real=0.04 secs]
2020-10-26T08:12:41.924+0800: 88421.373: [Full GC (Allocation Failure) 88421.373: [CMS: 2374960K->2374931K(2374400K), 6.8824410 secs]
2409888K->2409859K(4194304K), [Metaspace: 132104K->132104K(262144K)], 6.8831120 secs]
注意这一行:CMS: 2374960K->2374931K。Full GC 前后老年代几乎没变(只回收了 29KB),说明老年代里全是存活对象,不是内存泄漏导致的回收不掉,而是真的有 2.3GB 的活对象。
再加上耗时 6.88 秒——正常情况下 CMS 的 Full GC 不该这么久。这么长的耗时加上几乎没回收,指向一个可能性:老年代里有大量大对象,标记和清理都很耗时。
先看堆里是什么
在 GC 之前先抓一份堆转储。注意 jmap -dump 会触发一次 Full GC 并且 STW,生产上要谨慎(我们是在从节点上摘流量之后做的)。
$ jmap -dump:live,format=b,file=/tmp/report.hprof 1
Dumping heap to /tmp/report.hprof ...
Heap dump file created [2841128312 bytes]
$ ls -lh /tmp/report.hprof
-rw------- 1 root root 2.7G Oct 26 08:31 /tmp/report.hprof
MAT(Memory Analyzer Tool 1.10)打开,先看 Dominator Tree:
Class Name | Objects | Shallow Heap | Retained Heap
------------------------------------------------------------------------------------------------
byte[] | 18,432 | 2,013,265,920 | 2,013,265,920
|- byte[104857600] @ 0x6c2a14c08 .................. | 1 | 104,857,616 | 104,857,616
|- byte[104857600] @ 0x6c2a14c10 .................. | 1 | 104,857,616 | 104,857,616
|- byte[104857600] @ 0x6c2a14c18 .................. | 1 | 104,857,616 | 104,857,616
... 共 18 个 100MB 的 byte[] ...
------------------------------------------------------------------------------------------------
char[] | 882,133 | 98,241,120 |
java.util.HashMap$Node | 421,882 | 13,500,224 |
18432 个 byte[],占了 2.01GB,其中明显有一批正好是 104857600 字节(100MB)的。这数字太整了,肯定不是自然产生的。
右键看其中一个 100MB byte[] 的 GC Root 路径(Path to GC Roots,排除软/弱/虚引用):
byte[104857600] @ 0x6c2a14c08
|- value java.io.ByteArrayOutputStream @ 0x6c2a14bf0
|- buf com.xxx.excel.PoiWorkbookHolder @ 0x6c2a14c00
|- value java.lang.ThreadLocal$ThreadLocalMap$Entry @ 0x6c2a14be8
|- [0] java.lang.ThreadLocal$ThreadLocalMap$Entry[] @ 0x6c2a14bd0
|- table java.lang.ThreadLocal$ThreadLocalMap @ 0x6c2a14bb8
|- threadLocals java.lang.Thread "report-gen-3" @ 0x6c2a14ba0
引用链很清楚:一个叫 report-gen-3 的线程,它的 ThreadLocal 里挂着一个 ByteArrayOutputStream,里面是 100MB 的缓冲。
代码长什么样
@Service
public class ExcelExportService {
// 复用 ByteArrayOutputStream,避免每次 new(当年觉得这是个优化)
private static final ThreadLocal<ByteArrayOutputStream> BUFFER_HOLDER =
ThreadLocal.withInitial(ByteArrayOutputStream::new);
public byte[] export(ReportQuery query) {
ByteArrayOutputStream buffer = BUFFER_HOLDER.get();
buffer.reset();
Workbook workbook = new XSSFWorkbook(); // POI 3.17
Sheet sheet = workbook.createSheet("报表");
List<ReportRow> rows = reportMapper.queryAll(query); // 一次查 80 万行
for (int i = 0; i < rows.size(); i++) {
Row row = sheet.createRow(i);
// ... 填充 20 列
}
workbook.write(buffer);
workbook.close();
return buffer.toByteArray();
}
}
三个问题叠在一起:
问题一:ByteArrayOutputStream 的容量只增不减。 它内部是个 byte[],容量不够时按 newCapacity = oldCapacity << 1 翻倍扩容,但 reset() 只把 count 置 0,不会缩小底层数组。一旦某次导出了 100MB,这个线程的 buffer 就永久占着 100MB。我们有 32 个 report-gen 线程,18 个跑过大报表,就是 1.8GB。
问题二:ThreadLocal 被线程池里的线程持有。 这些线程是池化的,永不销毁,ThreadLocal 的值也就永不释放。而且我们自始至终没调用过 remove()。
问题三:这个 100MB 的数组是大对象,直接进老年代。 这就是标题里说的那个机制。
PretenureSizeThreshold:大对象直接进入老年代
JVM 有个参数 -XX:PretenureSizeThreshold,超过这个大小的对象直接在老年代分配,不经过新生代。
-XX:PretenureSizeThreshold=3145728 # 3MB
我们这个服务的启动参数里就有这条(是前人配的,我一开始没注意到)。所以那 18 个 100MB 的 byte[],一个都不经过 Eden,直接分配在老年代。
这个设计的初衷是合理的:大对象在新生代里复制来复制去成本极高(100MB 的对象在 Eden 和 Survivor 之间复制一次就是几百毫秒),而且大对象通常存活时间长(缓存、缓冲区),在新生代待着也是浪费。所以干脆直接放老年代,避免复制开销。
但它的副作用是:大对象绕过了新生代的"快速死亡"通道。正常情况下,一个朝生夕死的对象在 Minor GC 时就被回收了,成本极低。而一旦它进了老年代,就只能等 Major GC / Full GC 才能回收。
我们这个案例更极端——这些 byte[] 因为被 ThreadLocal 引用着,根本不是垃圾,Full GC 也回收不掉。2.3GB 的老年代被它们占满,剩下的业务对象在 Eden 里稍微一涨就触发晋升失败,于是每秒一次 Full GC。
顺便说明一个容易搞混的点:PretenureSizeThreshold 只对 Serial 和 ParNew 收集器有效。我们用的 CMS,新生代默认就是 ParNew,所以生效。如果用的是 Parallel Scavenge 或者 G1,这个参数无效(G1 有自己的 Humongous 判定规则:超过 Region 一半算大对象,直接进 Humongous Region)。
验证:模拟一次
我写了个小程序在测试环境复现,参数对齐生产:
// -Xms512m -Xmx512m -XX:+UseConcMarkSweepGC -XX:PretenureSizeThreshold=3145728
public class PretenureDemo {
static final ThreadLocal<byte[]> HOLDER = new ThreadLocal<>();
public static void main(String[] args) throws Exception {
ExecutorService pool = Executors.newFixedThreadPool(4);
for (int i = 0; i < 40; i++) {
pool.submit(() -> {
// 每个线程持有一个 20MB 的数组
HOLDER.set(new byte[20 * 1024 * 1024]);
try { Thread.sleep(2000); } catch (InterruptedException e) {}
});
}
Thread.sleep(60000);
}
}
$ jstat -gcutil $(jcmd -l | grep PretenureDemo | awk '{print $1}') 1000
S0 S1 E O M CCS YGC YGCT FGC FGCT GCT
0.00 0.00 4.00 8.14 94.31 91.02 0 0.000 0 0.000 0.000
0.00 0.00 8.02 68.24 94.31 91.02 0 0.000 0 0.000 0.000
0.00 0.00 12.11 98.87 94.31 91.02 1 0.012 1 0.184 0.196
0.00 0.00 16.33 98.91 94.31 91.02 2 0.024 3 0.552 0.576
Eden 才用了 4%~16%,老年代已经 98%。YGC 次数很少(对象根本没进新生代),但 Full GC 频繁。这和生产上的现象完全吻合。
去掉 -XX:PretenureSizeThreshold 再跑一次(20MB 对象在默认的 MaxTenuringThreshold=6 下依然会晋升,但至少会经过几次 Minor GC):
S0 S1 E O M CCS YGC YGCT FGC FGCT GCT
99.80 0.00 88.42 68.24 ... 12 0.184 0 0.000 0.184
0.00 99.80 12.11 72.31 ... 18 0.241 1 0.092 0.333
行为完全变了。当然这个 demo 里因为 ThreadLocal 持有,最终还是会进老年代——参数只是改变了路径,改变不了生命周期。
真正的修复
第一步:ThreadLocal 用完必须 remove
这是最根本的问题。ThreadLocal 配线程池是经典陷阱——线程不销毁,ThreadLocal 的值就一直挂在 ThreadLocalMap 上。而 ThreadLocalMap 的 key 是弱引用(会被 GC 回收),但 value 是强引用,不会。key 变成 null 之后 value 还在,造成泄漏,直到这个 Entry 被清理(ThreadLocalMap 的 expungeStaleEntry 只在特定时机触发)。
public byte[] export(ReportQuery query) {
try {
ByteArrayOutputStream buffer = BUFFER_HOLDER.get();
buffer.reset();
// ... 导出逻辑
return buffer.toByteArray();
} finally {
// 用完立刻清掉,让 byte[] 可以被 GC
BUFFER_HOLDER.remove();
}
}
第二步:别缓存大缓冲区,改成流式导出
复用 ByteArrayOutputStream 这个"优化"本身就是错的。100MB 的数组常驻内存,换来的是每次省一次数组分配(几十微秒)。正确的做法是流式写出,不攒整个数组:
public void export(HttpServletResponse response, ReportQuery query) throws IOException {
response.setContentType("application/vnd.openxmlformats-officedocument.spreadsheetml.sheet");
response.setHeader("Content-Disposition", "attachment; filename=report.xlsx");
// SXSSFWorkbook 是 POI 的流式版本,只在内存保留 windowSize 行
try (SXSSFWorkbook workbook = new SXSSFWorkbook(1000); // 内存中最多 1000 行
ServletOutputStream out = response.getOutputStream()) {
Sheet sheet = workbook.createSheet("报表");
int rowIndex = 0;
int page = 1;
while (true) {
List<ReportRow> rows = reportMapper.queryPage(query, page++, 2000);
if (rows.isEmpty()) break;
for (ReportRow r : rows) {
Row row = sheet.createRow(rowIndex++);
// 填充...
}
// SXSSF 会把超出窗口的行刷到磁盘临时文件
}
workbook.write(out);
}
// SXSSFWorkbook 用完必须 dispose,删临时文件
}
SXSSFWorkbook(POI 3.8+)是专门解决大文件导出 OOM 的。它只在内存里保留 windowSize 行,超出的刷到临时文件。80 万行的导出,内存从 2GB 降到 180MB。
注意两个点:SXSSFWorkbook 一定要 dispose()(try-with-resources 会自动调),否则临时文件不删;用它的 Row 对象在刷盘之后不能再访问(会抛异常)。
第三步:分页查,别一次查 80 万行
reportMapper.queryAll(query) 一次把 80 万行读进内存,光是 List<ReportRow> 本身就占 400MB。改成上面那样 2000 行一页地查。MyBatis 的 RowBounds 是内存分页(查出全部再截取),不能用,必须写 LIMIT offset, size。
而且深分页会有性能问题(offset 越大越慢),我们用"上一页最大 id"做游标:
<select id="queryPage" resultType="ReportRow">
SELECT id, order_no, amount, create_time, ...
FROM t_report_detail
WHERE create_time >= #{startTime}
AND create_time < #{endTime}
AND id > #{lastId} /* 游标,避免 offset 深分页 */
ORDER BY id
LIMIT #{size}
</select>
第四步:把 PretenureSizeThreshold 调大
这条是辅助手段。原来设的 3MB 太小了,正常业务里 3MB 的对象并不罕见(一个稍大的查询结果集、一张图片的处理缓冲)。我们调到了 16MB:
-XX:PretenureSizeThreshold=16777216
原则是:这个阈值应该大于"绝大多数正常业务对象的大小",只让真正的大对象走老年代快车道。设太小会让大量本可以在新生代消亡的对象提前进老年代,反而加剧 Full GC。
修复前后
| 指标 | 修复前 | 修复后 |
|---|---|---|
| Full GC 频率 | 40 次/小时 | 0 |
| Full GC 平均耗时 | 6900ms | — |
| 老年代占用 | 99.8% | 34% |
| 导出 80 万行内存峰值 | 2.1GB | 180MB |
| 导出 80 万行耗时 | 42 秒 | 28 秒 |
| 接口 TP99 | 8400ms | 210ms |
导出反而更快了,因为 SXSSF 边写边刷,不用在最后一次性序列化 100MB 的数组。
排查这类问题的套路
总结一下这次摸索出来的流程:
- 先看
jstat -gcutil。如果老年代长期高位 + Full GC 后回收不掉,说明是活对象太多不是泄漏(泄漏的话 Full GC 后老年代会明显下降)。Young GC 次数少而 Full GC 频繁 → 对象没走新生代 → 怀疑大对象。 - 看 GC 日志里 Full GC 前后的老年代大小。
CMS: 2374960K->2374931K这种几乎没变的,是活对象占满;变成2374960K->800000K的,是有大量可回收的垃圾。 - heap dump 用 MAT 的 Dominator Tree,按 Retained Heap 排序。如果
byte[]/char[]排第一且大小很整(1048576、104857600 这种),一定是自己代码里分配的大数组。 - Path to GC Roots 排除弱引用,找到持有者。挂在
Thread→threadLocals上的,就是 ThreadLocal 泄漏。 - 检查启动参数里的
PretenureSizeThreshold。这个参数很多项目是抄来的,配了但没人知道。
几个命令备查:
# 看参数是否生效
$ jinfo -flag PretenureSizeThreshold 1
-XX:PretenureSizeThreshold=3145728
# 在线看各年龄段对象大小(JDK 8 需要装 jol 或者用 jmap -histo)
$ jmap -histo:live 1 | head -20
# 只看某个类的实例数
$ jmap -histo:live 1 | grep '\[B'
1: 18432 2013265920 [B
# GC 原因统计
$ jstat -gccause 1 2000
写在后面
现在回头看,《一次 Full GC 频繁的排查:大对象直接进入老年代》本身不算多难,难的是线上真出问题那十分钟里的判断。经验都是这么来的。