MAT：一次線上內存泄漏排查

1、背景

首先，發現線上某分析應用出現異常，連續好幾天，一直沒有分析數據產出。故登錄到線上查看error.log日誌，發現：

明顯是 YCYX-Task 這個線程出現了內存溢出，致使程序假死。

2、排查歷程

一、初步定位

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打包壓縮一下！

二、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問題的解決了。