记一次连续几次FullGC事件的排查过程

[TOC]

背景

生产上有一套联机系统，这里称之为svc，提供rpc服务给上游联机系统调用。上游联机系统需要调用svc来查询一些信息，如果命中则做一些业务拦截操作。

其中svc有12台节点，通过zookeeper注册中心发布，客户端会自动负载均衡，每次请求会负载到其中1台机器上，默认是平均负载。

上游系统通过某种策略，只连了我们8台节点，成为之node1-node8，node9到node12没有被上游系统连接。

同时svc还有个配套的管理系统，可以供管理员查询一些日志信息。管理系统会将一些查询随机发送到12台充的某一台。

事件简述

在一次版本之后，系统平稳运行，直到有一次一个监控告警信息打破了平静：“xx系统熔断了svc服务”！

上游系统xx调用我们的svc服务，如果在10s连续超时的交易达到200笔则熔断对svc的调用，超时时间为200ms

赶紧跑去排查，发现在熔断的时间点，有一台机器的gc表现异常，连续好几次FullGC。gc日志如下

10:11:05 [GC (Allocation Failure) [PSYoungGen: 692720K->6112K(636416K)] 757557K->145190K(2034688K), 0.0949942 secs] [Times: user=0.34 sys=0.03, real=0.09 secs] 
10:11:06 [GC (Allocation Failure) [PSYoungGen: 636384K->34282K(664576K)] 775462K->225360K(2062848K), 0.1025718 secs] [Times: user=0.36 sys=0.04, real=0.10 secs] 
10:11:08 [GC (Allocation Failure) [PSYoungGen: 664554K->34295K(543744K)] 855632K->318534K(1942016K), 0.1298240 secs] [Times: user=0.47 sys=0.04, real=0.13 secs] 
10:11:09 [GC (Allocation Failure) [PSYoungGen: 543735K->93614K(603136K)] 827974K->377893K(2001408K), 0.0536636 secs] [Times: user=0.20 sys=0.00, real=0.05 secs] 
10:11:09 [GC (Allocation Failure) [PSYoungGen: 603054K->81486K(553984K)] 887333K->491033K(1952256K), 0.0907987 secs] [Times: user=0.31 sys=0.04, real=0.09 secs] 
10:11:10 [GC (Allocation Failure) [PSYoungGen: 539726K->112670K(571392K)] 1199130K->772441K(1969664K), 0.0748770 secs] [Times: user=0.25 sys=0.00, real=0.07 secs] 
10:11:10 [GC (Allocation Failure) [PSYoungGen: 570910K->127486K(496640K)] 1230681K->804070K(1894912K), 0.1017275 secs] [Times: user=0.38 sys=0.01, real=0.11 secs] 
10:11:11 [GC (Allocation Failure) [PSYoungGen: 485079K->164863K(534016K)] 1392063K->1077960K(1932288K), 0.0779391 secs] [Times: user=0.30 sys=0.01, real=0.08 secs] 
10:11:11 [GC (Allocation Failure) [PSYoungGen: 487248K->150606K(436736K)] 1400345K->1178153K(1835008K), 0.1152364 secs] [Times: user=0.41 sys=0.05, real=0.12 secs] 
10:11:12 [Full GC (Ergonomics) [PSYoungGen: 387882K->0K(436736K)] [ParOldGen: 1283618K->648742K(1398272K)] 1671500K->648742K(1835008K), [Metaspace: 49835K->49700K(1093632K)], 1.2026718 secs] [Times: user=4.33 sys=0.06, real=1.20 secs] 
10:11:13 [Full GC (Ergonomics) [PSYoungGen: 265187K->0K(436736K)] [ParOldGen: 1396660K->891559K(1398272K)] 1661847K->891559K(1835008K), [Metaspace: 49700K->49700K(1093632K)], 0.7475226 secs] [Times: user=2.78 sys=0.02, real=0.75 secs] 
10:11:14 [GC (Allocation Failure) [PSYoungGen: 264215K->4608K(485376K)] 1155775K->1145473K(1883648K), 0.0528093 secs] [Times: user=0.21 sys=0.00, real=0.05 secs] 
10:11:15 [GC (Allocation Failure) [PSYoungGen: 276480K->138528K(464896K)] 1417345K->1279393K(1863168K), 0.0261127 secs] [Times: user=0.10 sys=0.00, real=0.02 secs] 
10:11:15 [GC (Allocation Failure) [PSYoungGen: 390944K->145597K(398336K)] 1531809K->1286463K(1796608K), 0.0240648 secs] [Times: user=0.06 sys=0.01, real=0.03 secs] 
10:11:16 [GC (Allocation Failure) [PSYoungGen: 398013K->192477K(465920K)] 1538879K->1333343K(1864192K), 0.0290938 secs] [Times: user=0.11 sys=0.00, real=0.03 secs] 
10:11:16 [Full GC (Ergonomics) [PSYoungGen: 425437K->0K(465920K)] [ParOldGen: 1265793K->647703K(1398272K)] 1691231K->647703K(1864192K), [Metaspace: 49700K->49700K(1093632K)], 0.7658346 secs] [Times: user=2.88 sys=0.00, real=0.76 secs] 
10:11:17 [GC (Allocation Failure) [PSYoungGen: 232960K->256K(465920K)] 880663K->647959K(1864192K), 0.0058027 secs] [Times: user=0.02 sys=0.00, real=0.01 secs] 
10:11:17 [GC (Allocation Failure) [PSYoungGen: 233216K->288K(465920K)] 1130775K->897847K(1864192K), 0.0067661 secs] [Times: user=0.02 sys=0.00, real=0.00 secs] 
10:11:17 [GC (Allocation Failure) [PSYoungGen: 233248K->288K(465920K)] 1130807K->897847K(1864192K), 0.0038751 secs] [Times: user=0.02 sys=0.00, real=0.00 secs] 
10:11:17 [GC (Allocation Failure) [PSYoungGen: 233248K->96K(465920K)] 1130807K->897903K(1864192K), 0.0072712 secs] [Times: user=0.02 sys=0.00, real=0.01 secs] 
10:11:17 [Full GC (Ergonomics) [PSYoungGen: 131113K->0K(465920K)] [ParOldGen: 1358608K->753261K(1398272K)] 1489721K->753261K(1864192K), [Metaspace: 49700K->49700K(1093632K)], 0.7841817 secs] [Times: user=2.96 sys=0.00, real=0.79 secs] 
10:11:18 [GC (Allocation Failure) [PSYoungGen: 9388K->192K(465920K)] 1223451K->1214254K(1864192K), 0.0048831 secs] [Times: user=0.02 sys=0.00, real=0.01 secs] 
10:11:18 [GC (Allocation Failure) [PSYoungGen: 230825K->230496K(465920K)] 1444888K->1444735K(1864192K), 0.0357069 secs] [Times: user=0.11 sys=0.00, real=0.03 secs] 
10:11:18 [GC (Allocation Failure) --[PSYoungGen: 461725K->461725K(465920K)] 1675964K->1675988K(1864192K), 0.0334670 secs] [Times: user=0.11 sys=0.00, real=0.03 secs] 
10:11:18 [Full GC (Ergonomics) [PSYoungGen: 461725K->0K(465920K)] [ParOldGen: 1214262K->753454K(1398272K)] 1675988K->753454K(1864192K), [Metaspace: 49700K->49700K(1093632K)], 0.7459855 secs] [Times: user=2.76 sys=0.02, real=0.75 secs] 
10:11:19 [GC (Allocation Failure) [PSYoungGen: 9943K->256K(465920K)] 1224198K->1214511K(1864192K), 0.0093183 secs] [Times: user=0.01 sys=0.00, real=0.01 secs] 
10:11:19 [GC (Allocation Failure) [PSYoungGen: 230928K->230464K(465920K)] 1445183K->1444960K(1864192K), 0.0297630 secs] [Times: user=0.12 sys=0.00, real=0.03 secs] 
10:11:19 [GC (Allocation Failure) --[PSYoungGen: 461328K->461328K(465920K)] 1675824K->1675840K(1864192K), 0.0307309 secs] [Times: user=0.12 sys=0.00, real=0.03 secs] 
10:11:19 [Full GC (Ergonomics) [PSYoungGen: 461328K->0K(465920K)] [ParOldGen: 1214511K->753638K(1398272K)] 1675840K->753638K(1864192K), [Metaspace: 49700K->49700K(1093632K)], 0.7065179 secs] [Times: user=2.66 sys=0.01, real=0.71 secs] 
10:11:20 [GC (Allocation Failure) [PSYoungGen: 4387K->224K(465920K)] 1218826K->1214663K(1864192K), 0.0059501 secs] [Times: user=0.02 sys=0.00, real=0.01 secs] 
10:11:20 [GC (Allocation Failure) [PSYoungGen: 230894K->230496K(465920K)] 1445334K->1445136K(1864192K), 0.0298472 secs] [Times: user=0.11 sys=0.00, real=0.03 secs] 
10:11:20 [GC (Allocation Failure) --[PSYoungGen: 461596K->461596K(465920K)] 1676236K->1676260K(1864192K), 0.0331509 secs] [Times: user=0.10 sys=0.00, real=0.04 secs] 
10:11:20 [Full GC (Ergonomics) [PSYoungGen: 461596K->0K(465920K)] [ParOldGen: 1214663K->753893K(1398272K)] 1676260K->753893K(1864192K), [Metaspace: 49700K->49700K(1093632K)], 0.7237456 secs] [Times: user=2.73 sys=0.01, real=0.72 secs] 
10:11:21 [Full GC (Ergonomics) [PSYoungGen: 232960K->0K(465920K)] [ParOldGen: 1345769K->654494K(1398272K)] 1578729K->654494K(1864192K), [Metaspace: 49700K->49700K(1093632K)], 0.7514767 secs] [Times: user=2.81 sys=0.01, real=0.76 secs] 
10:13:23 [GC (Allocation Failure) [PSYoungGen: 232956K->1696K(465920K)] 887451K->656190K(1864192K), 0.0107365 secs] [Times: user=0.03 sys=0.00, real=0.01 secs] 
10:15:23 [GC (Allocation Failure) [PSYoungGen: 234656K->1696K(465920K)] 889150K->657058K(1864192K), 0.0152908 secs] [Times: user=0.04 sys=0.00, real=0.01 secs] 

