内存泄露案例1: Eclipse MAT&IBM HeapAnalyzer-由于错使用循环变量导致WHILE死循环的OOM

2022-03-19/2022-03-20 | 0 评论 | 1,238 浏览

本文介绍了一次测试环境的开发过程的OOM问题排查,期间使用到了内存dump分析工具: Eclipse MAT和IBM HeapAnalyzer 两种分析工具.
最终结合代码找到了具体问题代码. 此文章会涉及到dump内存的基本分析. 以及分析内存泄漏的过程.

在分析完并定位到内存泄露后,定位到代码. 反过来再复盘之前的过程. 实际上也可以不用使用内存Dump这个终极工具. 也可以比较方便的
定位内存泄露的地方. 更多的可能是需要更详细的分析代码.(也就是要对源代码更熟悉一些)

背景

开发组里面有同学反馈测试环境的机器可能存在内存泄露. POD节点被强制KILL了. 同时留下了一个很小的故障dump文件. 根据经验 , 这个可能是由于堆内存使用过多. 堆外内存空间较小. 在有较大的内存压力的时候极可能触发K8S的POD节点内存限制. 从而直接被KILL.

增加内存无效

在尝试增加内存大小后(非重点,不详述).仍然出现了机器假死, 内存占用过大的情况.

注: 此图为后面复现OOM产生的图.非最原始的现场图

上图说明: 实际当时情况下看到的内存占用更像是一个内存无法GC .处于一直FULLGC的情况下.类似于图中时间段: 20:20~20:25 这段时间

下面的监控图展示了GC的频率与GC时长

注: gc的频率已经非常高了

下面是摘抄了一些GC日志

