一次完整的JVM堆外內存泄漏故障排查記錄

本文轉載自查看原文 2020-08-27 11:30 10278 Java/ 線上問題排查

前言

記錄一次線上JVM堆外內存泄漏問題的排查過程與思路，其中夾帶一些JVM內存分配機制以及常用的JVM問題排查指令和工具分享，希望對大家有所幫助。

在整個排查過程中，我也走了不少彎路，但是在文章中我仍然會把完整的思路和想法寫出來，當做一次經驗教訓，給后人參考，文章最后也總結了下內存泄漏問題快速排查的幾個原則。

本文的主要內容：

故障描述和排查過程
故障原因和解決方案分析
JVM堆內內存和堆外內存分配原理
常用的進程內存泄漏排查指令和工具介紹和使用

文章撰寫不易，請大家多多支持我的原創技術公眾號：后端技術漫談

故障描述

8月12日中午午休時間，我們商業服務收到告警，服務進程占用容器的物理內存（16G）超過了80%的閾值，並且還在不斷上升。

監控系統調出圖表查看：

像是Java進程發生了內存泄漏，而我們堆內存的限制是4G，這種大於4G快要吃滿內存應該是JVM堆外內存泄漏。

確認了下當時服務進程的啟動配置：

-Xms4g -Xmx4g -Xmn2g -Xss1024K -XX:PermSize=256m -XX:MaxPermSize=512m -XX:ParallelGCThreads=20 -XX:+UseConcMarkSweepGC -XX:+UseParNewGC -XX:+UseCMSCompactAtFullCollection -XX:CMSInitiatingOccupancyFraction=80

雖然當天沒有上線新代碼，但是當天上午我們正在使用消息隊列推送歷史數據的修復腳本，該任務會大量調用我們服務其中的某一個接口，所以初步懷疑和該接口有關。

下圖是該調用接口當天的訪問量變化：

可以看到案發當時調用量相比正常情況（每分鍾200+次）提高了很多（每分鍾5000+次）。

我們暫時讓腳本停止發送消息，該接口調用量下降到每分鍾200+次，容器內存不再以極高斜率上升，一切似乎恢復了正常。

接下來排查這個接口是不是發生了內存泄漏。

排查過程

首先我們先回顧下Java進程的內存分配，方便我們下面排查思路的闡述。

以我們線上使用的JDK1.8版本為例。JVM內存分配網上有許多總結，我就不再進行二次創作。

JVM內存區域的划分為兩塊：堆區和非堆區。

堆區：就是我們熟知的新生代老年代。
非堆區：非堆區如圖中所示，有元數據區和直接內存。

這里需要額外注意的是：永久代（JDK8的原生去）存放JVM運行時使用的類，永久代的對象在full GC時進行垃圾收集。

復習完了JVM的內存分配，讓我們回到故障上來。

堆內存分析

雖說一開始就基本確認與堆內存無關，因為泄露的內存占用超過了堆內存限制4G，但是我們為了保險起見先看下堆內存有什么線索。

我們觀察了新生代和老年代內存占用曲線以及回收次數統計，和往常一樣沒有大問題，我們接着在事故現場的容器上dump了一份JVM堆內存的日志。

堆內存Dump

堆內存快照dump命令：

jmap -dump:live,format=b,file=xxxx.hprof pid

畫外音：你也可以使用jmap -histo:live pid直接查看堆內存存活的對象。

導出后，將Dump文件下載回本地，然后可以使用Eclipse的MAT（Memory Analyzer）或者JDK自帶的JVisualVM打開日志文件。

使用MAT打開文件如圖所示：

可以看到堆內存中，有一些nio有關的大對象，比如正在接收消息隊列消息的nioChannel，還有nio.HeapByteBuffer，但是數量不多，不能作為判斷的依據，先放着觀察下。

下一步，我開始瀏覽該接口代碼，接口內部主要邏輯是調用集團的WCS客戶端，將數據庫表中數據查表后寫入WCS，沒有其他額外邏輯

發覺沒有什么特殊邏輯后，我開始懷疑WCS客戶端封裝是否存在內存泄漏，這樣懷疑的理由是，WCS客戶端底層是由SCF客戶端封裝的，作為RPC框架，其底層通訊傳輸協議有可能會申請直接內存。

