记一次连续几次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)）

最后编辑于 ：
©著作权归作者所有,转载或内容合作请联系作者
  • 人面猴
    序言：七十年代末，一起剥皮案震惊了整个滨河市，随后出现的几起案子，更是在滨河造成了极大的恐慌，老刑警刘岩，带你破解...
    沈念sama阅读 216,001评论 6赞 498
  • 死咒
    序言：滨河连续发生了三起死亡事件，死亡现场离奇诡异，居然都是意外死亡，警方通过查阅死者的电脑和手机，发现死者居然都...
    沈念sama阅读 92,210评论 3赞 392
  • 救了他两次的神仙让他今天三更去死
    文/潘晓璐 我一进店门，熙熙楼的掌柜王于贵愁眉苦脸地迎上来，“玉大人，你说我怎么就摊上这事。” “怎么了？”我有些...
    开封第一讲书人阅读 161,874评论 0赞 351
  • 道士缉凶录：失踪的卖姜人
    文/不坏的土叔 我叫张陵，是天一观的道长。 经常有香客问我，道长，这世上最难降的妖魔是什么？ 我笑而不...
    开封第一讲书人阅读 58,001评论 1赞 291
  • 港岛之恋（遗憾婚礼）
    正文 为了忘掉前任，我火速办了婚礼，结果婚礼上，老公的妹妹穿的比我还像新娘。我一直安慰自己，他们只是感情好，可当我...
    茶点故事阅读 67,022评论 6赞 388
  • 恶毒庶女顶嫁案：这布局不是一般人想出来的
    文/花漫 我一把揭开白布。 她就那样静静地躺着，像睡着了一般。 火红的嫁衣衬着肌肤如雪。 梳的纹丝不乱的头发上，一...
    开封第一讲书人阅读 51,005评论 1赞 295
  • 城市分裂传说
    那天，我揣着相机与录音，去河边找鬼。 笑死，一个胖子当着我的面吹牛，可吹牛的内容都是我干的。 我是一名探鬼主播，决...
    沈念sama阅读 39,929评论 3赞 416
  • 双鸳鸯连环套：你想象不到人心有多黑
    文/苍兰香墨 我猛地睁开眼，长吁一口气：“原来是场噩梦啊……” “哼！你这毒妇竟也来了？” 一声冷哼从身侧响起，我...
    开封第一讲书人阅读 38,742评论 0赞 271
  • 万荣杀人案实录
    序言：老挝万荣一对情侣失踪，失踪者是张志新（化名）和其女友刘颖，没想到半个月后，有当地人在树林里发现了一具尸体，经...
    沈念sama阅读 45,193评论 1赞 309
  • 护林员之死
    正文 独居荒郊野岭守林人离奇死亡，尸身上长有42处带血的脓包…… 初始之章·张勋 以下内容为张勋视角 年9月15日...
    茶点故事阅读 37,427评论 2赞 331
  • 白月光启示录
    正文 我和宋清朗相恋三年，在试婚纱的时候发现自己被绿了。 大学时的朋友给我发了我未婚夫和他白月光在一起吃饭的照片。...
    茶点故事阅读 39,583评论 1赞 346
  • 活死人
    序言：一个原本活蹦乱跳的男人离奇死亡，死状恐怖，灵堂内的尸体忽然破棺而出，到底是诈尸还是另有隐情，我是刑警宁泽，带...
    沈念sama阅读 35,305评论 5赞 342
  • 日本核电站爆炸内幕
    正文 年R本政府宣布，位于F岛的核电站，受9级特大地震影响，放射性物质发生泄漏。R本人自食恶果不足惜，却给世界环境...
    茶点故事阅读 40,911评论 3赞 325
  • 男人毒药：我在死后第九天来索命
    文/蒙蒙 一、第九天 我趴在偏房一处隐蔽的房顶上张望。 院中可真热闹，春花似锦、人声如沸。这庄子的主人今日做“春日...
    开封第一讲书人阅读 31,564评论 0赞 21
  • 一桩弑父案，背后竟有这般阴谋
    文/苍兰香墨 我抬头看了看天上的太阳。三九已至，却和暖如春，着一层夹袄步出监牢的瞬间，已是汗流浃背。 一阵脚步声响...
    开封第一讲书人阅读 32,731评论 1赞 268
  • 情欲美人皮
    我被黑心中介骗来泰国打工， 没想到刚下飞机就差点儿被人妖公主榨干…… 1. 我叫王不留，地道东北人。 一个月前我还...
    沈念sama阅读 47,581评论 2赞 368
  • 代替公主和亲
    正文 我出身青楼，却偏偏与公主长得像，于是被迫代替她去往敌国和亲。 传闻我的和亲对象是个残疾皇子，可洞房花烛夜当晚...
    茶点故事阅读 44,478评论 2赞 352