2022-03-19T20:20:51.228+0800: 514.283: [GC pause (G1 Evacuation Pause) (young) 5943M->5671M(6144M), 0.0779985 secs]
2022-03-19T20:20:51.576+0800: 514.631: [GC pause (G1 Evacuation Pause) (young) 5955M->5683M(6144M), 0.0478549 secs]
2022-03-19T20:20:51.885+0800: 514.940: [GC pause (G1 Evacuation Pause) (young) 5967M->5696M(6144M), 0.0465688 secs]
2022-03-19T20:20:52.186+0800: 515.241: [GC pause (G1 Evacuation Pause) (young) 5978M->5707M(6144M), 0.0472413 secs]
2022-03-19T20:20:52.270+0800: 515.325: [GC concurrent-mark-end, 21.0200623 secs]
2022-03-19T20:20:52.271+0800: 515.326: [GC remark, 0.0890849 secs]
2022-03-19T20:20:52.360+0800: 515.415: [GC cleanup 5739M->5739M(6144M), 0.0072510 secs]
2022-03-19T20:20:52.539+0800: 515.594: [GC pause (G1 Evacuation Pause) (young) 5991M->5718M(6144M), 0.0498064 secs]
2022-03-19T20:20:52.761+0800: 515.816: [GC pause (G1 Evacuation Pause) (young) 6002M->5729M(6144M), 0.0463567 secs]
2022-03-19T20:20:52.980+0800: 516.035: [GC pause (G1 Evacuation Pause) (young) (initial-mark) 6013M->5740M(6144M), 0.0491012 secs]
2022-03-19T20:20:53.029+0800: 516.084: [GC concurrent-root-region-scan-start]
2022-03-19T20:20:53.041+0800: 516.096: [GC concurrent-root-region-scan-end, 0.0113863 secs]
2022-03-19T20:20:53.041+0800: 516.096: [GC concurrent-mark-start]
2022-03-19T20:20:53.292+0800: 516.347: [GC pause (G1 Evacuation Pause) (young) 6024M->5751M(6144M), 0.0506288 secs]
2022-03-19T20:20:53.605+0800: 516.660: [GC pause (G1 Evacuation Pause) (young) 6035M->5762M(6144M), 0.0675043 secs]
2022-03-19T20:20:55.789+0800: 518.844: [GC pause (G1 Evacuation Pause) (young) 6046M->5774M(6144M), 0.0480081 secs]
2022-03-19T20:20:55.837+0800: 518.892: [GC concurrent-mark-reset-for-overflow]
2022-03-19T20:20:56.095+0800: 519.150: [GC pause (G1 Evacuation Pause) (young) 6058M->5787M(6144M), 0.0501702 secs]
2022-03-19T20:20:56.408+0800: 519.463: [GC pause (G1 Evacuation Pause) (young) 6069M->5798M(6144M), 0.0667547 secs]
2022-03-19T20:20:56.722+0800: 519.777: [GC pause (G1 Evacuation Pause) (young) 6082M->5810M(6144M), 0.0749635 secs]
2022-03-19T20:20:57.035+0800: 520.090: [GC pause (G1 Evacuation Pause) (young) 6094M->5822M(6144M), 0.0837193 secs]
2022-03-19T20:20:57.380+0800: 520.435: [GC pause (G1 Evacuation Pause) (young) 6104M->5832M(6144M), 0.0510885 secs]
2022-03-19T20:20:57.694+0800: 520.749: [GC pause (G1 Evacuation Pause) (young)-- 6116M->5854M(6144M), 0.2161288 secs]
2022-03-19T20:20:58.173+0800: 521.228: [GC pause (G1 Evacuation Pause) (young)-- 6138M->6138M(6144M), 0.6843441 secs]
2022-03-19T20:20:58.859+0800: 521.914: [GC pause (G1 Evacuation Pause) (young) 6138M->6138M(6144M), 0.0089336 secs]
2022-03-19T20:20:58.868+0800: 521.923: [GC pause (G1 Evacuation Pause) (young) 6138M->6138M(6144M), 0.0058675 secs]
2022-03-19T20:20:58.874+0800: 521.929: [GC pause (G1 Evacuation Pause) (young) 6138M->6138M(6144M), 0.0052280 secs]
2022-03-19T20:20:58.880+0800: 521.935: [GC pause (G1 Evacuation Pause) (young) 6138M->6138M(6144M), 0.0049346 secs]
2022-03-19T20:20:58.885+0800: 521.940: [GC pause (G1 Evacuation Pause) (young) 6138M->6138M(6144M), 0.0053852 secs]
2022-03-19T20:20:58.891+0800: 521.946: [GC pause (G1 Evacuation Pause) (young) 6138M->6138M(6144M), 0.0048031 secs]
2022-03-19T20:20:58.897+0800: 521.951: [Full GC (Allocation Failure)  6138M->5545M(6144M), 10.1593790 secs]
2022-03-19T20:21:09.056+0800: 532.111: [GC concurrent-mark-abort]
2022-03-19T20:21:09.279+0800: 532.334: [GC pause (G1 Evacuation Pause) (young) 5851M->5556M(6144M), 0.0272664 secs]
2022-03-19T20:21:09.527+0800: 532.582: [GC pause (G1 Evacuation Pause) (young) (initial-mark) 5850M->5568M(6144M), 0.0553430 secs]
2022-03-19T20:21:09.583+0800: 532.638: [GC concurrent-root-region-scan-start]
2022-03-19T20:21:09.595+0800: 532.650: [GC concurrent-root-region-scan-end, 0.0121384 secs]
2022-03-19T20:21:09.595+0800: 532.650: [GC concurrent-mark-start]
2022-03-19T20:21:09.909+0800: 532.964: [GC pause (G1 Evacuation Pause) (young) 5850M->5579M(6144M), 0.1019146 secs]
2022-03-19T20:21:10.311+0800: 533.366: [GC pause (G1 Evacuation Pause) (young) 5861M->5591M(6144M), 0.0730048 secs]
2022-03-19T20:21:12.653+0800: 535.708: [GC pause (G1 Evacuation Pause) (young) 5873M->5603M(6144M), 0.0517848 secs]
2022-03-19T20:21:12.705+0800: 535.760: [GC concurrent-mark-reset-for-overflow]
2022-03-19T20:21:12.982+0800: 536.037: [GC pause (G1 Evacuation Pause) (young) 5885M->5615M(6144M), 0.0606651 secs]