是不是我的代碼出發了WCS客戶端的Bug，導致不斷地申請直接內存的調用，最終吃滿內存。

我聯系上了WCS的值班人，將我們遇到的問題和他們描述了一下，他們回復我們，會在他們本地執行下寫入操作的壓測，看看能不能復現我們的問題。

既然等待他們的反饋還需要時間，我們就准備先自己琢磨下原因。

我將懷疑的目光停留在了直接內存上，懷疑是由於接口調用量過大，客戶端對nio使用不當，導致使用ByteBuffer申請過多的直接內存。

畫外音：最終的結果證明，這一個先入為主的思路導致排查過程走了彎路。在問題的排查過程中，用合理的猜測來縮小排查范圍是可以的，但最好先把每種可能性都列清楚，在發現自己深入某個可能性無果時，要及時回頭仔細審視其他可能性。

沙箱環境復現

為了能還原當時的故障場景，我在沙箱環境申請了一台壓測機器，來確保和線上環境一致。

首先我們先模擬內存溢出的情況（大量調用接口）：

我們讓腳本繼續推送數據，調用我們的接口，我們持續觀察內存占用。

當開始調用后，內存便開始持續增長，並且看起來沒有被限制住（沒有因為限制觸發Full GC）。

接着我們來模擬下平時正常調用量的情況（正常量調用接口）：

我們將該接口平時正常的調用量（比較小，且每10分鍾進行一次批量調用）切到該壓測機器上，得到了下圖這樣的老生代內存和物理內存趨勢：

問題來了：為何內存會不斷往上走吃滿內存呢？

當時猜測是由於JVM進程並沒有對於直接內存大小進行限制（-XX:MaxDirectMemorySize），所以堆外內存不斷上漲，並不會觸發FullGC操作。

上圖能夠得出兩個結論：

在內存泄露的接口調用量很大的時候，如果恰好堆內老生代等其他情況一直不滿足FullGC條件，就一直不會FullGC，直接內存一路上漲。
而在平時低調用量的情況下，內存泄漏的比較慢，FullGC總會到來，回收掉泄露的那部分，這也是平時沒有出問題，正常運行了很久的原因。

由於上面提到，我們進程的啟動參數中並沒有限制直接內存，於是我們將-XX:MaxDirectMemorySize配置加上，再次在沙箱環境進行了測驗。

結果發現，進程占用的物理內存依然會不斷上漲，超出了我們設置的限制，“看上去”配置似乎沒起作用。

這讓我很訝異，難道JVM對內存的限制出現了問題？

到了這里，能夠看出我排查過程中思路執着於直接內存的泄露，一去不復返了。

畫外音：我們應該相信JVM對內存的掌握，如果發現參數失效，多從自己身上找原因，看看是不是自己使用參數有誤。

直接內存分析

為了更進一步的調查清楚直接內存里有什么，我開始對直接內存下手。由於直接內存並不能像堆內存一樣，很容易的看出所有占用的對象，我們需要一些命令來對直接內存進行排查，我有用了幾種辦法，來查看直接內存里到底出現了什么問題。

查看進程內存信息 pmap

pmap - report memory map of a process(查看進程的內存映像信息)

pmap命令用於報告進程的內存映射關系，是Linux調試及運維一個很好的工具。

pmap -x pid 如果需要排序  | sort -n -k3**

執行后我得到了下面的輸出，刪減輸出如下:

..
00007fa2d4000000    8660    8660    8660 rw---   [ anon ]
00007fa65f12a000    8664    8664    8664 rw---   [ anon ]
00007fa610000000    9840    9832    9832 rw---   [ anon ]
00007fa5f75ff000   10244   10244   10244 rw---   [ anon ]
00007fa6005fe000   59400   10276   10276 rw---   [ anon ]
00007fa3f8000000   10468   10468   10468 rw---   [ anon ]
00007fa60c000000   10480   10480   10480 rw---   [ anon ]
00007fa614000000   10724   10696   10696 rw---   [ anon ]
00007fa6e1c59000   13048   11228       0 r-x-- libjvm.so
00007fa604000000   12140   12016   12016 rw---   [ anon ]
00007fa654000000   13316   13096   13096 rw---   [ anon ]
00007fa618000000   16888   16748   16748 rw---   [ anon ]
00007fa624000000   37504   18756   18756 rw---   [ anon ]
00007fa62c000000   53220   22368   22368 rw---   [ anon ]
00007fa630000000   25128   23648   23648 rw---   [ anon ]
00007fa63c000000   28044   24300   24300 rw---   [ anon ]
00007fa61c000000   42376   27348   27348 rw---   [ anon ]
00007fa628000000   29692   27388   27388 rw---   [ anon ]
00007fa640000000   28016   28016   28016 rw---   [ anon ]
00007fa620000000   28228   28216   28216 rw---   [ anon ]
00007fa634000000   36096   30024   30024 rw---   [ anon ]
00007fa638000000   65516   40128   40128 rw---   [ anon ]
00007fa478000000   46280   46240   46240 rw---   [ anon ]
0000000000f7e000   47980   47856   47856 rw---   [ anon ]
00007fa67ccf0000   52288   51264   51264 rw---   [ anon ]
00007fa6dc000000   65512   63264   63264 rw---   [ anon ]
00007fa6cd000000   71296   68916   68916 rwx--   [ anon ]
00000006c0000000 4359360 2735484 2735484 rw---   [ anon ]

可以看出，最下面一行是堆內存的映射，占用4G，其他上面有非常多小的內存占用，不過通過這些信息我們依然看不出問題。

堆外內存跟蹤 NativeMemoryTracking

Native Memory Tracking (NMT) 是Hotspot VM用來分析VM內部內存使用情況的一個功能。我們可以利用jcmd（jdk自帶）這個工具來訪問NMT的數據。

NMT必須先通過VM啟動參數中打開，不過要注意的是，打開NMT會帶來5%-10%的性能損耗。

-XX:NativeMemoryTracking=[off | summary | detail]
# off: 默認關閉
# summary: 只統計各個分類的內存使用情況.
# detail: Collect memory usage by individual call sites.

然后運行進程，可以使用下面的命令查看直接內存：

jcmd <pid> VM.native_memory [summary | detail | baseline | summary.diff | detail.diff | shutdown] [scale= KB | MB | GB]
 
# summary: 分類內存使用情況.
# detail: 詳細內存使用情況，除了summary信息之外還包含了虛擬內存使用情況。
# baseline: 創建內存使用快照，方便和后面做對比
# summary.diff: 和上一次baseline的summary對比
# detail.diff: 和上一次baseline的detail對比
# shutdown: 關閉NMT

我們使用：

jcmd pid VM.native_memory detail scale=MB > temp.txt

得到如圖結果：

上圖中給我們的信息，都不能很明顯的看出問題，至少我當時依然不能通過這幾次信息看出問題。

排查似乎陷入了僵局。

山重水復疑無路

在排查陷入停滯的時候，我們得到了來自WCS和SCF方面的回復，兩方都確定了他們的封裝沒有內存泄漏的存在，WCS方面沒有使用直接內存，而SCF雖然作為底層RPC協議，但是也不會遺留這么明顯的內存bug，否則應該線上有很多反饋。

查看JVM內存信息 jmap

此時，找不到問題的我再次新開了一個沙箱容器，運行服務進程，然后運行jmap命令，看一看JVM內存的實際配置：

jmap -heap pid

得到結果：

Attaching to process ID 1474, please wait...
Debugger attached successfully.
Server compiler detected.
JVM version is 25.66-b17

using parallel threads in the new generation.
using thread-local object allocation.
Concurrent Mark-Sweep GC

Heap Configuration:
   MinHeapFreeRatio         = 40
   MaxHeapFreeRatio         = 70
   MaxHeapSize              = 4294967296 (4096.0MB)
   NewSize                  = 2147483648 (2048.0MB)
   MaxNewSize               = 2147483648 (2048.0MB)
   OldSize                  = 2147483648 (2048.0MB)
   NewRatio                 = 2
   SurvivorRatio            = 8
   MetaspaceSize            = 21807104 (20.796875MB)
   CompressedClassSpaceSize = 1073741824 (1024.0MB)
   MaxMetaspaceSize         = 17592186044415 MB
   G1HeapRegionSize         = 0 (0.0MB)

