一次使用MAT进行线上内存泄漏问题排查经历

一、背景

首先,发现线上某分析应用出现异常,连续好几天,一直没有分析数据产出。故登陆到线上查看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限制一下,否则列出的对象会铺满你的屏幕,另外:强制连接参数-Fjmap -histo:live是无效的):
在这里插入图片描述
如上,可以看到,除了几大基本类型外(因为各对象的底层都是几个基本类型,所以无意外它们会排在top前几),一个java.util.HashMapjava.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:002019-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问题的解决了。

展开阅读全文
©️2020 CSDN 皮肤主题: 数字20 设计师: CSDN官方博客 返回首页
实付0元
点击重新获取
扫码支付
钱包余额 0

抵扣说明:

1.余额是钱包充值的虚拟货币,按照1:1的比例进行支付金额的抵扣。
2.余额无法直接购买下载,可以购买VIP、C币套餐、付费专栏及课程。

余额充值