sql语句返回行数过多导致[B占爆jvm内存的问题一例

一次大版本上线之后,发现k8s的pod在不停自动重启。看到这种问题,第一反应就是是不是jvm内存被占爆之后oom导致重启。扫了眼gc日志,存在大量的full gc而且内存根本回收不下去:

[Full GC (Allocation Failure) 2018559K->2016225K(2018560K), 4.6366060 secs]

果然是jvm内存被占爆了。接下来就是看下到底是什么东西占了这么多内存,jmap -histo 1 | head -n 20(docker容器中应用进程的pid是1)走起:

num #instances #bytes class name
----------------------------------------------
1: 50953149 1719029856 [B
2: 12554824 851776232 [C
3: 3224844 335384120 [[B
4: 12556565 301357560 java.lang.String
5: 6785718 217142976 java.sql.Timestamp
6: 2164923 207832608 com.XXXX.api.model.PaymentPlan
7: 2457648 98305920 java.math.BigDecimal
8: 3224782 77394768 com.mysql.jdbc.ByteArrayRow
9: 2165292 51967008 java.lang.Long

……

本来以为打出来之后问题会迎刃而解,结果这下彻底懵逼了……怎么会有这么多的[B?这次发版没有新增用到流的地方,压根没地方会出现这么多byte[]啊…一大堆的[[B就更无从解释了,项目中根本不可能有用到byte[][]的地方。

一头雾水中的我仔细观察了下这些对象,发现第8名的com.mysql.jdbc.ByteArrayRow非常可疑,那一大堆byte[]和byte[][],大概都是它包含的吧。点进去看了下,果然:

QQ截图20200604155342

那怎么会有这么多的ByteArrayRow呢……该不会是哪条sql没限制返回数量,导致内存里一大堆sql返回结果吧?于是我们开始排查本次发版新增的sql,看看有没有这种问题。正在我们焦头烂额的检查代码的时候,测试同学在日志中一眼看到了一个不正常的sql:

QQ截图20200604154544

就是你了!只有逻辑删除的限制条件,可不是一下能查出来很多条嘛。仔细过了一遍代码,原来有一个地方在查询的时候,如果值为null就不传递限制条件,所以导致了这个没有限制条件的sql。

使用阿里云polardb自带的慢sql查询平台,也验证了这个问题——这条sql平均返回90万行结果、最大返回160万结果——这么多,内存不爆才有鬼了:

QQ截图20200604155118

发现问题之后,解决起来就很轻松了,赶紧修bug发版吧……还好出现这个问题的项目只是用来发送消息的,不影响主流程——无非是发送消息的时效性受点影响而已。