關於GC(上)：Apache的POI元件導致線上頻繁FullGC問題排查及處理全過程

阿新 • • 發佈：2019-11-12

某線上應用在進行查詢結果匯出Excel時，大概率出現持續的FullGC。解決這個問題時，記錄了一下整個的流程，也可以作為一般性的FullGC問題排查指導。

1. 生成dump檔案

為了定位FullGC的原因，首先需要獲取heap dump檔案，看下發生FullGC時堆記憶體的分配情況，定位可能出現問題的地方。

1. 1 通過JVM引數自動生成

可以在JVM引數中設定-XX:+ HeapDumpBeforeFullGC引數。
建議動態增加這個引數，直接在線上映象中增加一方面是要重新打包釋出，另一方面風險比較高

sudo -u admin /opt/taobao/java/bin/jinfo -flag +HeapDumpBeforeFullGC pid

sudo -u admin /opt/taobao/java/bin/jinfo -flag +HeapDumpAfterFullGC pid

也可以用HeapDumpOnOutOfMemoryError這個引數，只在outOfMemoryError發生時才dump。實測只有在fullgc完成時才會產生該檔案，fullgc期間看不到。
此外還需要-XX:HeapDumpPath=/home/admin/logs/java.hprof這個引數來指定dump檔案存放路徑。

1.2 通過JDK工具生成

1.2.1 jmap

先獲取java程序ID，再使用jmap進行dump。
注意，虛擬機器上的jmap可能沒有做路徑對映，需要手動選擇jdk路徑下來執行

ps -aux | grep java
jmap -dump:file=test.hprof,format=b XXXX

1.2.2 通過jcmd

JDK7後新增的多功能命令，其中jcmd pid GC.heap_dump FILE_NAME的效果和jmap -dump:file=test.hprof,format=b pid一樣。

1.3 JConsole

可以生成本機或遠端JVM的dump。還有一些其他工具就不詳細介紹了。

2. 下載dump檔案

由於使用的是阿里雲的伺服器，可以直接將dump檔案上傳到OSS上通過公司內部工具來分析，或通過OSS再下載到本地。
設定OSSCMD：
操作命令 osscmd config --host=oss-cn-hangzhou-am101.aliyuncs.com --id=** --key=**

建立bucke：osscmd cb 000001
上傳檔案：osscmd put 1.txt oss://000001/
下載檔案：osscmd get oss://000001/1.txt 1.txt

其他型別的Linux主機可以使用SCP命令，參考：Linux scp命令

3. 分析工具

通過dump檔案來分析fullGC的原因，需要關注哪些類佔用記憶體空間較多、不可到達類等。
由於使用的是公司內部工具Zprofiler和grace，詳細的使用過程這裡就不截圖了。一些其他可用的工具和命令(參考Java記憶體洩漏分析系列之六：JVM Heap Dump（堆轉儲檔案）的生成和MAT的使用):

jhat, JDK自帶，使用jhat <heap-dump-file>生成網頁，通過瀏覽器訪問``檢視
jvisualvm
Eclipse Memory Analyzer(MAT)
IBM Heap Analyzer

需要注意的是，只看dump檔案有時還不能得到結論，因為佔用空間大頭的有可能是String、ArrayBlockingList這樣的物件，而且內容可能是null或null物件的集合，無從排查。此時還要結合發生fullgc前後業務系統發生了什麼動作來確定。如果有條件的話可以在日常環境或預發環境重現一下。
當然，如果記憶體中的空間消耗物件是特殊的類，就比較好排查了。

4. 分析和改進

具體情況具體分析。

4.1 本次排查的場景

查詢DB中資料->在非同步執行緒中通過poi轉換成Excel->上傳到OSS。

示例程式碼：

// 匯出程式碼中將變數直接作為lambda表示式的值傳入
List<XXData>  data = queryData(request);
SheetDownloadProperty property = sheetDownloadProperties.get(0);
property.setTotalCount(request.getQueryRequest().getPageSize());
property.setPageSize(request.getQueryRequest().getPageSize());
property.setQueryFunction((currentPage, pageSize) ->  data);
// 該元件會線上程池非同步呼叫poi元件轉換為excel、上傳OSS、下載
asyncDownloadService.downloadFile(downloadTask);

private List<XXData> queryData(ExportRequest request) {
    //查詢DB，略
}

// 查詢方法
@FunctionalInterface
public interface PageFunction<T> {

    /**
     * 方法執行
     */
    List<T> apply(Integer currentPage,Integer pageSize);
}

4.2 dump檔案分析

