利用MAT分析工具解决线上疯狂oldGC过程

背景：

查询记录是我们公司关于异常快件的一个业务日志系统，主要记录了快件在收转运派签各个环节的各个系统产生一些异常操作 包括拦截、退改、客户投诉、客服处理等操作。日常查询流量在5000万，写入流量2000万，日均接口调用1.2亿次，主要前台页面内嵌在公司快件跟踪页面，上游有20多个应用 500多个消费者 调用 相当于一个业务日志中台。该应用部署了8台4c8g的parnew+cms的机器上，平时的话该配置还是比较轻松应对这些流量的，就算618、双十一流量翻倍的情况下也没有问题，但是上周五发版后，在0点一波很小的流量使得机器一小时oldGC 100多次，严重影响线上功能。

---

以下灰色字体选择性食用，建议直接观看正文

发版大致内容是查询记录写入加幂等校验、切了一个外部接口、和两个暂没流量接口，上线后正常验收流程都走了一遍，没有任何问题，也观察了接口性能良好。但是19号凌晨的时候突然接到运维电话查询记录告警严重。简单看一下确实是存在很多超时的服务，不管是服务还是调用或是sql都有长耗时的，于是第一反应线程池满了释放不了，这个时候想着会不会是调下游接口一直超时占着线程池或者是当天上的redis做的幂等出了问题。

由于是当天晚上上了版本，所以觉得是版本的原因引起的服务超时的可能性比较大，而且这个版本没有业务上的影响，所以为了快速止血，就选择先回滚了代码。回滚操作在一站式上--集群--更多--回滚即可。但是这里其实有个大坑，就是回滚代码和重启性质是一样的，都会新的容器上部署，原本旧的容器就会被销毁掉，当你止血后再去拿容器上的东西，就找不到任何东西，所以当出了问题后一定要第一时间保留现场，一定要第一时间保留现场 一定要第一时间保留现场 一定要第一时间保留现场 重要的事情说三遍！

在回滚代码以后，运维马上就说告警没了，这时候长舒一口气，但心也凉了一半，因为大概率是版本带来的问题了，于是便开始了漫长的排查问题的工作。

---

事后主要在zcat（公司内部监控系统）上观察故障发生时的流量、GC情况、服务耗时等数据。流量经过对比，发现查询记录在白天平均每小时2M流量，而发生故障时的凌晨为6k流量，发生故障前的几个小时流量也近乎平缓 在6k-8k,所以初步可以判定不是大流量导致服务超时的。接着又看了GC的情况，GC本来是想看一下GC日志和dump的数据的，但这时候反应过来 故障机器的容器没了，就只能在zcat上看看数据了。

这是zcat上展示的数据，看着奇怪，这个oldGC有三次的突起，中间还有两段时间显示老年代为0的，这里没拿到日志和dump，不知道是OOM还是zcat没有统计到。为了更直观的看oldGC数据，直接F12打开控制台，看到oldGC数据：

我们可以看到在53这一分钟oldGC了4次，这不到半个小时的时间oldGC了119次，正常情况下我们这个配置（CMS 新老年代各2G）下的机器，流量没有增多的情况下应该在1-2天才oldGC一次。

在看GC数据的时候，还注意到一个点，就是其实只有两台机器有服务超时的情况，一共部署了8台机器，其他机器是正常的，这个时候还考虑了是不是容器的问题，但主要排查方向还是在为什么发生GC上，由于没有更多的GC相关的资料，所以第二天排查异常艰难，第二天首先是在新增代码上找可能发生内存泄漏的地方和日志以及大数据表查故障时间有没有操作非正常查询记录数据，但这两项工作都没有结果，而且在测试环境造了大量查询和写入的数据，也没有复现。

---

正文：

回滚后机器一直正常运行，知道周日上午11点，又突然接到运维电话，我们的服务又出现大量超时了，这个时候，大致看了一下和之前的问题是类似的，且只有一台机器发生超时，这一次我第一时间保留了现场：

在保留现场以后，原本以为还需要重启之类的，但后面和运维沟通，保留现场会帮保留这个容器，并重启一个新的容器，所以在保留现场之后告警就马上没了。这里需要注意的是zke上容器最多只能保留6h，所以也需要第一时间下载相关数据，这是一些操作：

1、下载GC日志

我们可以在dev集群对应的配置找到gc日志的存放位置，一般我们没有改gc日志的位置配置就默认存放在/dev/shm/gc.log下（-Xloggc:/dev/shm/gc.log） 可使用 less 命令查看日志 这个gc日志里面记录了每次gc eden区 s1、s2 等内存区域的使用情况及回收率 和对象年龄占比等数据。

2、下载dump文件

