轉載自??一次堆外內存泄露的排查過程

最近在做一個基于 websocket 的長連中間件，服務端使用實現(xiàn)了 socket.io 協(xié)議（基于websocket協(xié)議，提供長輪詢降級能力） 的 netty-socketio 框架，該框架為 netty 實現(xiàn)，鑒于本人對 netty 比較熟，并且對比同樣實現(xiàn)了 socket.io 協(xié)議的其他框架，這個框架的口碑要更好一些，因此選擇這個框架作為底層核心。

任何開源框架都避免不了 bug 的存在，我們在使用這個開源框架的時候，就遇到一個堆外內存泄露的 bug，鑒于對 netty 比較熟，于是接下來便想挑戰(zhàn)一下，找出那只臭蟲（bug），接下來便是現(xiàn)象和排查過程，想看結論的同學可以直接拉到最后總結。

現(xiàn)象

某天早上突然收到告警，nginx 服務端大量5xx

?

我們使用 nginx 作為服務端 websocket 的七層負載，5xx爆發(fā)通常表明服務端不可用。由于目前 nginx 告警沒有細分具體哪臺機器不可用，接下來，到 cat（點評美團統(tǒng)一監(jiān)控平臺）去檢查一下整個集群的各項指標，發(fā)現(xiàn)如下兩個異常

?

某臺機器在同一時間點爆發(fā) gc，同一時間，jvm 線程阻塞

?

接下來，便開始漫長的 堆外內存泄露排查之旅行。

排查過程

階段1: 懷疑是log4j2

線程被大量阻塞，首先想到的是定位哪些線程被阻塞，最后查出來是 log4j2 狂打日志導致 netty 的 nio 線程阻塞（由于沒有及時保留現(xiàn)場，所以截圖缺失），nio 線程阻塞之后，我們的服務器無法處理客戶端的請求，對nginx來說是5xx。

接下來，查看 log4j2 的配置文件

?

發(fā)現(xiàn)打印到控制臺的這個 appender 忘記注釋掉了，所以我初步猜測是因為這個項目打印的日志過多，而 log4j2 打印到控制臺是同步阻塞打印的，接下來，把線上所有機器的這行注釋掉，以為大功告成，沒想到，過不了幾天，5xx告警又來敲門了，看來，這個問題沒那么簡單。

階段2：可疑日志浮現(xiàn)

接下來，只能硬著頭皮去查日志，查看故障發(fā)生點前后的日志，發(fā)現(xiàn)了一處可疑的地方

?

在極短的時間內，狂打 failed to allocate64(bytes)of direct memory(...)日志（瞬間十幾個日志文件，每個日志文件幾百M），日志里拋出一個 netty 自己封裝的 OutOfDirectMemoryError，說白了，就是堆外內存不夠用了，netty 一直在喊冤。

堆外內存泄露，我去，聽到這個名詞就有點沮喪，因為這個問題的排查就像 c 語言內存泄露一樣難以排查，首先想到的是，在 OOM 爆發(fā)之前，查看有無異常，然后查遍了 cat 上與機器相關的所有指標，查遍了 OOM 日志之前的所有日志，均未發(fā)現(xiàn)任何異常！這個時候心里開始罵了……

階段3：定位OOM源

但是沒辦法，只能看著這堆討厭的 OOM 日志發(fā)著呆，妄圖答案能夠蹦到眼前。一籌莫展之際，突然一道光在眼前一閃而過，在 OOM 下方的幾行日志變得耀眼起來（為啥之前就沒想認真查看日志？估計是被堆外內存泄露這幾個詞嚇怕了吧==），這幾行字是 ....PlatformDepedeng.incrementMemory()...。我去，原來，堆外內存是否夠用，是 netty 這邊自己統(tǒng)計的，那是不是可以找到統(tǒng)計代碼，找到統(tǒng)計代碼之后我們就可以看到 netty 里面的對外內存統(tǒng)計邏輯了？于是，接下來翻翻代碼，找到這段邏輯，在 PlatformDepedent 這個類里面

?

這個地方，是一個對已使用堆外內存計數(shù)的操作，計數(shù)器為 DIRECT_MEMORY_COUNTER，如果發(fā)現(xiàn)已使用內存大于堆外內存的上限（用戶自行指定），就拋出一個自定義 OOM Error，異常里面的文本內容正是我們在日志里面看到的。

接下來，驗證一下是否這個函數(shù)是在堆外內存分配的時候被調用

?

果然，在 netty 每次分配堆外內存之前，都會計數(shù)，想到這，思路開始慢慢清晰起來，心情也開始變好。

階段4：反射進行堆外內存監(jiān)控

既然 cat 上關于堆外內存的監(jiān)控沒有任何異常（應該是沒有統(tǒng)計準確，一直維持在 1M），而這邊我們又確認堆外內存已快超過上限，并且已經知道 netty 底層是使用哪個字段來統(tǒng)計的，那么接下來要做的第一件事情，就是反射拿到這個字段，然后我們自己統(tǒng)計 netty 使用堆外內存的情況。