Heap Usage:
New Generation (Eden + 1 Survivor Space):
   capacity = 1932787712 (1843.25MB)
   used     = 1698208480 (1619.5378112792969MB)
   free     = 234579232 (223.71218872070312MB)
   87.86316621615607% used
Eden Space:
   capacity = 1718091776 (1638.5MB)
   used     = 1690833680 (1612.504653930664MB)
   free     = 27258096 (25.995346069335938MB)
   98.41346682518548% used
From Space:
   capacity = 214695936 (204.75MB)
   used     = 7374800 (7.0331573486328125MB)
   free     = 207321136 (197.7168426513672MB)
   3.4349974840697497% used
To Space:
   capacity = 214695936 (204.75MB)
   used     = 0 (0.0MB)
   free     = 214695936 (204.75MB)
   0.0% used
concurrent mark-sweep generation:
   capacity = 2147483648 (2048.0MB)
   used     = 322602776 (307.6579818725586MB)
   free     = 1824880872 (1740.3420181274414MB)
   15.022362396121025% used

29425 interned Strings occupying 3202824 bytes

輸出的信息中，看得出老年代和新生代都蠻正常的，元空間也只占用了20M，直接內存看起來也是2g...

嗯？為什么MaxMetaspaceSize = 17592186044415 MB？看起來就和沒限制一樣。

再仔細看看我們的啟動參數：

-Xms4g -Xmx4g -Xmn2g -Xss1024K -XX:PermSize=256m -XX:MaxPermSize=512m -XX:ParallelGCThreads=20 -XX:+UseConcMarkSweepGC -XX:+UseParNewGC -XX:+UseCMSCompactAtFullCollection -XX:CMSInitiatingOccupancyFraction=80

配置的是-XX:PermSize=256m -XX:MaxPermSize=512m，也就是永久代的內存空間。而1.8后，Hotspot虛擬機已經移除了永久代，使用了元空間代替。 由於我們線上使用的是JDK1.8，所以我們對於元空間的最大容量根本就沒有做限制，-XX:PermSize=256m -XX:MaxPermSize=512m 這兩個參數對於1.8就是過期的參數。

下面的圖描述了從1.7到1.8，永久代的變更：

那會不會是元空間內存泄露了呢？

我選擇了在本地進行測試，方便更改參數，也方便使用JVisualVM工具直觀的看出內存變化。

使用JVisualVM觀察進程運行

首先限制住元空間，使用參數-XX:MetaspaceSize=64m -XX:MaxMetaspaceSize=128m，然后在本地循環調用出問題的接口。

得到如圖：

可以看出，在元空間耗盡時，系統出發了Full GC，元空間內存得到回收，並且卸載了很多類。

然后我們將元空間限制去掉，也就是使用之前出問題的參數：

-Xms4g -Xmx4g -Xmn2g -Xss1024K -XX:ParallelGCThreads=20 -XX:+UseConcMarkSweepGC -XX:+UseParNewGC -XX:+UseCMSCompactAtFullCollection -XX:CMSInitiatingOccupancyFraction=80 -XX:MaxDirectMemorySize=2g -XX:+UnlockDiagnosticVMOptions

得到如圖：

可以看出，元空間在不斷上漲，並且已裝入的類隨着調用量的增加也在不斷上漲，呈現正相關趨勢。

柳暗花明又一村

問題一下子明朗了起來，隨着每次接口的調用，極有可能是某個類都在不斷的被創建，占用了元空間的內存。

觀察JVM類加載情況 -verbose

在調試程序時，有時需要查看程序加載的類、內存回收情況、調用的本地接口等。這時候就需要-verbose命令。在myeclipse可以通過右鍵設置（如下），也可以在命令行輸入java -verbose來查看。

-verbose:class 查看類加載情況
-verbose:gc 查看虛擬機中內存回收情況
-verbose:jni 查看本地方法調用的情況