dump文件，我们的默认参数是开启oldGC（-XX:+PrintHeapAtGC）后生成dump并放在/data/logs (-XX:HeapDumpPath=/data/logs/)这个目录下的，但是事实上没有发生OOM，这时可以用   jmap -dump:format=b,file=文件名.hprof 进程号   这条命令生成oldGC时的dump文件。

然后就可以从zke上把文件下载下来，zke上面 对应容器旁边有个下载按钮 输入对应的文件路径和文件命名即可。

当然如果还有需要的话 可以下载jar包和应用日志。

接下来是dump文件分析，我这里用的是Memory Analysis Tool ，MAT是一款比JVM自带内存分析工具更好用的工具，需要单独下载，下载后需要改该工具启动目录下的初始参数

这里建议直接给xmx分10个G，如果打开dump有报错的情况，可以尝试设置-DhprofStrictnessWarning为true。

这个MAT主要的界面视图，这里圈了一些比较实用的功能，上面的工具栏直方图、Dominator Tree（支配树）、oql、还有线程视图，中间是大对象堆中占比情况，下面左边这里也是直方图和支配树，这里还有一个主要消费对象 ，中间还有一个分析报告也是比较好用的；

直方图：可以都能够展示各个类的实例数目以及这些实例的Shallowheap、Retained heap，这里这两个Shallowheap、Retained heap翻译为浅层堆和深层堆，浅层堆可以简单理解为对象本身在堆中内存大小，深层堆可以理解为对象本身及引用在堆中内存大小。

在这里我们就可以大致看出是有比较多的数组对象在堆里被引用着。

在看分析报告：

 这个报告的大概的意思是这个线程占了48%的内存，让我们点击这个线程栈看详细情况，当然这个报告不仅仅是分析线程的，他会大致告诉你是由什么原因产生的GC。

这是线程的详细情况，我们可以大致的看到 这个占用大量对象的线程还在一个mysql相关操作的Stream的read操作中，其实这里就可以大概分析出是我们的某条sql出了问题，但当时没注意。

接着我们打开支配树：

Dominator Tree: List the biggest objects and what they keep alive.

可以说，它就是专门用来看大对象的，一路点开内存占比高的对象，果然我们在这里看见我们的业务数据对象。

到这里我还是认为是查询了这些对象，可能这些对象是查询记录条数比较多或者是占用内存比较大的对象，导致内存被一下打爆了，发现这些运单均出自一张表，细致一点的分析就是一个ArrayList里面的不同运单的mysql行对象均出自一张表，因为查询记录是通过运单号进行分库分表的，所以不同运单号还是比较难在同一个查询中 命中同一张表的，所以在这里我们就猜测是不是某个sql进行查全表的操作了。

这时候问DBA有没有慢sql，结果DBA那边刚好有一条慢sql：

巧了，上面线程中数组引用的对象 运单号 也是出自0446这张表，这时就基本确定了就是因为这条sql查全表了，导致查到的数据太大直接进入老年代了。

最后用这张表对应的mapper进行查询，对这张表所有的查询sql进行检查，最终在这张表的manager里发现一个可疑查询操作：

ps：这里是陈年老代码，不是我写的，甩锅嘿嘿

这个查询是在一个service里面被循环调用，service方法的入参是一个List<String>， 在service这个list是有判空,但是在manager没有进行判空，这就导致了当list里面存在null对象的时候，在service的CollectionUtils.isEmpty的判空会为false，不会判定该对象为空的，而且下面是拿list里面的对象循环调用manager的查询，当manager里的查询运单号查询传入null值的时候，就导致了example不会拼接billCode的查询条件。所以本该被拼接成的sql：where bill_code='xxxxxx' and deleted=0 就变成了where deleted=0  所以就进行了查全表的操作。

拿到service的日志 找到对应时间查询 也刚好可以得到上游在这个时间点确实传了一个null值过来：

最终在该查询加判空以解决问题。

总结：

部署的服务集群中，有一台机器查询条件上游传入null值，业务层null值空数组校验通过，导致查询语句未拼接查询条件，以至于出现查全表的操作，查到的部分数据在写入应用时被虚拟机直接判定为大对象，进入老年代，老年代内存大部分被占用，发生oldGC，由于这些对象被Thread持有着，所以oldGC并不能清理掉这些数据，oldGC仅能清理很小一部分老年代所以少量正常的YGC后的对象进入老年代就会导致一次oldGC，正常情况下生产的YGC几秒就会一次，这也就导致这不到半小时的时间里会oldGC100多次，也就导致了我们的机器在提供服务的时候，很有可能上游的一次正常的查询经历多次oldGC都拿不到结果 导服务大量超时的出现。