?

堆外內存統(tǒng)計字段是 DIRECT_MEMORY_COUNTER，我們可以通過反射拿到這個字段，然后定期check這個值，就可以監(jiān)控 netty 堆外內存的增長情況。

?

我們通過反射拿到這個字段，然后每隔一秒打印，我為什么要這樣做？

因為，通過我們前面的分析，在爆發(fā)大量 OOM 現(xiàn)象之前，沒有任何可疑的現(xiàn)象，那么只有兩種情況，一種是突然某個瞬間分配了大量的堆外內存導致OOM，一種是堆外內存緩慢增長，到達某個點之后，最后一根稻草將機器壓垮。這段代碼加上去之后，打包上線。

階段5：到底是緩慢增長還是瞬間飆升？

代碼上線之后，初始內存為 16384k（16M），這是因為線上我們使用了池化堆外內存，默認一個 chunk 為16M，不必過于糾結。

?

沒過一會，內存就開始緩慢飆升，并且沒有釋放的跡象，20幾分鐘之后，內存如下

?

到了這里，猜測可能是前面提到的第二種情況，也就是內存緩慢增長造成的 OOM，由于內存實在增長太慢，于是調整機器負載權重為其他機器的兩倍，但是仍然是以幾K級別在增長，這天剛好是周五，索性就過他個一個周末再開看。

過完一個愉快的周末之后，到公司第一時間便是連上跳板機，登錄線上機器，開始 tail -f 繼續(xù)查看日志，輸完命令之后，懷著期待的心情重重的敲下了回車鍵

?

果然不出所料，內存一直在緩慢增長，一個周末的時間，堆外內存已經飆到快一個 G 了，這個時候，我竟然想到了一句成語：只要功夫深，鐵杵磨成針！雖然堆外內存幾個K幾個K的在增長，但是只要一直持續(xù)下去，總有把內存打爆的時候（線上堆外內存上限設置的是2G）。

到了這里，我又開始自問自答了：內存為啥會緩慢增長，伴隨著什么而增長？因為我們的應用是面向用戶端的websocket，那么，會不會是每一次有用戶進來，交互完之后，然后離開，內存都會增長一些，然后不釋放呢？帶著這個疑問，我開始線下模擬。

階段6：線下模擬

本地起好服務，把監(jiān)控堆外內存的單位改為以B為單位（因為本地流量較小，打算一次一個客戶端連接），另外，本地也使用非池化內存（內存數(shù)字較小，容易看出問題），這樣，服務端啟動之后，控制臺打印信息如下

?

在沒有客戶端接入的時候，堆外內存一直是0，在意料之中。接下來，懷著著無比激動的心情，打開瀏覽器，然后輸入網(wǎng)址，開始我們的模擬之旅。

我們的模擬流程是：新建一個客戶端鏈接->斷開鏈接->再新建一個客戶端鏈接->再斷開鏈接

?

如上圖所示，一次 connect 和 disconnect 為一次連接的建立與關閉，上圖綠色框框的日志分別是兩次連接的生命周期。我們可以看到，內存每次都是在連接被關閉的的時候暴漲 256B 然后不釋放，到了這里，問題進一步縮小，肯定是連接被關閉的時候，觸發(fā)了框架的一個bug，這個bug在觸發(fā)之前分配了 256B 的內存，然后bug觸發(fā)，內存沒有釋放。問題縮小之后，接下來開始擼源碼捉蟲！

階段7：線下排查

接下來，我將本地服務重啟，開始完整的線下排查過程。將目光定位到 netty-socketio 這個框架的 disconnect 事件（客戶端websocket連接關閉的時候回調用到這里），基本上可以確定是在 disconnect 事件前后申請的內存沒有釋放

?

這里，在使用 idea debug的時候，要選擇只掛起當前線程，這樣我們在單步跟蹤的時候，控制臺仍然可以看到堆外內存統(tǒng)計線程在打印日志。

客戶端連接上之后然后關閉，斷點進入到 onDisconnect 回調，我特意在此多停留了一會，發(fā)現(xiàn)控制臺內存并沒有飆升（7B這個內存暫時沒有去分析，只需要知道，客戶端連接斷開之后，我們斷點hold住，內存還未開始漲），接下來，神奇的一幕出現(xiàn)了，我將斷點放開，讓程序跑完

?

debug 松掉之后，內存立馬飆升了！！這個時候我已經知道，這只臭蟲飛不了多遠了。在 debug 的時候，掛起的是當前線程，那么肯定是當前線程某個地方申請了堆外內存，然后沒有釋放，接下來，快馬加鞭，深入源碼。

每一次單步調試，我都會觀察控制臺的內存飆升的情況，很快，我們來到了這個地方

?