我們在本地環境，添加啟動參數-verbose:class循環調用接口。

可以看到生成了無數com.alibaba.fastjson.serializer.ASMSerializer_1_WlkCustomerDto:

[Loaded com.alibaba.fastjson.serializer.ASMSerializer_1_WlkCustomerDto from file:/C:/Users/yangzhendong01/.m2/repository/com/alibaba/fastjson/1.2.71/fastjson-1.2.71.jar]
[Loaded com.alibaba.fastjson.serializer.ASMSerializer_1_WlkCustomerDto from file:/C:/Users/yangzhendong01/.m2/repository/com/alibaba/fastjson/1.2.71/fastjson-1.2.71.jar]
[Loaded com.alibaba.fastjson.serializer.ASMSerializer_1_WlkCustomerDto from file:/C:/Users/yangzhendong01/.m2/repository/com/alibaba/fastjson/1.2.71/fastjson-1.2.71.jar]
[Loaded com.alibaba.fastjson.serializer.ASMSerializer_1_WlkCustomerDto from file:/C:/Users/yangzhendong01/.m2/repository/com/alibaba/fastjson/1.2.71/fastjson-1.2.71.jar]
[Loaded com.alibaba.fastjson.serializer.ASMSerializer_1_WlkCustomerDto from file:/C:/Users/yangzhendong01/.m2/repository/com/alibaba/fastjson/1.2.71/fastjson-1.2.71.jar]
[Loaded com.alibaba.fastjson.serializer.ASMSerializer_1_WlkCustomerDto from file:/C:/Users/yangzhendong01/.m2/repository/com/alibaba/fastjson/1.2.71/fastjson-1.2.71.jar]

當調用了很多次，積攢了一定的類時，我們手動執行Full GC，進行類加載器的回收，我們發現大量的fastjson相關類被回收。

如果在回收前，使用jmap查看類加載情況，同樣也可以發現大量的fastjson相關類：

jmap -clstats 7984

這下有了方向，這次仔細排查代碼，查看代碼邏輯里哪里用到了fastjson，發現了如下代碼：

/**
 * 返回Json字符串.駝峰轉_
 * @param bean 實體類.
 */
public static String buildData(Object bean) {
    try {
        SerializeConfig CONFIG = new SerializeConfig();
        CONFIG.propertyNamingStrategy = PropertyNamingStrategy.SnakeCase;
        return jsonString = JSON.toJSONString(bean, CONFIG);
    } catch (Exception e) {
        return null;
    }
}

問題根因

我們在調用wcs前將駝峰字段的實體類序列化成下划線字段，**這需要使用fastjson的SerializeConfig，而我們在靜態方法中對其進行了實例化。SerializeConfig創建時默認會創建一個ASM代理類用來實現對目標對象的序列化。也就是上面被頻繁創建的類com.alibaba.fastjson.serializer.ASMSerializer_1_WlkCustomerDto,如果我們復用SerializeConfig，fastjson會去尋找已經創建的代理類，從而復用。但是如果new SerializeConfig()，則找不到原來生成的代理類，就會一直去生成新的WlkCustomerDto代理類。

下面兩張圖時問題定位的源碼：

我們將SerializeConfig作為類的靜態變量，問題得到了解決。

private static final SerializeConfig CONFIG = new SerializeConfig();

static {
    CONFIG.propertyNamingStrategy = PropertyNamingStrategy.SnakeCase;
}

fastjson SerializeConfig 做了什么

SerializeConfig介紹：

SerializeConfig的主要功能是配置並記錄每種Java類型對應的序列化類（ObjectSerializer接口的實現類），比如Boolean.class使用BooleanCodec（看命名就知道該類將序列化和反序列化實現寫到一起了）作為序列化實現類，float[].class使用FloatArraySerializer作為序列化實現類。這些序列化實現類，有的是FastJSON中默認實現的（比如Java基本類），有的是通過ASM框架生成的（比如用戶自定義類），有的甚至是用戶自定義的序列化類（比如Date類型框架默認實現是轉為毫秒，應用需要轉為秒）。當然，這就涉及到是使用ASM生成序列化類還是使用JavaBean的序列化類類序列化的問題，這里判斷根據就是是否Android環境（環境變量"java.vm.name"為"dalvik"或"lemur"就是Android環境），但判斷不僅這里一處，后續還有更具體的判斷。

