【Java内存溢出排查】gc监测以及内存突增问题排查
前情提要
文档:【Java内存溢出排查】测试环境服务器挂...
链接:http://note.youdao.com/noteshare?id=783e7ec89950f4167867ef3ef33470b6&sub=48AEFC6FDECB4C60869FAA5FABF57AB0
通过以下命令信息可以确定是内存溢出,且Full GC后内存无法得到回收
top -Hp 1 (发现JVM Thread占用 CPU200%)
jstat -gccause 1 3s (发现大量full gc,且full gc后内存没有得到回收)
jmap -heap 1 (发现新生代、老年代used占比均99.99%)
问题分析
新版本代码部署到预发布环境后,同样出现了频繁Full GC(1w+次),CPU飙高而堆内存回收不了的问题,在代码发布上线之前,必须排查出到底原因是什么?
之前针对测试环境的现场信息分析,基本可以确定不存在比较明显的内存泄漏(即使存在,也不会是导致服务挂掉的根本原因)
这里再次用新的方法说明为什么得出这个结论——
线索一:MAT(Memery Analysis Tools)指出的唯一内存泄漏可能
根据MAT对我们测试环境怪掉时的堆内存快照分析,给出的唯一的内存泄漏建议如下,换句话说,有一定量ParallelWebappClassLoader对象的引用出现了问题,导致GC无法正常回收这部分内存,那么一定量指的是多少?12.39%,也就是存在内存泄漏问题的话,对整个堆内存溢出问题的影响是非常小的。一般比较明显的内存溢出问题,占比会达到70%以上。
ParallelWebappClassLoader到底是不是内存泄漏?
如果不是ParallelWebappClassLoader对象引用造成的,服务器内存溢出的根因到底又是什么?
线索二:GC后的内存占用情况
下面是测试环境服务器正常情况下,执行jmap -histo:live pid | head -n 23 命令的截图,可以得到当前内存中排名前20的对象实例和class等信息。
这里说明下jmap -histo:live [pid]命令,执行后,将会触发一次Full GC,得到的执行结果是Full GC后的内存对象情况。
通过jstat -gccause [pid]命令也可以看到jmap执行后的GC原因,会显示 “Heap Inspection Initiated GC”
从instances列来看,[C、[I、[B排名靠前是正常的,毕竟是基础数据类型(char\int\byte)。
当时最先怀疑的是绿色框中的ConcurrentHashMap$Node对象,这可能是某些比较大的map造成的,一般内存泄漏也会是各种map或list持有引用导致的。
所以直接执行下面命令重点观察ConcurrentHashMap$Node对象的实例数(instances)
jmap -histo:live 1 | grep java.util.concurrent.ConcurrentHashMap$Node
得到如下结果,简单总结一下结果,下面的执行信息太长可以跳过……
1)随着服务被持续调用,java.util.concurrent.ConcurrentHashMap$Node对象实例数会不断累加,但GC过后也得到了回收
2)一定时间段内,ConcurrentHashMap$Node对象的回收慢于其增长数量,回收效率比较低
num #instances #bytes class name
----------------------------------------------1: 516515 77064424 [C2: 30478 39696288 [B3: 337998 29743824 java.lang.reflect.Method4: 16370 18795648 [I5: 510907 12261768 java.lang.String6: 374742 11991744 java.util.concurrent.ConcurrentHashMap$Node7: 222880 10698240 org.aspectj.weaver.reflect.ShadowMatchImpl8: 130860 7360464 [Ljava.lang.Object;9: 222880 7132160 org.aspectj.weaver.patterns.ExposedState
root@team-app-service-2-599746d64b-h6tzj:/usr/local/tomcat# jmap -histo:live 1 | grep java.util.concurrent.ConcurrentHashMap$Node6: 374823 11994336 java.util.concurrent.ConcurrentHashMap$Node18: 5441 2834704 [Ljava.util.concurrent.ConcurrentHashMap$Node;52: 7680 491520 java.util.concurrent.ConcurrentHashMap561: 107 5136 java.util.concurrent.ConcurrentHashMap$TreeNode744: 149 2384 java.util.concurrent.ConcurrentHashMap$EntrySetView927: 4 1120 java.util.concurrent.ConcurrentHashMap$CounterCell
1029: 34 816 java.util.concurrent.ConcurrentHashMap$KeySetView
1190: 11 528 java.util.concurrent.ConcurrentHashMap$TreeBin
1719: 12 192 java.util.concurrent.ConcurrentHashMap$ValuesView
3436: 2 48 [Ljava.util.concurrent.ConcurrentHashMap$CounterCell;
root@team-app-service-2-599746d64b-h6tzj:/usr/local/tomcat# jmap -histo:live 1 | grep java.util.concurrent.ConcurrentHashMap$Node6: 374851 11995232 java.util.concurrent.ConcurrentHashMap$Node18: 5455 2835824 [Ljava.util.concurrent.ConcurrentHashMap$Node;52: 7694 492416 java.util.concurrent.ConcurrentHashMap564: 107 5136 java.util.concurrent.ConcurrentHashMap$TreeNode747: 149 2384 java.util.concurrent.ConcurrentHashMap$EntrySetView930: 4 1120 java.util.concurrent.ConcurrentHashMap$CounterCell
1033: 34 816 java.util.concurrent.ConcurrentHashMap$KeySetView
1197: 11 528 java.util.concurrent.ConcurrentHashMap$TreeBin
1719: 12 192 java.util.concurrent.ConcurrentHashMap$ValuesView
3435: 2 48 [Ljava.util.concurrent.ConcurrentHashMap$CounterCell;
root@team-app-service-2-599746d64b-h6tzj:/usr/local/tomcat# jmap -histo:live 1 | grep java.util.concurrent.ConcurrentHashMap$Node6: 375425 12013600 java.util.concurrent.ConcurrentHashMap$Node18: 5742 2858784 [Ljava.util.concurrent.ConcurrentHashMap$Node;51: 7981 510784 java.util.concurrent.ConcurrentHashMap581: 107 5136 java.util.concurrent.ConcurrentHashMap$TreeNode760: 149 2384 java.util.concurrent.ConcurrentHashMap$EntrySetView939: 4 1120 java.util.concurrent.ConcurrentHashMap$CounterCell
1039: 34 816 java.util.concurrent.ConcurrentHashMap$KeySetView
1197: 11 528 java.util.concurrent.ConcurrentHashMap$TreeBin
1719: 12 192 java.util.concurrent.ConcurrentHashMap$ValuesView
3435: 2 48 [Ljava.util.concurrent.ConcurrentHashMap$CounterCell;
root@team-app-service-2-599746d64b-h6tzj:/usr/local/tomcat# jmap -histo:live 1 | grep java.util.concurrent.ConcurrentHashMap$Node6: 374815 11994080 java.util.concurrent.ConcurrentHashMap$Node18: 5437 2834384 [Ljava.util.concurrent.ConcurrentHashMap$Node;52: 7676 491264 java.util.concurrent.ConcurrentHashMap561: 107 5136 java.util.concurrent.ConcurrentHashMap$TreeNode744: 149 2384 java.util.concurrent.ConcurrentHashMap$EntrySetView926: 4 1120 java.util.concurrent.ConcurrentHashMap$CounterCell
1028: 34 816 java.util.concurrent.ConcurrentHashMap$KeySetView
1190: 11 528 java.util.concurrent.ConcurrentHashMap$TreeBin
1719: 12 192 java.util.concurrent.ConcurrentHashMap$ValuesView
3435: 2 48 [Ljava.util.concurrent.ConcurrentHashMap$CounterCell;
root@team-app-service-2-599746d64b-h6tzj:/usr/local/tomcat# jmap -histo:live 1 | grep java.util.concurrent.ConcurrentHashMap$Node6: 374850 11995200 java.util.concurrent.ConcurrentHashMap$Node18: 5450 2835488 [Ljava.util.concurrent.ConcurrentHashMap$Node;51: 7690 492160 java.util.concurrent.ConcurrentHashMap563: 107 5136 java.util.concurrent.ConcurrentHashMap$TreeNode745: 150 2400 java.util.concurrent.ConcurrentHashMap$EntrySetView928: 4 1120 java.util.concurrent.ConcurrentHashMap$CounterCell
1030: 34 816 java.util.concurrent.ConcurrentHashMap$KeySetView
1192: 11 528 java.util.concurrent.ConcurrentHashMap$TreeBin
1718: 12 192 java.util.concurrent.ConcurrentHashMap$ValuesView
3431: 2 48 [Ljava.util.concurrent.ConcurrentHashMap$CounterCell;
root@team-app-service-2-599746d64b-h6tzj:/usr/local/tomcat# jmap -histo:live 1 | grep java.util.concurrent.ConcurrentHashMap$Node6: 375404 12012928 java.util.concurrent.ConcurrentHashMap$Node18: 5697 2855376 [Ljava.util.concurrent.ConcurrentHashMap$Node;51: 7940 508160 java.util.concurrent.ConcurrentHashMap576: 107 5136 java.util.concurrent.ConcurrentHashMap$TreeNode762: 152 2432 java.util.concurrent.ConcurrentHashMap$EntrySetView943: 4 1120 java.util.concurrent.ConcurrentHashMap$CounterCell
1042: 34 816 java.util.concurrent.ConcurrentHashMap$KeySetView
1202: 11 528 java.util.concurrent.ConcurrentHashMap$TreeBin
1732: 12 192 java.util.concurrent.ConcurrentHashMap$ValuesView
3456: 2 48 [Ljava.util.concurrent.ConcurrentHashMap$CounterCell;
root@team-app-service-2-599746d64b-h6tzj:/usr/local/tomcat# jmap -histo:live 1 | grep java.util.concurrent.ConcurrentHashMap$Node6: 374882 11996224 java.util.concurrent.ConcurrentHashMap$Node18: 5449 2835472 [Ljava.util.concurrent.ConcurrentHashMap$Node;51: 7690 492160 java.util.concurrent.ConcurrentHashMap559: 107 5136 java.util.concurrent.ConcurrentHashMap$TreeNode746: 151 2416 java.util.concurrent.ConcurrentHashMap$EntrySetView928: 4 1120 java.util.concurrent.ConcurrentHashMap$CounterCell
1029: 34 816 java.util.concurrent.ConcurrentHashMap$KeySetView
1191: 11 528 java.util.concurrent.ConcurrentHashMap$TreeBin
1718: 12 192 java.util.concurrent.ConcurrentHashMap$ValuesView
3431: 2 48 [Ljava.util.concurrent.ConcurrentHashMap$CounterCell;
root@team-app-service-2-599746d64b-h6tzj:/usr/local/tomcat# jmap -histo:live 1 | grep java.util.concurrent.ConcurrentHashMap$Node6: 375174 12005568 java.util.concurrent.ConcurrentHashMap$Node18: 5462 2838848 [Ljava.util.concurrent.ConcurrentHashMap$Node;51: 7701 492864 java.util.concurrent.ConcurrentHashMap560: 107 5136 java.util.concurrent.ConcurrentHashMap$TreeNode741: 153 2448 java.util.concurrent.ConcurrentHashMap$EntrySetView926: 4 1120 java.util.concurrent.ConcurrentHashMap$CounterCell
1024: 34 816 java.util.concurrent.ConcurrentHashMap$KeySetView
1190: 11 528 java.util.concurrent.ConcurrentHashMap$TreeBin
1714: 12 192 java.util.concurrent.ConcurrentHashMap$ValuesView
3431: 2 48 [Ljava.util.concurrent.ConcurrentHashMap$CounterCell;
root@team-app-service-2-599746d64b-h6tzj:/usr/local/tomcat# jmap -histo:live 1 | grep java.util.concurrent.ConcurrentHashMap$Node6: 376732 12055424 java.util.concurrent.ConcurrentHashMap$Node18: 5818 2866688 [Ljava.util.concurrent.ConcurrentHashMap$Node;51: 8078 516992 java.util.concurrent.ConcurrentHashMap574: 107 5136 java.util.concurrent.ConcurrentHashMap$TreeNode757: 154 2464 java.util.concurrent.ConcurrentHashMap$EntrySetView949: 4 1120 java.util.concurrent.ConcurrentHashMap$CounterCell
1051: 34 816 java.util.concurrent.ConcurrentHashMap$KeySetView
1230: 11 528 java.util.concurrent.ConcurrentHashMap$TreeBin
1788: 12 192 java.util.concurrent.ConcurrentHashMap$ValuesView
3509: 2 48 [Ljava.util.concurrent.ConcurrentHashMap$CounterCell;
所以分析ConcurrentHashMap$Node对象可能存在泄漏,在通过MAT查看该对象的引用情况(排除弱引用),根据shallow heap字段倒序排序,得到结果证实了MAT指出的内存泄漏问题对象ParallelWebappClassLoader,说明MAT分析是有道理的,所以可以确定这里存在比较“轻微”的内存泄漏问题。
为什么说是“轻微”的内存泄漏问题?接着就要分析下,服务挂掉的时候,这个ConcurrentHashMap$Node对象占用堆内存12307392b≈11.73M,而当时老年代大小为337M,所以不是它压垮的服务器。
这里也可以直接看下ParallelWebappClassLoader对象的Retained Heap(深堆内存)大小,这个值意味着如果该对象被回收,将获得多少的内存收益。
线索三:内存突增
当时只关注了内存泄漏这个点,忘记了流量突增或者是某些特定代码查询的数据量突增,也可能导致内存溢出,特别是在老年代设置得比较小的情况下。
而我们测试环境的流量不可能产生突增,基本就是测试同学在进行功能测试,QPS也比较低。从sky walking监控服务挂掉时的请求量也都还算正常
但看内存监控发现有内存的突增,14:53到14:54一分钟从402M突增到了462M,并且之后还在突增到483M(这时Full GC后老年代used占比依然是99.99%),测试环境堆的总大小500M,所以服务器内存溢出,应该是这个时间段的某段代码执行导致的。
问题排查
思路一:排查接口
方向找到了,首先想到是分析关键时间段内的接口请求,能够一下子填满60+M的数据请求,接口耗时应该会挺长,因为在内存中遍历数据需要时间,再加上服务IO也需要时间。
不过由于测试环境日志被清理了,预发布环境有没有监控信息,从接口为入口的线索断掉了(况且接口响应慢也有可能是因为线程阻塞等其他资源竞争,没有说服力)
思路二:根据内存快照,对比突增内存对应的对象及其引用
没有接口日志也没关系,我对比了一下测试环境,服务器内存溢出时(下图1)的快照和服务器正常工作时(观察了比较久,数据稳定)的内存快照(下图2)
内存增加了47M(图3),还没算上其他的一些incoming引用对象的大小,那么这个突增的大小是对应得上前面分析得问题根因的。
(图1)
(图2)
(图3)
所以可以在服务挂掉时,且执行过GC后的堆内存快照中排查分析“[C”和“[B”这两块内存数据,可以更准确的找到这部分出问题的数据,最终找到问题代码。
先展开char[]对象和其引用,看看具体是什么东东导致比正常服务时多出来30M数据。
按照Shallow Heap(浅堆空间,即对象实际占用内存大小)倒叙排序,找一些问题对象看看(哪些是问题对象?1体积比较大的;2体积不大,但个数惊人的)
对比时突然发现当时测试环境怪掉时拿到的堆快照和服务正常时的快照数据几乎一致,暂时还不知道是不是文件下载错了,所以目前只能调整测试环境JVM配置,等测试环境再次出现问题时再dump一次堆快照,然后建立可用对照组进一步分析。
再次把服务器搞挂一次之后,拿到监控数据,频繁Full GC,各堆内存区域used 99%
此时的堆内存对象占用情况如下,基本和上一次挂掉的数据一致。
MAT建立对照组,分析问题数据,发现问题对象[C 的引用有一个ElasticSearchGroupUnitField,和客源匹配小组日记查询有关,是ES搜索服务提供的接口。
这一个大char[]对象的实际内存占用了17141776b ≈ 16.34M,难以想象这个接口发布到线上,多线程请求执行时服务器能撑多久……
这就是导致测试环境服务器挂掉的根本原因!
问题代码分析
查询某个客户匹配的小组日记列表时,没有加入小组id条件,而设置的pageSize为1000条,在没有指定groupId的情况下,整个小组日记中搜索与之匹配的日记数据,那肯定是每次都是满载的1000条,而日记的字段又比较多,单个文档的数据量比较大。
这个业务方法在客源列表、客源详情、客源匹配日记接口等都有调用,所以将代码发布到测试环境后,针对性测试了几分钟服务就挂了,问题复现。
修复逻辑比较简单,就是加入需要查询的小组id作为查询条件,修复后,再次针对以上场景进行测试,GC回收正常,问题解决。
总结
1. 排查服务器内存性能问题应该从2个大方向获取信息进行分析:
a. 内存泄漏
b. 内存(流量)突增
先确定是什么病,再对症下药,以免绕弯子…
2. 加强code review的执行力度,毕竟code review的成本比这样一顿排查和分析要小得多,反向的排查总是要复杂和困难的
最后,还是感谢 trouble maker,还有帮忙验证的测试同学!
【Java内存溢出排查】gc监测以及内存突增问题排查相关推荐
- Java内存溢出故障案例及Linux内存机制探究
文章目录 Java内存溢出故障案例及Linux内存机制探究 OOM Killer触发机制分析 如何避免系统触发OOM Killer 这部分内容属于demo案例分享,解决线上运维问题,思路是最重要的 J ...
- python 内存溢出能捕获吗_Python内存泄漏和内存溢出的解决方案
一.内存泄漏 像Java程序一样,虽然Python本身也有垃圾回收的功能,但是同样也会产生内存泄漏的问题. 对于一个用 python 实现的,长期运行的后台服务进程来说,如果内存持续增长,那么很可能是 ...
- java 内存溢出-与gc
感谢原作者 在日常中我们经常遇到这样的错误:java.lang.OutOfMemoryError: Java heap space. 但是除了heap space 的OutOfMemoryError, ...
- Java反序列化json内存溢出_fastJson与一起堆内存溢出'血案'
现象 QA同学反映登录不上服务器 排查问题1–日志级别 查看log,发现玩家登录的时候抛出了一个java.lang.OutOfMemoryError 大概代码是向Redis序列化一个PlayerMir ...
- java堆外内存溢出_JVM 案例 - 堆外内存导致的溢出错误
案例 一个网站为了实现客户端实时从服务端接收数据,使用了 CometD 1.1.1 作为服务端推送框架,服务器是 Jetty7.1.4,CPU i5,内存 4G,操作系统 32位Windows. 服务 ...
- java模拟内存溢出并分析_模拟内存溢出通过MAT分析
构建一个简单的Springboot应用,模拟出OOM场景,再导出heap dump文件,通过Mat分析. 搭建简易Springboot,模拟OOM场景 搭建一个简易的springboot工程,在con ...
- java 内存溢出时打印_如何在JVM内存溢出的时候自动dump内存快照
解决OOM问题的一个初步思路 首先第一个问题,假设发生OOM了,必然说明系统中某个区域的对象太多了,塞满了那个区域,而且一定是无法回收掉那些对象,最终才会导致内存溢出的. 既然是这个思路,要解决OOM ...
- java内存溢出原因及解决_java内存溢出的原因和解决方法
java内存溢出的原因和解决方法 发布时间:2020-06-15 17:57:39 来源:亿速云 阅读:85 作者:元一 内存溢出含义: 内存溢出(out of memory)通俗理解就是内存不够,通 ...
- java内存溢出怎样查找代码_JVM - 内存溢出,问题查找
当内存溢出会抛出 java.lang.OutOfMemoryError: Java heap space 的异常,那这个时候怎样去分析到底哪里导致内存溢出呢? 我们可以通过在vm的参数, -XX:+H ...
最新文章
- Aliyun LOG Java Producer 快速入门
- MySQL:SELECT COUNT 小结
- pcb地线应该不应该做成环路_PCB制板的基础知识,你都学会了吗?(中)
- Codeforces1045G
- PostgreSQL下安装pg_stat_statements
- container view_高级UI晋升之常用View(三)中篇
- CDN行业“三足鼎立”格局已定,谁能代表未来?
- ElasticSearch 介绍及使用方法
- Linux内核workqueue
- gc java root_深入理解Java中的Garbage Collection
- hbase数据读取优化_read读取优化_HBase最佳实践_HBase开发指南_云数据库 HBase - 阿里云...
- [Java2 入门经典]第6章 类的扩展与继承
- 利用matlab自带函数graycoprops 实现基于共生矩阵的遥感图像纹理特征分析
- 吉大计算机学院周柚,周柚
- Java 动态编译基础学习
- win7降低屏幕亮度_win7亮度调节不见了怎么办
- Python - turtle画图库 临摹粉色花卉卡片
- coldfusion php,在Coldfusion中加密,然后在PHP中解密
- ARM32 寄存器分类
- Wireshark 抓取 iphone 测试机的数据包