通過內部工具可見，fullGC前有三個佔據記憶體較高的ArrayBlockingList，裡面有大量的內容為null的Object。

這三個ArrayBlockingList所屬的中介軟體，雖然本身和業務流程沒有關係，但是仍不能排除嫌疑。

4.3 嘗試解決

4.3.1 方案1：poi相關解決方案

由於依賴了二方庫poi，這個庫的usermodel模式很容易引起fullGC，同時也懷疑是因為lambda表示式直接傳了變數。
把poi的usermodel改為事件模式（https://my.oschina.net/OutOfMemory/blog/1068972）可以避免這個問題。
但是該功能是一個二次封裝的三方包中的，同時其他引用該元件的應用fullgc頻率並不高，沒有采用這個方案。

4.3.2 方案2：中介軟體升級

持有大量null物件的中介軟體版本較低，且新版目前已不再維護，老版本的releas note雖然沒有提到這條bug fix，有一定嫌疑。
該中介軟體初始化時會建立三個容量為810241024的ArrayBlockingList，和dump檔案相符合。
同樣是因為這個中介軟體是在三方包中封裝，不方便直接該版本，同樣沒有采用這個方案。

4.3.3 方案3：增大堆大小

可以調整metaspace引數來實現，本次想找到程式碼中相關的線索來解決，未採用該方案。

4.3.4 方案4：業務程式碼修改

仔細觀察了這段程式碼在其他系統的的實現，發現其他系統的lambda表示式是匿名方法，而不是直接傳值，即：

property.setQueryFunction((currentPage, pageSize) ->  {
    // 查詢邏輯, 略
);

懷疑是直接傳變數進去導致的垃圾回收問題。更改到這種模式後，觸發下載功能時，連續長時間的fullGC仍然時有發生，沒有解決問題。

4.3.5 方案5：替換垃圾回收器

暫時能確定的原因是，公司中介軟體本身佔用堆記憶體較多，執行poi增加了GC的頻率。但是由於它們都在二方庫的原因，不方便修改。
此時搜尋到stackoverflow有關於poi反覆GC的一個問題，和我的情況類似，也是反覆GC但是仍然不能釋放記憶體。有回覆建議將GC回收器替換為G1GC，將預設的UseConcMarkSweepGC替換後效果明顯，一次FullGC就可以完成回收釋放，不會反覆FullGC，如下圖，20:30前的fullGC是CMS，持續時間長且反覆進行；20:30後是替換後第一次觸發excel轉換下載，進行了多次下載，即使發生FullGC也只有1次，大大緩解了之前的問題：

本次暫定只採用方案5。

G1GC在JDK9已替代CMS成為了正式的垃圾回收器，低版本JDK需要手動設定。具體需要設定的JVM引數：

-Xms32m
-Xmx1g
-XX:+UnlockExperimentalVMOptions
-XX:+UseG1GC 
-XX:MaxHeapFreeRatio=15 
-XX:MinHeapFreeRatio=5

注意前兩行一般應用都會設定，不要覆蓋掉。最後兩行需要視情況調整。另外，預設的-XX:+UseConcMarkSweepGC需要去掉。

使用G1GC時需要確認工作執行緒數是否和預期一致，不要太多，一般來說和CPU核數一致即可。出現非預期數目的原因可能是，映象指令碼指定核數時，直接按照物理機而不是虛擬機器核數來生成。
檢視方式是看gc日誌：

虛擬機器設定核數的dokcker指令碼示例：

export CPU_COUNT="$(grep -c 'cpu[0-9][0-9]*' /proc/stat)"

5. 其他

5.1 典型fullGC場景舉例

外部資源未釋放，如將利用tair實現的分散式鎖放在Map中，未做解鎖
fastjson的反序列化異常丟擲後沒有處理
框架固有缺陷，如本例apache的poi元件，使用usermodel模式做excel匯出時，當操作比較頻繁或有其他記憶體洩漏有可能造成
JVM的metaspace設定過小

5.2 core dump和heap dump

core dump是針對執行緒某一時刻的執行情況的，可以看到執行到哪個類哪個方法哪一行以及執行棧的；heap dump是針對記憶體某一時刻的分配情況的。

5.3 stackoverflow上關於poi記憶體佔用問題的討論：

簡單摘譯了一些，可以直接看原文。

Java對堆記憶體分配是懶回收的，如果JVM不想這麼做，即使執行Runtime.gc()，也可能什麼也不做。sapiensl和Amongalen的回答
觸發FullGC，並不是因為記憶體洩漏，僅僅是因為poi佔用了太多的記憶體。Michael的回答

關於G1GC，會在後續文章中研究