Full GC (Allocation Failure) 引发的应用僵死

距离上次博文已经有快半年了。原本打算在过年期间写一篇2019年的回顾和总结。但也被这突如其来的疫情打乱。放假期间一直关注相关新闻导致信息过载,一度非常沮丧。

2月复工以后,停止了疫情信息的摄取,反倒心理上轻松不少。人都是健忘的,可不是吗?

言归正传,上篇博文说遇到一个服务假死的问题,具体现象就是服务不再接收任何请求,客户端会抛出Broken Pipe。正好最近又重现了,并且找到了root cause。

检查状态

系统状态

依然从全局入手,执行top查看发现负载很低,cpu都在10%以下,说明不是计算密集的问题,基本可以感觉是io或者是jvm垃圾回收有异常。另外查询系统情况推荐dstat这个工具,蜜汁好用。

1
dstat -lcdngy

JVM状态

因为开启了gc log,所以先检查一下是不是有频繁的full gc,当然上手就jstat不犹豫也是没问题的。

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
2020-02-19T17:32:59.041+0800: 5618.660: Application time: 0.9945668 seconds
{Heap before GC invocations=339 (full 70):
par new generation total 1415616K, used 1415615K [0x00000006f0800000, 0x0000000750800000, 0x0000000750800000)
eden space 1258368K, 100% used [0x00000006f0800000, 0x000000073d4e0000, 0x000000073d4e0000)
from space 157248K, 99% used [0x000000073d4e0000, 0x0000000746e6ffd0, 0x0000000746e70000)
to space 157248K, 0% used [0x0000000746e70000, 0x0000000746e70000, 0x0000000750800000)
concurrent mark-sweep generation total 2621440K, used 2621440K [0x0000000750800000, 0x00000007f0800000, 0x00000007f0800000)
Metaspace used 124199K, capacity 131576K, committed 135808K, reserved 1169408K
class space used 14564K, capacity 15735K, committed 16256K, reserved 1048576K
2020-02-19T17:32:59.042+0800: 5618.661: [Full GC (Allocation Failure) 2020-02-19T17:32:59.043+0800: 5618.661: [CMS2020-02-19T17:33:00.282+0800: 5619.901: [CMS-concurrent-mark: 2.232/2.235 secs] [Times: user=3.23 sys=0.00, real=2.24 secs]
(concurrent mode failure): 2621440K->2611778K(2621440K), 7.6795988 secs] 4037055K->2611778K(4037056K), [Metaspace: 124199K->124199K(1169408K)], 7.6798738 secs] [Times: user=7.68 sys=0.00, real=7.68 secs]
Heap after GC invocations=340 (full 71):
par new generation total 1415616K, used 0K [0x00000006f0800000, 0x0000000750800000, 0x0000000750800000)
eden space 1258368K, 0% used [0x00000006f0800000, 0x00000006f0800000, 0x000000073d4e0000)
from space 157248K, 0% used [0x000000073d4e0000, 0x000000073d4e0000, 0x0000000746e70000)
to space 157248K, 0% used [0x0000000746e70000, 0x0000000746e70000, 0x0000000750800000)
concurrent mark-sweep generation total 2621440K, used 2611778K [0x0000000750800000, 0x00000007f0800000, 0x00000007f0800000)
Metaspace used 124199K, capacity 131576K, committed 135808K, reserved 1169408K
class space used 14564K, capacity 15735K, committed 16256K, reserved 1048576K
}

大概有十几个Full GC,原因都是 Allocation Failure。特别值得注意的是,GC前eden的占用是100%,s0的占用是99%,此时还有Allocation Failure说明old区也满了。eden和s0的对象都无法通过Young GC回收,年轻代对象继续向old区晋升,但是old区也满了,导致 Allocation Failure 触发Full GC,而且耗时7.68 secs,这可是STW啊,整个系统都暂停响应了。再看GC后的情况,年轻代都清零了,说明并不是有内存泄露导致无法回收。而是短时间有大量新对象被创建,Young GC来不及回收,直到新对象不断晋升到老年代导致的STW。

那么接下来就开始追查什么原因会创建这么多新对象,手头缺一个最好的证据,就是Full GC时的heap dump。开启jstat不停的刷,等到old区快满的时候,抓dump。

时机正好,通过jmap导出dump文件

1
jmap -dump:format=b,file=/tmp/heap.hprof 1

一看文件足足有6g,说明真的是待回收的对象太多了。

分析Dump

使用mat打开这个dump文件都花了半小时,风扇呼呼的在抗议。一个小tip,记得把mat的Xmx调大,不然会崩掉。另外由于这次并不是内存泄露造成不可回收,所以需要打开mat的Keep unreachable objects去分析不可触达的对象。

打开lead suspects可以看到最大的是java.lang.Object[],这也印证了大量对象被创建并被加入数组的猜测。

Root cause

那么究竟是什么操作引发的呢?在mat的报告中最终发现这个object是一个entity类,说明这是一个数据库操作,查询出了大量结果导致的。

这种查询量级一定会被记录为了慢查询,打开阿里云的RDS慢日志查询

218w的记录被查询到,没有直接OOM算是走运了。

但是查询的sql很奇怪,出现了is null的条件语句,由于这个字段是索引字段应该精确匹配的,业务逻辑中不可能出现查询空记录的需求。repository的查询接口是使用spring-data-jpa标准描述的。

1
Person findByAAndBAndC(String A, String B, String C);

理论上应该转化为

1
select * from person where A=A and B=B and C=C;

结果却变成了

1
select * from person where A is null and B=B and C=C;

这样以来,就跳开了索引并查询到相当可观的记录。经过试验发现如果未经过判空校验,当A=null时,spring-data-jpa会自动转化为is null的SQL语句。

最终我们对所有类似调用都加上了Assert.notnull的处理。重新上线后问题解决,再也没有FGC发生了。

总结

对于程序员来讲,这种“智能”的框架真的是非常可怕,当你面对一个黑盒的时候,灾难往往就在不远处。