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

時間 2020-08-29

標籤一次完整 jvm 內存泄漏故障排查記錄欄目 Java 简体版

原文原文鏈接

前言

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

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

本文的主要內容：git

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

文章撰寫不易，請你們多多支持個人原創技術公衆號：後端技術漫談github

故障描述

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

監控系統調出圖表查看：算法

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

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

-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之後）。