MAT：一次线上内存泄漏排查

localhost01
4,071 阅读8分钟

一、背景

首先，发现线上某分析应用出现异常，连续好几天，一直没有分析数据产出。故登陆到线上查看error.log日志，发现：

在这里插入图片描述
明显是 YCYX-Task 这个线程出现了内存溢出，导致程序假死。

二、排查历程

1、初步定位

jinfo

首先，我们使用jinfo pid查看当前jvm的堆相关参数：

在这里插入图片描述
可见，最大堆容量为：4G。

jstat

接下来，我们使用命令jstat -gcutil pid 1s 5查看5秒内当前堆占用情况：

在这里插入图片描述
如上，新生代已经满了（占用97.33%），老年代也已经满了（占用100%），同时FullGC高达967次！

jmap

除了jstat命令外，我们也可以使用jmap -heap pid查看下当前JVM堆情况：

在这里插入图片描述
然后，我们用jmap -F -histo pid | head -n 13查看前13行打印，即查看TOP10的大对象（最好用head限制一下，否则列出的对象会铺满你的屏幕，另外：强制连接参数-F对jmap -histo:live是无效的）：
在这里插入图片描述
如上，可以看到，除了几大基本类型外（因为各对象的底层都是几个基本类型，所以无意外它们会排在top前几），一个java.util.HashMap和java.util.ArrayList非常显眼……先记下，后面继续分析先。

最后，我们使用命令jmap -F -dump:file=a.bin pid将堆dump出来，发现dump出来的文件有4.02G，很恐怖，故使用tar -czvf a.tar.gz a.bin打包压缩一下！

2、MAT深入分析

调整MAT最大堆内存

将打包好的a.tar.gz拉回到本地，并解压。但是由于a.bin过大，MAT打开肯定会内存溢出，故调整MAT软件的最大堆内存：

[ MAT根目录下的MemoryAnalyzer.ini ]
-startup
plugins/org.eclipse.equinox.launcher_1.5.0.v20180512-1130.jar
--launcher.library
plugins/org.eclipse.equinox.launcher.win32.win32.x86_64_1.1.700.v20180518-1200
-vmargs
-Xmx6g

-Xmx 改为6G！

MAT分析大对象

在这里插入图片描述
映入眼帘的就是一个超、超、超级大的对象，3GB，占用了97.25的内存，且位于 YCYX-Task 这个线程内，印证了开头的error.log报错日志YCYX-Task报内存泄漏的情况。然后点开这个java.lang.Object[]的Details，如下图：
在这里插入图片描述
可以看到，这个Object数组，的确占用了3个G的内存，同时也的确在一个ArrayList内部，印证了刚刚jmap -histo pid | head -n 13一个异常ArrayList的情况，同时它内部也正是由HashMap构成！
在这里插入图片描述
图上，可以看到这个ArrayList存了接近31万个元素，故导致内存泄漏。最终得出结论是由于代码里面的一个ArrayList问题！

代码走读排查

结合error.log日志报出的问题JAVA类、报错代码行数，再结合问题应该出在一个ArrayList上，很容易就定位到了相关问题代码块：

  /**
	* 按照指定起止时间分析数据
	* @param beginTime 起始时间
	* @param endTime 截至时间
	*/
   @Override public void exec(String beginTime, String endTime) {
        List<Map<String, Object>> emlWithLoginList = new ArrayList<>();
        List<Map<String, Object>> emlList = new ArrayList<>();

        while (true) {
            try {
				//如果已分析到截至时间，则退出。
            	if (DateUtil.compareTime(beginTime, endTime) > 0) {
                    break;
                }

                //每次循环向前推10小时，YCYX_PERIOD=10小时
                String tmpTime=DateUtil.addHours(beginTime, YCYX_PERIOD);
                
                //1.构造请求
                BoolQueryBuilder bqb = QueryBuilders.boolQuery();
                bqb.must(QueryBuilders.rangeQuery(CREATE_TIME).gt(beginTime).lte(tmpTime));
                bqb.must(QueryBuilders.termQuery(IS_DELETE, IS_FIELD_VALUE));
                bqb.must(QueryBuilders.existsQuery(TOS));
                bqb.must(QueryBuilders.existsQuery(FROMS));
                bqb.must(QueryBuilders.existsQuery(SEND_TYPE));
                bqb.must(QueryBuilders.existsQuery(SESSION_ID));

                log.debug("emlAnalysis begin at " + beginTime + ", and end at " + lastTime);

                SearchSourceBuilder requestBuilder = new SearchSourceBuilder().query(bqb).size(PAGE_SIZE).sort(CREATE_TIME, SortOrder.ASC).fetchSource(new String[] {"*"},
                        new String[] {EML_CONTENT});

                //2.发起请求
                EsHelper.getResponseScroll(EsCluster.DEFAULT, INF_EML_INDEX, "14m", requestBuilder.toString(), result -> {
                            
                            //3.解析结果
                            EsSearchHit[] hits = result.getHits().getHits();
                            List<Map<String, Object>> loginList;
                            for (EsSearchHit hit : hits) {
                            	//将邮件Map添加到列表中
                             	Map<String, Object> emlMap = hit.getSource();
                                emlList.add(emlMap);
                                
                                //将邮件+MailLogin的Map添加到另一个列表中
                                Map<String, Object> emlWithLoginMap = new HashMap(emlMap);               
                                String sessionId = emlMap.get(SESSION_ID).toString();
                                MailLogin mailLogin = EsService.getMailLoginBySessionId(sessionId);
                                emlWithLoginMap.put("Login_Key", mailLogin );
                                emlWithLoginList.add(emlWithLoginMap);
                            }
                            return true;
                        });

                //4.A类检测逻辑
                checkDSYJEml(emlWithLoginList);
				emlWithLoginList.clear();

                //5.B类检测逻辑
                checkYCYXEml(emlList);
				emlList.clear();
                
                beginTime = tmpTime;
            } catch (Throwable e) {
                log.error("", e);
            }
        }
    }