排查过程

阶段1-不能自圆其说的初步结论

• 因为是full gc，则表示内存占用异常，于是观察了日志和负载情况，发现日志并没有报错，各台机器的负载仍然均衡，因此排除了短时间内大量压力打到一台机器的可能。
• 在生产环境看了一会日志和gc情况，已经恢复正常
• 生产上上游系统xx连接了8台机器，仅1台机器有类似的情况
• 将gc日志带回开发环境。虽然fullgc但是并未产生dump文件，手动dump了堆转储文件带回
• 通过分析工具分析gc，在10:11分的时候，内存突然升高，且连续触发了好几次full gc
• 用mat对dump文件进行分析，给出的内存泄露报告是log4j2相关的RingBuffer空间占用较大。（log4j2异步日志使用disruptor作为队列）但是整个RingBuffer占用的空间也并不大
• mat分析的dump文件中，可达的对象占比很小，只有100多M，不可达对象很高，快1个G，不可达的对象大都是char[]和byte[]类型

根据以上排查，有如下初步结论:

• 根据经验，log4j2已经使用了很久，未出现过内存溢出的情况。log4j对disruptor的缓冲区大小是有固定大小的。但是查了下代码，日志的确打印的太多了，而且很多地方使用的是拼接字符串的方式，即使是debug的日志。因此怀疑难道真的是日志打印的太多导致了fullgc？
• mat分析的结果中，不可达对象多为char[]和byte[]，其中char[]是String的内部结构，可能真的是日志太多了
• 但是如何解释在负载均衡的情况下，其他机器都没事？难道是那台机器所在的物理机有问题？或者物理机上的其他虚机占用资源太多？于是去运维那里要了宿主物理机的其他虚机信息，并拿到了io和网络、内存占用情况，发现唯一的内存冲高还是我们自己的进程造成的~

