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

时间  2020-07-10
标签 mat 一次 线上 内存 泄漏 排查 繁體版
原文   原文链接

1、背景

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

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

2、排查历程

一、初步定位

jinfo

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

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

jstat

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

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

jmap

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

在这里插入图片描述
而后，咱们用 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打包压缩一下！框架

二、MAT深刻分析

调整MAT最大堆内存

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

[ 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！jvm

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！ide

而经过MAT查看了问题List内Map元素的全部Key，并无找到相关叫作Login_Key的元素，故推测问题List应该是这个emlList！ fetch

在这里插入图片描述
而直接看上面的代码逻辑，没有发现什么大的问题。且本方法是按照传入的起、止时间，按 每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问题的解决了。

相关文章
相关标签/搜索
每日一句
    每一个你不满意的现在，都有一个你没有努力的曾经。
本站公众号
   欢迎关注本站公众号,获取更多信息
联系我们 最近搜索 最新文章 沪ICP备13005482号-10 MyBatis教程 SQL 教程 MySQL教程 Java 教程 Thymeleaf 教程 Hibernate教程 Spring教程 Redis教程