由上面代码可见，问题List应该就是 emlWithLoginList 或者 emlList的其中一个了，而两个List存储的内容基本相同，除了emlWithLoginList内的Map元素额外存了一个叫做Login_Key的key！

而通过MAT查看了问题List内Map元素的所有Key，并没有找到相关叫做Login_Key的元素，故推测问题List应该是这个emlList！

在这里插入图片描述
而直接看上面的代码逻辑，没有发现什么大的问题。且本方法是按照传入的起、止时间，按每10小时为时间段，依次进行ES数据查询、分析的。

因此我们先猜测，是否是因为当前时间段的ES数据过大导致？

代码里面可以看到，ES查询的数据，是通过CREATE_TIME(该常量值为@createtime)进行升序查询的，故先查的数据，应该位于这个问题List的开头，而后查的数据在问题List的结尾。

因此通过MAT找到问题List的第一个和最后一个元素，即得到本次查询的起、止时间：

在这里插入图片描述
在这里插入图片描述
可以看到，时间段大致为2019-11-01 16:00:00到2019-11-02 02:00:00！时间符合我们的每批数据查询的10小时时间段。

图上说明，查询这一批数据，程序得到了31万条数据！

而我又到Kibana查询了一下这个时间段的数据量：

在这里插入图片描述
才两万多条，完全对不上啊？

一下子就迷了，这个情况有点说不通，想了半天，于是，又仔细地看了下代码：

在这里插入图片描述
注意到了图上位置的代码，这两个List都在不断的添加元素，然后执行各自的检测逻辑，最后调用clear()方法清空List，为何emlWithLoginList没有问题，而emlList却内存溢出了？

那么就很显然了：

  1. 假如在执行checkYCYXEml(emlList)时，出现了异常，就会直接被下面的catch给捕获；
  2. 因而不会走下面的emlList.clear()代码，同时也不会走beginTime = timeTime；
  3. 由于try catch位于while循环内部，因此抛出异常后会继续循环，且因为没有执行beginTime = timeTime，故查询的数据还是之前的这个时间段的数据；
  4. 同时，也可以解释为什么emlWithLoginList没有问题了，因为在异常代码的前面，可以进行正常的clear()操作。

那么，如果是checkYCYXEml(emlList)时，出现了异常，error.log应该是有异常日志打印的，通过关键字checkYCYXEml搜了一下：

在这里插入图片描述
果然找到了这个方法报出的异常，并且原因是Ice超时。这个我是知道的，由于公司新上的EsService中间件（部署在分布式RPC框架-Ice上面的），限制了各调用方的ES查询时间，超过指定时间，会强行返回一个Ice超时错误，目的是为了防止不规范的复杂语句把ES查崩！

按照上面说的，如果是这个原因，这段代码会重复查询2019-11-01 16:00:00到2019-11-02 02:00:00的数据，且不断加入到emlList中，最后撑爆JVM！

那么MAT中的这个问题List应该会有多个相同元素存在（数据重复加入进去了嘛）。

如何验证这一点呢？

因为这些数据有一个emlkey字段，是一个唯一主键，对应这条记录在ES中的_id，因此可通过MAT，根据某一条数据的emlkey，去查找是否问题emlList中有多个元素均存在相同的emlkey，即可证明。

MAT对字符串进行分组

在这里插入图片描述
在这里插入图片描述
由于这个dump文件很大，故查询需要花很长时间，需耐心等待~
在这里插入图片描述
题外话：我们可以看到，很多String值是相同的，但却分配了好几十万个String对象来存储，这里我们可以使用Java 8的-XX:+UseStringDeduplication功能，来减轻重复字符串的问题。这将导致这几十万个String实例，但其底层的数组均指向同一个char数组。

图上即是对针对String进行的分组操作，这时，我们随便找一个元素的emlkey，查询一下：

在这里插入图片描述
然后选中该记录，右键，使用merge shortest paths to gc roots功能，可查看这些对象到GC ROOT的最短路径，说白了，就是想通过这个功能，查看当前这个String是属于哪个对象下面的：
在这里插入图片描述
可以看到，有32个String对象，值均为854742740486326718e
在这里插入图片描述
在这里插入图片描述
那么为什么有32个String呢，这是因为每个对象，除了有一个emlkey属性，还有一个document_id属性，这两个值是一样的，均是表示ES的_id，如图：
在这里插入图片描述
OK，16个对象，相当于重新查询了ES16遍，每次查询是22221条，22221x16=355536，数量基本吻合，没有完全对上，是因为上面代码里的scroll查询，也出现过IceTimeOut异常，导致22221条还没有完全查询完即结束了。

最后这个问题，基本就定位到了，修复也就简单了，把两个Clear()方法，都移到catch后面的finally中，即可保证100%会调用，另外就是对接中间件的同事，针对IceTimeOut问题的解决了。

avatar
文章
阅读
粉丝

友情链接：