前段時間由於業務需要，需要從資料庫中查詢出來所有滿足條件的資料，然後匯入到檔案中。於是隨便寫了個程式，查詢出所有滿足條件然後再寫入檔案。但是實際上線後卻發現，程式剛開始執行馬上看到部分資料寫入到檔案，但是後面執行越來越慢，於是對此分析排查了一下。
應用環境
JDK 1.7 + Spring 4.3 + mybatis + oracle
問題排查
查詢以及寫入檔案虛擬碼如下：
private void queryAllData(Request request, List querData, int count, String path, List allData) {
if (CollectionUtils.isEmpty(querData)) {
return;
}
allData.addAll(querData);
// 總 List 大於一定指定數量將資料重新整理到檔案
if (allData.size() > 20000) {
saveToFile(request, allData, path);
}
// 判斷下一個偏移量 是否大於 總數
request.setPageNo(request.getPageNo() + 1);
// 查詢下一頁資料
List newQueryData = queryDao.selectDataByPage(request);
queryAllData(request, newQueryData, count, path, allData);
}
複製程式碼其中 queryDao.selectDataByPage 為一個分頁查詢方法。這個方法目的就在於遞迴查詢分頁資料，如果某一頁資料為空，就代表查詢結束，此時已查詢出所有資料。
為什麼不直接執行 select * from table where a=xx 類似的資料直接查出所有資料？
因為寫程式之前，查詢了一下滿足條件的資料總共有 200 w 資料，這樣如果直接一把查詢出所有資料，主要擔心堆記憶體直接佔滿，導致 OOM 錯誤。
寫完程式碼，部署到線上，然後執行匯出資料，就放著不管，幹其他事。過一段時間回來看資料匯出結果，這個時候大吃一驚，程式竟然還沒有結束，資料也才匯出 3/4 左右。這個時候意識到程式肯定存在問題，於是仔細檢查了一遍程式碼，也沒看出什麼。
沒辦法，這個時候只能分析線上程式 GC 情況了，幸好開啟了列印 GC 日誌的選項。拿到 GC 日誌檔案後，由於不太精通 GC 日誌詳細內容，只能借靠外部力量了。GC 日誌分析網站，該網站可以分析 GC 日誌，然後可以檢視各個時間點堆記憶體佔用情況。分析情況如圖。
這張圖為 GC 之後堆記憶體佔用情況。可以看出堆記憶體在 Full GC 之後並沒有很快的降下來且很快下一次 Full GC 就開始了。這樣大致可以看出，程式沒有在期待時間內執行結束，就是由於堆內被佔用過多，持續引起Full GC，應用程式執行緒持續被掛起。然後我們再看堆記憶體老年代佔用情況。
如上圖，堆記憶體老年代佔用空間持續上升直到接近佔滿，引起 Full GC，並沒有緩解這種情況，之後記憶體佔用一直接近到佔滿。
綜上，我們可以得知程式出現了記憶體洩漏。
知道了原因，我們就好順著找到問題。又順著捋了一遍程式碼，可惜的是並沒有看出問題。難道是 allData 資料集合越來越大，然後導致該現象？仔細檢視了 saveToFile 程式碼邏輯。
List<String> lines = Lists.newArrayListWithExpectedSize(allData.size());
for (Data data : allData) {
String line = process(data);
lines.add(line);
}
String fileName = "xx.txt";
try {
log.info("檔案開始輸出,輸出行數{}", lines.size());
FileUtils.writeLines(new File(fileName), "utf-8", lines, true);
allData.clear();
lines = null;
} catch (IOException e) {
log.error("檔案輸出失敗", e);
// 輸出失敗，先不管了，將資料繼續儲存集合中
}
複製程式碼可以看到，資料一旦寫入到檔案中，allData 集合立刻清空，所以不可能是該問題導致。
看了好幾遍程式碼之後，還是無法確定問題原因。最後一遍檢視程式碼，靈關一現，不會是 newQueryData 導致的問題吧？嘗試把這裡程式碼改成下面方式。
private void queryAllData(Request request, List querData, int count, String path, List allData) {
if (CollectionUtils.isEmpty(querData)) {
return;
}
allData.addAll(querData);
// queryData 放入到 allData 中後，將 querData 結合清空。
querData.clear();
// 總 List 大於一定指定數量將資料重新整理到檔案
if (allData.size() > 20000) {
saveToFile(request, allData, path);
}
// 判斷下一個偏移量 是否大於 總數
request.setPageNo(request.getPageNo() + 1);
// 查詢下一頁資料
newQueryData = queryDao.selectDataByPage(request);
queryAllData(request, newQueryData, count, path, allData);
複製程式碼改完程式碼，立刻部署，開始執行程式。這個時候檢視堆記憶體佔用情況，就可以知道改動是否有效。這裡推薦一個方便檢視 JVM 程式資訊的工具 vjtop。可以快速檢視堆記憶體佔用情況。
執行 vjtop 之後，一直盯著堆記憶體佔用情況。然後發現 eden 空間持續上升直到接近到滿，然後發生 Minor GC ，eden 空間迅速清空。 old 區記憶體也沒有一直佔用接近到滿這麼誇張。大概佔用 1/5 記憶體。改善情況如想象中一致，等待一定時間後，資料匯出完畢。
分析
現在我們分析為什麼出現記憶體洩漏。
我們知道 jvm 執行時，記憶體區分為 堆，虛擬機器棧，方法區等。上面我們發生的現象就與虛擬機器棧有關。
什麼事虛擬機器棧？
摘錄深入 Java 虛擬機器一書解釋
虛擬機器棧描述的是 Java 方法執行的記憶體模型：每個方法執行時都會建立一個棧幀用於儲存區域性變數表，運算元棧，動態連結，方法出口等資訊。每一個方法從呼叫直至執行完後的過程，就對應一個棧幀在虛擬機器棧中入棧到出棧的過程。
Java 執行緒執行方法時，jvm 虛擬機器棧資料結構如圖所示。
可以看出，我們在呼叫函式 1 時，就將該棧幀壓如棧中。函式 1 呼叫函式 2 時，也將該棧幀壓入棧中。處於棧中的棧幀包含區域性變數表，運算元幀等，而區域性變數表包含基本資料型別，以及物件引用指標。物件指標指向堆記憶體物件。就是因為物件引用指標，導致我們上面情況。為何這麼說那。我們再看下面這張圖。
我們可以看到，棧中每個方法 newQueryData 都指向堆中真正的物件。由於遞迴執行時，前面的方法都壓到棧中，newQueryData 一直還指向堆中物件，然後 GC 時，由於物件還處於被引用，虛擬機器判定該物件存活，所以不清理這些物件。隨著遞迴方法越來越深入，堆積的 newQueryData 越來越多，量表引起質變，導致堆記憶體被佔滿，引發虛擬機器持續 GC。但是每次 GC 之後卻無法騰出空間。最後我們看到的現象就是程式執行很慢很慢。
## 總結
這個問題本質看起來不是很難，但是實際發生的時候排查問題著實花費不少時間。下面我們總結一下這個過程。
- 如果程式實際執行起來與預想差距太大，那麼不用想了，肯定哪裡出問題了，趕快登上機器檢視吧。
- 程式執行必要節點的日誌輸出需要列印。上面程式本來剛開始寫的時候，由於主觀意思，想想沒那麼難，很快就擼完部署了。最後檢視日誌，由於沒有必要的日誌輸出，都不知道程式卡在那了。
- 需要了解一些 JVM 相關工具，可以及時檢視 JVM 相關情況，如記憶體使用情況。如本文的例子，實際上我們可以 dump 記憶體，然後分析哪裡發生了記憶體洩漏。很不幸的是，這方面本人只是處於瞭解層面，用的時候卻不知道如何下手，只好求助於一些現成開源工具完成。之後需要好好補這方面操作能力，哈哈哈。
- 本文如果使用 while 迴圈代替遞迴方式，問題可能更快定位。遞迴中的記憶體洩漏可能更加隱蔽，很容易被我們忽略，同學們下次再寫遞迴方法的時候不僅要注意遞迴方法深度，還要注意這個過程需要及時釋放無用物件，不要讓記憶體洩漏發生。
好了，文章大概就這樣了，下次文章再見了。
參考文章以及網站
- 深入 Java 虛擬機器 堆記憶體章節
- Java JVM 中 堆，棧，方法區 詳解
- gc 日誌分析網站
- 檢視 JVM 程式資訊的工具 -- vjtop
如果覺得好的話，請幫作者點個讚唄~ 謝謝
喜歡本文的讀者們，歡迎長按關注訂閱號程式通事~讓我與你分享程式那些事。
