运维在群里 @ 我:你们这个服务内存一直在涨
那天下午运维丢了一张图到群里,是 Zabbix 上我们订单服务的 JVM 内存曲线,从早上 9 点的 1.2 GB 一路爬到下午 4 点的 3.8 GB,容器限制是 4 GB。他问:这是不是内存泄漏?
我当时的第一反应是想 dump 下来看,被带我的师兄拦住了。他说别急,先看十分钟曲线再说。后来证明这个顺序很重要,我把整套流程记下来。
jstat:先判断是泄漏还是正常的锯齿
JVM 的内存曲线本来就该是锯齿状的,对象在 Eden 区生、YGC 时被回收,老年代慢慢涨、FGC 时掉下来。如果它一直在涨且不回落,才叫可疑。
登机器,先找到 PID:
$ jps -l
18304 /app/order-service.jar
21947 sun.tools.jps.Jps
然后每 5 秒采一次 GC 数据,采 20 次:
$ jstat -gcutil 18304 5000 20
S0 S1 E O M CCS YGC YGCT FGC FGCT GCT
0.00 98.43 67.21 41.05 95.12 92.88 1843 38.472 3 1.203 39.675
0.00 98.43 84.66 41.05 95.12 92.88 1843 38.472 3 1.203 39.675
62.15 0.00 3.88 41.32 95.12 92.88 1844 38.493 3 1.203 39.696
62.15 0.00 21.40 41.32 95.12 92.88 1844 38.493 3 1.203 39.696
0.00 71.08 9.75 41.58 95.12 92.88 1845 38.511 3 1.203 39.714
几个字段的意思:
S0/S1/E/O:两个 Survivor 区、Eden 区、老年代的已用百分比M:Metaspace 使用率,CCS:压缩类空间使用率YGC/YGCT:Young GC 次数和累计耗时FGC/FGCT:Full GC 次数和累计耗时
这 100 秒里 YGC 发生了 3 次,大概 30 秒一次,每次 20 毫秒左右,很正常。关键看 O 这一列:41.05 → 41.32 → 41.58,每次 YGC 之后老年代都涨一点,而且 FGC 一直是 3 次没变过。老年代容量是 2 GB,41% 就是 860 MB,涨速大约每分钟 3 MB。
这个形态很像泄漏。但也可能只是对象晋升速度比较快,得看更长时间。我又开着采了半小时,老年代到了 48%,FGC 涨到 5 次,每次 FGC 之后只掉下去 0.5 个百分点——回收不掉,基本可以定性是泄漏了。
补充一个我常看的:jstat -gc 18304 输出的是实际字节数(KB),适合算精确的晋升量;-gcutil 是百分比,适合看趋势。想看最近一次 GC 的原因用 jstat -gccause,它多两列 LGCC(上次 GC 原因)和 GCC(当前 GC 原因)。
jmap -histo:不 dump 就能看到大对象
确认泄漏之后,别急着 dump。先试这个:
$ jmap -histo 18304 | head -20
num #instances #bytes class name
----------------------------------------------
1: 128463 71859120 [B
2: 98421 23456784 [Ljava.util.HashMap$Node;
3: 482015 15424480 java.util.HashMap$Node
4: 478932 11494368 java.lang.String
5: 1204 9284600 [Ljava.lang.Object;
6: 98217 3142944 com.xxx.order.dto.OrderDetailDTO
[B 是 byte 数组,128463 个实例占了 68 MB。OrderDetailDTO 有 98217 个,而这个时候系统里活跃订单撑死 3000 单——多出来的 9 万多个肯定是被谁攥着不放。
按类名过滤一下,看更准:
$ jmap -histo 18304 | grep com.xxx.order
6: 98217 3142944 com.xxx.order.dto.OrderDetailDTO
41: 98217 2357208 com.xxx.order.vo.OrderListVO
数量一模一样,98217。这两个类是一对一的关系,说明有个地方在往容器里塞 OrderListVO。全局搜这个类的引用,找到了:
@Component
public class OrderQueryCache {
// 当初为了"避免重复查库"加的本地缓存,没有过期策略
private static final Map<Long, OrderListVO> CACHE = new HashMap<>();
public OrderListVO query(Long userId) {
OrderListVO vo = CACHE.get(userId);
if (vo != null) {
return vo;
}
vo = orderMapper.listByUser(userId);
CACHE.put(userId, vo);
return vo;
}
}
一个 static 的 HashMap,只 put 不 remove,key 是 userId。跑了 4 个月,积累 9.8 万个用户的订单列表,其中每个 OrderListVO 里还挂着平均 12 条 OrderDetailDTO。这就是 68 MB byte 数组的来源——OrderDetailDTO 里那个 remark 字段。
这个坑是我自己三个月前埋的,当时觉得"用户量不大,缓存一下没坏处"。
jmap -dump:什么时候该 dump
上面那个例子靠 -histo 就够了,因为类名直接露了馅。但如果 -histo 第一名是 java.lang.Object[] 或者 char[] 这种看不出归属的,才需要 dump 出完整快照用 MAT 分析引用链。
dump 有两个必须注意的点:
第一,-histo:live 和 -dump:live 会先触发一次 Full GC。:live 参数的意思是"只统计活对象",JVM 必须先做一次完整 GC 才能知道谁是活的。我们这台机器老年代 860 MB,一次 FGC 耗时 1.1 秒,整个进程 Stop The World。线上高峰期不要干这事。
# 会触发 Full GC
$ jmap -dump:live,format=b,file=/tmp/order.hprof 18304
# 不触发 Full GC,但文件更大(包含待回收对象),且会 STW
$ jmap -dump:format=b,file=/tmp/order.hprof 18304
第二,dump 过程本身是 STW 的,耗时和堆大小成正比。我们 2 GB 堆 dump 出来 1.8 GB 文件,耗时 23 秒,这 23 秒里服务完全不响应。所以 dump 之前一定要先摘流量。
我们的做法是:先在注册中心把这台实例下线,等 30 秒让存量请求跑完,再 dump,dump 完直接重启(反正要发版修 bug),不用摘完再挂上去。整个流程写成了脚本:
#!/bin/bash
PID=$1
# 1. 摘流量
curl -X POST "http://127.0.0.1:8080/actuator/service-registry?status=DOWN" \
-H "Content-Type: application/vnd.spring-boot.actuator.v2+json"
sleep 30
# 2. dump
jmap -dump:format=b,file=/data/dump/order-$(date +%Y%m%d%H%M).hprof $PID
# 3. 打印一下瞬时状态留档
jstack $PID > /data/dump/order-$(date +%Y%m%d%H%M).stack
# 4. 重启
kill -15 $PID
还有个备选方案是加 -XX:+HeapDumpOnOutOfMemoryError -XX:HeapDumpPath=/data/dump 让 JVM 在 OOM 时自动 dump。好处是能抓到出事那一刻的现场,坏处是 OOM 时堆已经很大,dump 时间可能几分钟,而且文件动辄好几个 GB。这个参数我们所有服务都默认开着,但真出事时它的文件往往救不了急,还是得靠人工在低水位时抓。
dump 出来的文件用 Eclipse MAT 打开,看 Histogram → 右键 → Merge Shortest Paths to GC Roots,就能看到是谁在持有这些对象。那次我看到的是 OrderQueryCache.CACHE 这条静态引用链,和 -histo 的推断一致。
jstack:顺手看一眼线程
内存问题不需要 jstack,但我养成了习惯,dump 之前先存一份,因为重启之后现场就没了。另一个常用场景是 CPU 飙高时定位线程,套路是:
# 1. 找到占用 CPU 最高的线程
$ top -H -p 18304
PID USER PR NI VIRT RES SHR S %CPU %MEM
18341 app 20 0 8123m 3.8g 14m R 92.3 47.1
# 2. 转成十六进制(jstack 里的 nid 是十六进制的)
$ printf '%x\n' 18341
47a5
# 3. 在 jstack 输出里搜这个 nid
$ jstack 18304 > /tmp/stack.txt
$ grep -A 20 'nid=0x47a5' /tmp/stack.txt
"pool-7-thread-3" #68 prio=5 os_prio=0 tid=0x00007f2c1c0e8000 nid=0x47a5 runnable
java.lang.Thread.State: RUNNABLE
at java.util.HashMap.getNode(HashMap.java:571)
at java.util.HashMap.get(HashMap.java:557)
at com.xxx.order.OrderQueryCache.query(OrderQueryCache.java:24)
顺便提一句,那次打印出来的 jstack 里我还看到线程总数 418 个,其中 http-nio-8080-exec-* 有 200 个(Tomcat 默认 maxThreads),另外还有 6 个不同名字的业务线程池各自开了 20~50 个。线程不是无限的资源,每个线程默认栈大小 1 MB(-Xss),418 个线程光栈就占了 400 MB 的虚拟内存。后来我们统一收敛到 3 个池子。
下篇预告
这篇先把《jmap、jstat、jstack 三板斧排查内存问题》里的坑列了,下一篇写我们当时是怎么在线上工程里真正落地的——包括那次让领导拍桌的故障复盘。