netty 堆外內存泄露排查盛宴

這篇文章對於排查使用了 netty 引起的堆外內存泄露問題，有必定的通用性，但願對你有所啓發

背景

最近在作一個基於 websocket 的長連中間件，服務端使用實現了 socket.io 協議（基於websocket協議，提供長輪詢降級能力） 的 netty-socketio 框架，該框架爲 netty 實現，鑑於本人對 netty 比較熟，而且對比一樣實現了 socket.io 協議的其餘框架，這個框架的口碑要更好一些，所以選擇這個框架做爲底層核心。

任何開源框架都避免不了 bug 的存在，咱們在使用這個開源框架的時候，就遇到一個堆外內存泄露的 bug，鑑於對 netty 比較熟，因而接下來便想挑戰一下，找出那隻臭蟲（bug），接下來即是現象和排查過程，想看結論的同窗能夠直接拉到最後總結。

現象

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

咱們使用 nginx 做爲服務端 websocket 的七層負載，5xx爆發一般代表服務端不可用。因爲目前 nginx 告警沒有細分具體哪臺機器不可用，接下來，到 cat（點評美團統一監控平臺）去檢查一下整個集羣的各項指標，發現以下兩個異常

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

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

排查過程

階段1: 懷疑是log4j2

線程被大量阻塞，首先想到的是定位哪些線程被阻塞，最後查出來是 log4j2 狂打日誌致使 netty 的 nio 線程阻塞（因爲沒有及時保留現場，因此截圖缺失），nio 線程阻塞以後，咱們的服務器沒法處理客戶端的請求，對nginx來講是5xx。

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

發現打印到控制檯的這個 appender 忘記註釋掉了，因此我初步猜想是由於這個項目打印的日誌過多，而 log4j2 打印到控制檯是同步阻塞打印的，接下來，把線上全部機器的這行註釋掉，覺得大功告成，沒想到，過不了幾天，5xx告警又來敲門了，看來，這個問題沒那麼簡單。

階段2：可疑日誌浮現

接下來，只能硬着頭皮去查日誌，查看故障發生點先後的日誌，發現了一處可疑的地方

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

堆外內存泄露，我去，聽到這個名詞就有點沮喪，由於這個問題的排查就像 c 語言內存泄露同樣難以排查，首先想到的是，在 OOM 爆發以前，查看有無異常，而後查遍了 cat 上與機器相關的全部指標，查遍了 OOM 日誌以前的全部日誌，均未發現任何異常！這個時候內心開始罵了……

階段3：定位OOM源

可是沒辦法，只能看着這堆討厭的 OOM 日誌發着呆，妄圖答案可以蹦到眼前。束手無策之際，忽然一道光在眼前一閃而過，在 OOM 下方的幾行日誌變得耀眼起來（爲啥以前就沒想認真查看日誌？估計是被堆外內存泄露這幾個詞嚇怕了吧==），這幾行字是 ....PlatformDepedeng.incrementMemory()...。我去，原來，堆外內存是否夠用，是 netty 這邊本身統計的，那是否是能夠找到統計代碼，找到統計代碼以後咱們就能夠看到 netty 裏面的對外內存統計邏輯了？因而，接下來翻翻代碼，找到這段邏輯，在 PlatformDepedent 這個類裏面

這個地方，是一個對已使用堆外內存計數的操做，計數器爲 DIRECT_MEMORY_COUNTER，若是發現已使用內存大於堆外內存的上限（用戶自行指定），就拋出一個自定義 OOM Error，異常裏面的文本內容正是咱們在日誌裏面看到的。

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

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

階段4：反射進行堆外內存監控

既然 cat 上關於堆外內存的監控沒有任何異常（應該是沒有統計準確，一直維持在 1M），而這邊咱們又確認堆外內存已快超過上限，而且已經知道 netty 底層是使用哪一個字段來統計的，那麼接下來要作的第一件事情，就是反射拿到這個字段，而後咱們本身統計 netty 使用堆外內存的狀況。

堆外內存統計字段是 DIRECT_MEMORY_COUNTER，咱們能夠經過反射拿到這個字段，而後按期check這個值，就能夠監控 netty 堆外內存的增加狀況。

咱們經過反射拿到這個字段，而後每隔一秒打印，我爲何要這樣作？

由於，經過咱們前面的分析，在爆發大量 OOM 現象以前，沒有任何可疑的現象，那麼只有兩種狀況，一種是忽然某個瞬間分配了大量的堆外內存致使OOM，一種是堆外內存緩慢增加，到達某個點以後，最後一根稻草將機器壓垮。這段代碼加上去以後，打包上線。

階段5：究竟是緩慢增加仍是瞬間飆升？

代碼上線以後，初始內存爲 16384k（16M），這是由於線上咱們使用了池化堆外內存，默認一個 chunk 爲16M，沒必要過於糾結。

沒過一會，內存就開始緩慢飆升，而且沒有釋放的跡象，20幾分鐘以後，內存以下

到了這裏，猜想多是前面提到的第二種狀況，也就是內存緩慢增加形成的 OOM，因爲內存實在增加太慢，因而調整機器負載權重爲其餘機器的兩倍，可是仍然是以幾K級別在增加，這天恰好是週五，索性就過他個一個週末再開看。

過完一個愉快的週末以後，到公司第一時間即是連上跳板機，登陸線上機器，開始 tail -f 繼續查看日誌，輸完命令以後，懷着期待的心情重重的敲下了回車鍵

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

到了這裏，我又開始自問自答了：內存爲啥會緩慢增加，伴隨着什麼而增加？由於咱們的應用是面向用戶端的websocket，那麼，會不會是每一次有用戶進來，交互完以後，而後離開，內存都會增加一些，而後不釋放呢？帶着這個疑問，我開始線下模擬。