注: 实际这个GC日志实际上会GC失败.同时用户线程应该也会失败. 失败后堆空间的内存可以被释放,即下一次GC是可以回收到内存的. ( 当时没有明白出问题的点和被持续的用户请求以及GC日志的频繁FULL GC给迷惑了 )

dump 内存

命令: jmap -dump:live,format=b,file=./a.dump
堆大小: 约6G

使用`IMB Heap Analyzer`工具进行分析

由于需要的内存较大, 需要设置一下启动命令: java -jar -Xmx24g /path/to/JVM/ha457.jar

从图中可以看到内存中存在一个ArrayList 里面存储了大量的string. 其值是一个中横线连接的两个数字串.如:3-18354009600000,这个看起来非常像是拼接起来的cache_key. 但是询问开发同学,其并没有什么印象. 只能从另外一个方向努力.

注: 这个工具目前用下来就是既好用,也难用. 好用的点是. 他能够比较好的分析堆. 把堆上的对象统计出来. 然后统计出各种维度的对象个数与大小计数. 不好太的地方就是没有给出GC_ROOTS , 简单说就是比如我栈上引用了一个ArrayList<String> , 他能够找到这个arraylist对象,并且其子节点的所有节点的大小,内容基本都能够识别和查看. 但是却没有这个数组对象的持有者是谁. 按IBM Analyzer的说法.这个数组就是一个根对象.或者是没有parent的对象.但是按常理一个ArrayList是无法直接存在的.按可能的GC_ROOT:要么是被一个某个类的静态变量持有;要么是在某一个栈桢里面;要么是常量池或者是方法区的Class对象依赖等;
不管怎样,应该会有一个引用槽位才对.但是这个软件并没有给出来是哪来的根引用了这个对象. 因此需要进一步的分析.

使用`MAT`工具分析内存泄露.

不得不说MAT是一个强大的内存分析工具. 功能和可人工介入和探索的点要丰富很多. 如果早一些用这个工具分析就不会这么麻烦了.

mat给出的可疑内存泄露报告给出的信息非常的准确. 这个堆文件中只有一个可疑的内存泄露点. 同时这个报告里面有:

线程: 确定是哪个线程持有这些对象. 对分析范围的缩小有非常大的帮助.
- 这里是一个http-nio-8080-exec-8说明这是一个HTTP请求中出现了问题.
在后面给出了对象占用的内存大小
下图中的最短路径到堆积节点(可以理解为汇聚节点) 给出了HTTP线程拥有了这个ArrayList,同时这个ArrayList里面是Object对象.

具体再看一下对象的内容.因为是string, 最直观的是把内容打出来.人工瞅瞅.可能一眼就发现了问题 ,如下图:

在这个支配图(Dominator Tree)中,可以发现这个ArrayList 中大量的内容都是雷同的. 再往下看.

通过类型对对象进行汇聚,发现所有的类型都为String. 与上图一致. 在泄露的内存类型都为String且被关联到了这个ArrayList中. 最关键的是下面提供的Thread信息. 能够非常精确的找到出问题的点:

线程属性分析:

这是一个http线程: http-nio-8080-exec-8

这个浅堆大小(参考shallow heap - 浅堆大小) 是128

深堆大小: 2.8G (大约, 定义参考上面的连接)

状态是: 存活,可运行 (alive , runnable)

再看一下堆栈:

http-nio-8080-exec-8
  at java.util.GregorianCalendar.<init>(Ljava/util/TimeZone;Ljava/util/Locale;Z)V (GregorianCalendar.java:737)
  at java.util.Calendar$Builder.build()Ljava/util/Calendar; (Calendar.java:1482)
  at sun.util.locale.provider.CalendarProviderImpl.getInstance(Ljava/util/TimeZone;Ljava/util/Locale;)Ljava/util/Calendar; (CalendarProviderImpl.java:88)
  at java.util.Calendar.createCalendar(Ljava/util/TimeZone;Ljava/util/Locale;)Ljava/util/Calendar; (Calendar.java:1666)
  at java.util.Calendar.getInstance()Ljava/util/Calendar; (Calendar.java:1613)
  at com.fenbi.leo.homework.server.utils.DateTimeUtils.getEndTimeOfMonthExclusive(J)J (DateTimeUtils.java:228)
  at com.fenbi.leo.homework.server.web.logic.group.StudyGroupRankingListLogic.addNewLikeCnt(Ljava/util/Map;JJLjava/util/List;)V (StudyGroupRankingListLogic.java:277)
  at com.fenbi.leo.homework.server.web.logic.group.StudyGroupRankingListLogic.getHonorMonthRankingList(Lcom/fenbi/leo/homework/server/web/context/LeoContext;)Lcom/fenbi/leo/homework/server/web/data/group/vo/StudyGroupHonorRankingListVO; (StudyGroupRankingListLogic.java:260)
  at com.fenbi.leo.homework.server.web.ctrl.group.StudyGroupRankingListController.honorMonth$original$i9HwKDay()Lcom/yuanli/leo/framework/core/remote/api/APIResponse; (StudyGroupRankingListController.java:57)
  at com.fenbi.leo.homework.server.web.ctrl.group.StudyGroupRankingListController.honorMonth$original$i9HwKDay$accessor$Mb4aspCT()Lcom/yuanli/leo/framework/core/remote/api/APIResponse; (Unknown Source)
  at com.fenbi.leo.homework.server.web.ctrl.group.StudyGroupRankingListController$auxiliary$k9SdSGPC.call()Ljava/lang/Object; (Unknown Source)

这里可以很明显的看到代码在StudyGroupRankingListLogic.java:277 中存在问题.

这里的 likedKey就是上面提到的ArrayList 里面存储的是String.而且是一个栈上的局部变量.但是由于while的循环条件这里书写有错误导致这个循环一直不能结束.直到把内存写爆.

注: 这里的代码含义大概是根据一个起始日期时间戳,循环遍历生成一个月以内的所有可能的key.每一个key由一个groupid-timestamp 这个刚好就是在内存dump中看到的值.由于这个时间无法停下来.后面失效的时间里面的时间戳就会特别大.所以在看内存值的时候有种好像不是时间戳的感觉.

到这里其实这个问题基本主分析完了. 其实这个问题也不需要这么复杂.只要是代码作者自己对自己代码功能敏感一点的话.其实是比较好发现的.当然还是得依赖一定的分析工具. 比如直接使用jstack进行分析.而不是上最后的屠龙刀.

后记

通过上面的分析,对这一个故障的复盘就比较清晰了.

这是一个HTTP请求,需要一个月榜的数据. 而这个月榜的数据在实时计算的时候需要生成每一天的相应的榜单数据key. 而这个key的生成处理代码有问题,导致while循环处理成了死循环.最后把内存给写爆了.不过有几点需要梳理的如下, 这些实际与一般的理解是有出入的.

这个内存泄露不算是最终的泄露. 如果HTTP请求在进入死循环的时候. 会一直申请内存. 直到内存耗尽.但是在申请内存失败的时候, 最终HTTP请求会失败. 在HTTP请求失败后 , 这些内存是可以释放的.
并不是所有的GC都会失败. 每一次请求的GC只会失败一次.
这个内存泄露与一般的使用了全局类的缓存还不一样.比如: HashMap , LoadingCace等. 实际是代码逻辑错误导致的内存使用无法停止.
这个错误是可以简单发现的.

RBA的技术分享