在這一行沒執(zhí)行之前，控制臺的內存依然是 263B，然后，當執(zhí)行完這一行之后，立馬從 263B漲到519B（漲了256B）

?

于是，bug的范圍進一步縮小，我將本次程序跑完，釋然后客戶端再來一次連接，斷點打在 client.send()這行， 然后關閉客戶端連接，之后直接進入到這個方法，隨后的過程有點長，因為與 netty 的時間傳播機制有關，這里就省略了，最后，我跟到了如下代碼， handleWebsocket

?

在這個地方，我看了一處非常可疑的地方，在上圖的斷點上一行，調用 encoder 分配了一段內存，調用完之后，我們的控制臺立馬就彪了 256B，所以，我懷疑肯定是這里申請的內存沒有釋放，他這里接下來調用 encoder.encodePacket() 方法，猜想是把數(shù)據(jù)包的內容以二進制的方式寫到這段 256B的內存，接下來，我跟到這段 encode 代碼，單步執(zhí)行之后，定位到這行代碼

?

這段代碼是把 packet 里面一個字段的值轉換為一個 char，然而，當我使用 idea 預執(zhí)行的時候，卻拋出類一個憤怒的 NPE！！也就是說，框架申請到一段內存之后，在encoder的時候，自己GG了，自己給自己挖了個NPE的深坑，最后導致內存無法釋放（最外層有堆外內存釋放邏輯，現(xiàn)在無法執(zhí)行到了），然后越攢越多，越攢越多，直到最后一根稻草，堆外內存就這樣爆了，這里的源碼有興趣的讀者可以自己去分析一下，限于篇幅原因，這里就不再分析了。

階段8：bug解決

bug既然已經找到，接下來便要解決了，這里只需要解決這個NPE異常，就可以fix掉，我們的目標就是，讓這個 subType 字段不為空，我們先通過 idea 的線程調用棧定位到這個 packet 是在哪個地方定義的

?

我們找到 idea 的 debugger 面板，眼睛盯著 packet 這個對象不放，然后上線移動光標，便光速定位到，原來，定義 packet 對象這個地方在我們前面的代碼其實已經出現(xiàn)過，我們查看了一下 subType 這個字段，果然是null，接下來，解決bug很容易。

?

我們給這個字段賦值即可，由于這里是連接關閉事件，所以，我給他指定了一個名為 DISCONNECT 的字段（改日深入去研究socket.io的協(xié)議），反正這個bug是在連接關閉的時候觸發(fā)的，就粗暴一點了 ！==。

解決這個bug的過程是：將這個框架的源碼下載到本地，然后加上這一行，最后，我重新build一下，pom 里改改名字，推送到我們公司的倉庫，這樣，我項目就可以直接使用了。

改完bug之后，習慣性地去github上找到引發(fā)這段bug的commit

好奇的是，為啥這位 dzn commiter 會寫出這么一段如此明顯的bug，而且時間就在今年3月30號，項目啟動的前夕，真是無比尷尬呀 ?

階段9：線下驗證

一切就緒之后，首先，我們來進行本地驗證，服務起起來之后，我瘋狂地建立連接，瘋狂地斷開連接，觀察堆外內存的情況

?

好家伙，不管你如何斷開連接，堆外內存一直不漲了，至此，bug 基本fix，當然，最后一步，我們把代碼推到線上驗證。

階段10：線上驗證

這次線上驗證，我們避免了比較土的打日志方法，我們把堆外內存的這個指標噴射到 cat上，然后再來觀察一段時間的堆外內存的情況

?

發(fā)現(xiàn)過一段時間，堆外內存已經穩(wěn)定不漲了，我們的捉蟲之旅到此結束！最后，我來給本次捉蟲之旅做一次總結

總結

1.遇到堆外內存泄露不要怕，仔細耐心分析，總能找到思路，要多看日志，多分析。

2.如果使用了netty 堆外內存，那么你可以自行監(jiān)控堆外內存的使用情況，不需要借助第三方工具，我這里是使用的反射拿到的堆外內存的情況。

3.逐漸縮小范圍，直到bug被你找到。當你確認某個線程的執(zhí)行帶來 bug 的時候，可單步執(zhí)行，可二分執(zhí)行，定位到某行代碼之后，跟到這段代碼，然后繼續(xù)單步執(zhí)行或者二分的方式來定位最終出 bug 的代碼，這個方法屢試不爽，最后總能找到bug。

4.熟練掌握 idea 的調試，讓你的捉蟲速度快如閃電，這里，最常見的調試方式是預執(zhí)行表達式，以及通過線程調用棧，死盯某個對象，就能夠掌握這個對象的定義，賦值之類。

總結

以上是生活随笔為你收集整理的一次堆外内存泄露的排查过程的全部內容，希望文章能夠幫你解決所遇到的問題。

如果覺得生活随笔網(wǎng)站內容還不錯，歡迎將生活随笔推薦給好友。