階段6：線下模擬

本地起好服務，把監控堆外內存的單位改成以B爲單位（由於本地流量較小，打算一次一個客戶端鏈接），另外，本地也使用非池化內存（內存數字較小，容易看出問題），這樣，服務端啓動以後，控制檯打印信息以下

在沒有客戶端接入的時候，堆外內存一直是0，在乎料之中。接下來，懷着着無比激動的心情，打開瀏覽器，而後輸入網址，開始咱們的模擬之旅。

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

如上圖所示，一次 connect 和 disconnect 爲一次鏈接的創建與關閉，上圖綠色框框的日誌分別是兩次鏈接的生命週期。咱們能夠看到，內存每次都是在鏈接被關閉的的時候暴漲 256B 而後不釋放，到了這裏，問題進一步縮小，確定是鏈接被關閉的時候，觸發了框架的一個bug，這個bug在觸發以前分配了 256B 的內存，而後bug觸發，內存沒有釋放。問題縮小以後，接下來開始擼源碼捉蟲！

階段7：線下排查

接下來，我將本地服務重啓，開始完整的線下排查過程。將目光定位到 netty-socketio 這個框架的 disconnect 事件（客戶端websocket鏈接關閉的時候回調用到這裏），基本上能夠肯定是在 disconnect 事件先後申請的內存沒有釋放

這裏，在使用 idea debug的時候，要選擇只掛起當前線程，這樣咱們在單步跟蹤的時候，控制檯仍然能夠看到堆外內存統計線程在打印日誌。

客戶端鏈接上以後而後關閉，斷點進入到 onDisconnect 回調，我特地在此多停留了一會，發現控制檯內存並無飆升（7B這個內存暫時沒有去分析，只須要知道，客戶端鏈接斷開以後，咱們斷點hold住，內存還未開始漲），接下來，神奇的一幕出現了，我將斷點放開，讓程序跑完

debug 鬆掉以後，內存立馬飆升了！！這個時候我已經知道，這隻臭蟲飛不了多遠了。在 debug 的時候，掛起的是當前線程，那麼確定是當前線程某個地方申請了堆外內存，而後沒有釋放，接下來，馬不停蹄，深刻源碼。

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

在這一行沒執行以前，控制檯的內存依然是 263B，而後，當執行完這一行以後，立馬從 263B漲到519B（漲了256B）

因而，bug的範圍進一步縮小，我將本次程序跑完，釋而後客戶端再來一次鏈接，斷點打在 client.send() 這行， 而後關閉客戶端鏈接，以後直接進入到這個方法，隨後的過程有點長，由於與 netty 的時間傳播機制有關，這裏就省略了，最後，我跟到了以下代碼，handleWebsocket

在這個地方，我看了一處很是可疑的地方，在上圖的斷點上一行，調用 encoder 分配了一段內存，調用完以後，咱們的控制檯立馬就彪了 256B，因此，我懷疑確定是這裏申請的內存沒有釋放，他這裏接下來調用 encoder.encodePacket() 方法，猜測是把數據包的內容以二進制的方式寫到這段 256B的內存，接下來，我跟到這段 encode 代碼，單步執行以後，定位到這行代碼

這段代碼是把 packet 裏面一個字段的值轉換爲一個 char，然而，當我使用 idea 預執行的時候，卻拋出類一個憤怒的 NPE！！也就是說，框架申請到一段內存以後，在encoder的時候，本身GG了，本身給本身挖了個NPE的深坑，最後致使內存沒法釋放（最外層有堆外內存釋放邏輯，如今沒法執行到了），而後越攢越多，越攢越多，直到最後一根稻草，堆外內存就這樣爆了，這裏的源碼有興趣的讀者能夠本身去分析一下，限於篇幅緣由，這裏就再也不分析了。

階段8：bug解決

bug既然已經找到，接下來便要解決了，這裏只須要解決這個NPE異常，就能夠fix掉，咱們的目標就是，讓這個 subType 字段不爲空，咱們先經過 idea 的線程調用棧定位到這個 packet 是在哪一個地方定義的

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

咱們給這個字段賦值便可，因爲這裏是鏈接關閉事件，因此，我給他指定了一個名爲 DISCONNECT 的字段（改日深刻去研究socket.io的協議），反正這個bug是在鏈接關閉的時候觸發的，就粗暴一點了 ！==。

解決這個bug的過程是：將這個框架的源碼下載到本地，而後加上這一行，最後，我從新build一下，pom 裏改更名字，推送到咱們公司的倉庫，這樣，我項目就能夠直接使用了。

改完bug以後，習慣性地去github上找到引起這段bug的commit

好奇的是，爲啥這位 dzn commiter 會寫出這麼一段如此明顯的bug，並且時間就在今年3月30號，項目啓動的前夕！

階段9：線下驗證

一切就緒以後，首先，咱們來進行本地驗證，服務起起來以後，我瘋狂地創建鏈接，瘋狂地斷開鏈接，觀察堆外內存的狀況

好傢伙，無論你如何斷開鏈接，堆外內存一直不漲了，至此，bug 基本fix，固然，最後一步，咱們把代碼推到線上驗證。

階段10：線上驗證

此次線上驗證，咱們避免了比較土的打日誌方法，咱們把堆外內存的這個指標噴射到 cat上，而後再來觀察一段時間的堆外內存的狀況

發現過一段時間，堆外內存已經穩定不漲了，咱們的捉蟲之旅到此結束！最後，我來給本地捉蟲之旅作一次總結

總結

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

2.若是使用了netty 堆外內存，那麼你能夠自行監控堆外內存的使用狀況，不須要藉助第三方工具，我這裏是使用的反射拿到的堆外內存的狀況。

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

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

最後，祝願你們都能找到本身的 bug！