理論上來說，每個SerializeConfig實例若序列化相同的類，都會找到之前生成的該類的代理類，來進行序列化。們的服務在每次接口被調用時，都實例化一個ParseConfig對象來配置Fastjson反序列的設置，而未禁用ASM代理的情況下，由於每次調用ParseConfig都是一個新的實例，因此永遠也檢查不到已經創建的代理類，所以Fastjson便不斷的創建新的代理類，並加載到metaspace中，最終導致metaspace不斷擴張，將機器的內存耗盡。

升級JDK1.8才會出現問題

導致問題發生的原因還是值得重視。為什么在升級之前不會出現這個問題？這就要分析jdk1.8和1.7自帶的hotspot虛擬機的差異了。

從jdk1.8開始，自帶的hostspot虛擬機取消了過去的永久區，而新增了metaspace區，從功能上看，metaspace可以認為和永久區類似，其最主要的功用也是存放類元數據，但實際的機制則有較大的不同。

首先，metaspace默認的最大值是整個機器的物理內存大小，所以metaspace不斷擴張會導致java程序侵占系統可用內存，最終系統沒有可用的內存；而永久區則有固定的默認大小，不會擴張到整個機器的可用內存。當分配的內存耗盡時，兩者均會觸發full gc，但不同的是永久區在full gc時，以堆內存回收時類似的機制去回收永久區中的類元數據（Class對象），只要是根引用無法到達的對象就可以回收掉，而metaspace判斷類元數據是否可以回收，是根據加載這些類元數據的Classloader是否可以回收來判斷的，只要Classloader不能回收，通過其加載的類元數據就不會被回收。這也就解釋了我們這兩個服務為什么在升級到1.8之后才出現問題，因為在之前的jdk版本中，雖然每次調用fastjson都創建了很多代理類，在永久區中加載類很多代理類的Class實例，但這些Class實例都是在方法調用是創建的，調用完成之后就不可達了，因此永久區內存滿了觸發full gc時，都會被回收掉。

而使用1.8時，因為這些代理類都是通過主線程的Classloader加載的，這個Classloader在程序運行的過程中永遠也不會被回收，因此通過其加載的這些代理類也永遠不會被回收，這就導致metaspace不斷擴張，最終耗盡機器的內存了。

這個問題並不局限於fastjson，只要是需要通過程序加載創建類的地方，就有可能出現這種問題。尤其是在框架中，往往大量采用類似ASM、javassist等工具進行字節碼增強，而根據上面的分析，在jdk1.8之前，因為大多數情況下動態加載的Class都能夠在full gc時得到回收，因此不容易出現問題，也因此很多框架、工具包並沒有針對這個問題做一些處理，一旦升級到1.8之后，這些問題就可能會暴露出來。

總結

問題解決了，接下來復盤下整個排查問題的流程，整個流程暴露了我很多問題，最主要的就是對於JVM不同版本的內存分配還不夠熟悉，導致了對於老生代和元空間判斷失誤，走了很多彎路，在直接內存中排查了很久，浪費了很多時間。

其次，排查需要的一是仔細，二是全面，，最好將所有可能性先行整理好，不然很容易陷入自己設定好的排查范圍內，走進死胡同不出來。

最后，總結一下這次的問題帶來的收獲：

JDK1.8開始，自帶的hostspot虛擬機取消了過去的永久區，而新增了metaspace區，從功能上看，metaspace可以認為和永久區類似，其最主要的功用也是存放類元數據，但實際的機制則有較大的不同。
對於JVM里面的內存需要在啟動時進行限制，包括我們熟悉的堆內存，也要包括直接內存和元生區，這是保證線上服務正常運行最后的兜底。
使用類庫，請多注意代碼的寫法，盡量不要出現明顯的內存泄漏。
對於使用了ASM等字節碼增強工具的類庫，在使用他們時請多加小心（尤其是JDK1.8以后）。