## 前言 記錄一次線上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記憶體分配網上有許多[總結](https://www.cnblogs.com/duanxz/p/3520829.html)，我就不再進行二次創作。 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