本文详细记录了一次Java服务在测试环境中遭遇内存溢出问题的排查过程，通过分析内存泄漏、流量突增及特定代码行为，最终定位并解决了由不当ES查询引发的内存占用激增问题。
前情提要
文档：【Java内存溢出排查】测试环境服务器挂...
通过以下命令信息可以确定是内存溢出，且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 [C
2: 30478 39696288 [B
3: 337998 29743824 java.lang.reflect.Method
4: 16370 18795648 [I
5: 510907 12261768 java.lang.String
6: 374742 11991744 java.util.concurrent.ConcurrentHashMap$Node
7: 222880 10698240 org.aspectj.weaver.reflect.ShadowMatchImpl
8: 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$Node
6: 374823 11994336 java.util.concurrent.ConcurrentHashMap$Node
18: 5441 2834704 [Ljava.util.concurrent.ConcurrentHashMap$Node;
52: 7680 491520 java.util.concurrent.ConcurrentHashMap
561: 107 5136 java.util.concurrent.ConcurrentHashMap$TreeNode
744: 149 2384 java.util.concurrent.ConcurrentHashMap$EntrySetView
927: 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$Node
6: 374851 11995232 java.util.concurrent.ConcurrentHashMap$Node
18: 5455 2835824 [Ljava.util.concurrent.ConcurrentHashMap$Node;
52: 7694 492416 java.util.concurrent.ConcurrentHashMap
564: 107 5136 java.util.concurrent.ConcurrentHashMap$TreeNode
747: 149 2384 java.util.concurrent.ConcurrentHashMap$EntrySetView
930: 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$Node
6: 375425 12013600 java.util.concurrent.ConcurrentHashMap$Node
18: 5742 2858784 [Ljava.util.concurrent.ConcurrentHashMap$Node;
51: 7981 510784 java.util.concurrent.ConcurrentHashMap
581: 107 5136 java.util.concurrent.ConcurrentHashMap$TreeNode
760: 149 2384 java.util.concurrent.ConcurrentHashMap$EntrySetView
939: 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$Node
6: 374815 11994080 java.util.concurrent.ConcurrentHashMap$Node
18: 5437 2834384 [Ljava.util.concurrent.ConcurrentHashMap$Node;
52: 7676 491264 java.util.concurrent.ConcurrentHashMap
561: 107 5136 java.util.concurrent.ConcurrentHashMap$TreeNode
744: 149 2384 java.util.concurrent.ConcurrentHashMap$EntrySetView
926: 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$Node
6: 374850 11995200 java.util.concurrent.ConcurrentHashMap$Node
18: 5450 2835488 [Ljava.util.concurrent.ConcurrentHashMap$Node;
51: 7690 492160 java.util.concurrent.ConcurrentHashMap
563: 107 5136 java.util.concurrent.ConcurrentHashMap$TreeNode
745: 150 2400 java.util.concurrent.ConcurrentHashMap$EntrySetView
928: 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$Node
6: 375404 12012928 java.util.concurrent.ConcurrentHashMap$Node
18: 5697 2855376 [Ljava.util.concurrent.ConcurrentHashMap$Node;
51: 7940 508160 java.util.concurrent.ConcurrentHashMap
576: 107 5136 java.util.concurrent.ConcurrentHashMap$TreeNode
762: 152 2432 java.util.concurrent.ConcurrentHashMap$EntrySetView
943: 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$Node
6: 374882 11996224 java.util.concurrent.ConcurrentHashMap$Node
18: 5449 2835472 [Ljava.util.concurrent.ConcurrentHashMap$Node;
51: 7690 492160 java.util.concurrent.ConcurrentHashMap
559: 107 5136 java.util.concurrent.ConcurrentHashMap$TreeNode
746: 151 2416 java.util.concurrent.ConcurrentHashMap$EntrySetView
928: 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$Node
6: 375174 12005568 java.util.concurrent.ConcurrentHashMap$Node
18: 5462 2838848 [Ljava.util.concurrent.ConcurrentHashMap$Node;
51: 7701 492864 java.util.concurrent.ConcurrentHashMap
560: 107 5136 java.util.concurrent.ConcurrentHashMap$TreeNode
741: 153 2448 java.util.concurrent.ConcurrentHashMap$EntrySetView
926: 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$Node
6: 376732 12055424 java.util.concurrent.ConcurrentHashMap$Node
18: 5818 2866688 [Ljava.util.concurrent.ConcurrentHashMap$Node;
51: 8078 516992 java.util.concurrent.ConcurrentHashMap
574: 107 5136 java.util.concurrent.ConcurrentHashMap$TreeNode
757: 154 2464 java.util.concurrent.ConcurrentHashMap$EntrySetView
949: 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，还有帮忙验证的测试同学！
扫一扫
14万+
被折叠的 条评论
为什么被折叠?
到【灌水乐园】发言