因此，以上得出的结论，真的没法定位出原因。而且如果结论是日志太多了，则应该其他机器也会出现类似的情况，顶多是时间的早晚。

google了很多gc排查的文章，仍然一头雾水，找不到类似现象的案例。

阶段2-一个偶然的重大发现

实在没法把锅甩给基础环境，而上游系统又是均衡的负载，想了想，难道要将锅甩给管理平台了？越想越觉得有可能，毕竟饥不择食。

因为管理平台每次点击某个按钮，都只会讲请求发送到某个节点，而不是全部发送，所以极有可能是管理平台做了什么操作？

根据这个思路，联系了管理平台的管理员，反馈并没有做什么操作，而且由于分析这里的时候，日子已经过了几天，日志也没了，不好通过日志追溯~

于是又只能硬着头皮到生产上检查，准备将所有的节点内存信息都dump回来，暴力对比，希望发现一些端倪。

借着这次机会仔细学习了一下mat的其他功能，相比之前了解的多很多。

找到了一个机会，把所有的进程都dump了文件。但是发现了另一个神奇的现象：另一台机器，node10也有类似的现象，而且node10没有上游系统调用！！！

观察了node10的gc日志，和之前出问题的node5的非常一致，时间几乎一致，只是相差几秒。

“一定是环境的问题！”

