JVM堆外內(nèi)存泄漏故障排查的示例分析

直接內(nèi)存分析

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

查看進程內(nèi)存信息 pmap

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

pmap命令用于報告進程的內(nèi)存映射關系，是Linux調(diào)試及運維一個很好的工具。

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

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

..
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 ]

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

堆外內(nèi)存跟蹤 NativeMemoryTracking

?  

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

?  

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

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

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

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

我們使用：

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

得到如圖結(jié)果：

 

 

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

排查似乎陷入了僵局。

山重水復疑無路

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

查看JVM內(nèi)存信息 jmap

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

jmap -heap pid

得到結(jié)果：

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，直接內(nèi)存看起來也是2g...

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

再仔細看看我們的啟動參數(shù)：

-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，也就是永久代的內(nèi)存空間。「而1.8后，Hotspot虛擬機已經(jīng)移除了永久代，使用了元空間代替?！?/strong> 由于我們線上使用的是JDK1.8，「所以我們對于元空間的最大容量根本就沒有做限制」，-XX:PermSize=256m -XX:MaxPermSize=512m 這兩個參數(shù)對于1.8就是過期的參數(shù)。

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

 

「那會不會是元空間內(nèi)存泄露了呢？」

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

 

使用JVisualVM觀察進程運行

首先限制住元空間，使用參數(shù)-XX:MetaspaceSize=64m -XX:MaxMetaspaceSize=128m，然后在本地循環(huán)調(diào)用出問題的接口。

得到如圖：

 

「可以看出，在元空間耗盡時，系統(tǒng)出發(fā)了Full GC，元空間內(nèi)存得到回收，并且卸載了很多類。」

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

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

 

得到如圖：

 

「可以看出，元空間在不斷上漲，并且已裝入的類隨著調(diào)用量的增加也在不斷上漲，呈現(xiàn)正相關趨勢?！?/strong>

 

柳暗花明又一村

問題一下子明朗了起來，「隨著每次接口的調(diào)用，極有可能是某個類都在不斷的被創(chuàng)建，占用了元空間的內(nèi)存」。

 

觀察JVM類加載情況 -verbose

?  

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

?  

-verbose:class 查看類加載情況
-verbose:gc 查看虛擬機中內(nèi)存回收情況
-verbose:jni 查看本地方法調(diào)用的情況

 

我們在本地環(huán)境，添加啟動參數(shù)-verbose:class循環(huán)調(diào)用接口。

可以看到生成了無數(shù)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]

 

當調(diào)用了很多次，積攢了一定的類時，我們手動執(zhí)行Full GC，進行類加載器的回收，我們發(fā)現(xiàn)大量的fastjson相關類被回收。

 

「如果在回收前，使用jmap查看類加載情況，同樣也可以發(fā)現(xiàn)大量的fastjson相關類：」

jmap -clstats 7984

 

 

這下有了方向，「這次仔細排查代碼」，查看代碼邏輯里哪里用到了fastjson，發(fā)現(xiàn)了如下代碼：

/**
 * 返回Json字符串.駝峰轉(zhuǎn)_
 * @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;
    }
}

   

問題根因

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

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

 

 

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

private static final SerializeConfig CONFIG = new SerializeConfig();

static {
    CONFIG.propertyNamingStrategy = PropertyNamingStrategy.SnakeCase;
}

   

fastjson SerializeConfig 做了什么

SerializeConfig介紹：

?  

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

?  

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

 

升級JDK1.8才會出現(xiàn)問題

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

?  

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

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

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

?  

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

 

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

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

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

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