推导出了看似强有力的结论，于是向运维求助，看看二者是不是共享物理机，或者那一刻有别的云环境的任务干扰。

经历了一番周折，发现并没有，没有什么特殊的任务，二者连物理机也不是同一个。

但同时，还有另外一个重大的发现——node10节点，在发生fullgc的时候，自动生成了一个dump文件。

虽然所有节点都配置了HeapDumpOnOutOfMemoryError，但是node5却没有产生

几乎准备将锅甩给玄学了，却发现了这个dump文件，如获至宝，赶快带回去分析，果然，真相大白！

阶段3-问题源于生产，还是要回溯到生产

拿到了“原生”的dump文件之后，使用mat文件一打开，发现有一个自己构建的列表，持有了29w个pojo对象，没错，是29w个，占据了400多M空间~

WechatIMG3.jpeg

然后结合代码分析（这中间还经历了一些波折，此处不再赘述）。总之最后终于定位到，原来真的是一个供管理平台使用的服务接口触发的这个问题：

管理平台查询近期的记录，因为是分库分表，结合管理平台的分页和条件查询，控制逻辑比较复杂，结果因为一个代码缺陷，导致了每次查询，有多少记录就会查询多少记录，因此导致了内存暴涨。

到这里，所有的逻辑都通了：

• 管理平台调用了有问题的查询接口，查询接口一次查询快30w条记录
• 后端查询到了大量的信息，引发了连续的fullgc
• 由于这个过程比较长，并不能在秒级内就让查询的结果被gc然后回收空间
• 和上游xx系统没有关系~
• 和基础环境没有关系~

然而是谁去点击这个管理平台的呢?分析到这里，开发人员才终于想起来，原来是事件当天，自己点击了管理平台！！！

最后，修复bug，问题解决。

小结

由于时间问题，写的有点仓促，中间也经历了一些弯路，这里总结下几个感想

• 生产事件分析，一定要尽量基于当时的信息，比如出事时候的日志、dump文件等。本次事件被抓到的关进因素，还是fullgc时产生的dump文件。当然如果可以开发测试环境复现，那另说，有时候一些问题很难复现
• 分析某个模块的问题，一定要全盘分析，不要放过每一个干系方。这次事件排查了很久，才将注意力转移到管理平台上来
• 要能够自圆其说，不能留着疑点，强行解释，比如前面提到的，可能是日志过多的原因。解释不通的地方，一定有其道理
• 生产日志最好保留久一些，在磁盘足够的情况下，建议30天左右
• java进程一定要配置-XX:+HeapDumpOnOutOfMemoryError -XX:HeapDumpPath=xxx.dump，在内存溢出时会是救命稻草

其实还有个问题，就是，实际生产配置的堆空间最大是2G,理论上即使查出了29w记录，也是够用的，为何会频繁fullgc呢？感兴趣的同学可以自己去查询，我有空会再整理一下（可能和gc机制的策略有关，相关信息可以检索关键字Full GC (Ergonomics)）