Netty堆外內存泄露排查與總結

導讀

Netty 是一個異步事件驅動的網絡通訊層框架,用於快速開發高可用高性能的服務端網絡框架與客戶端程序,它極大地簡化了 TCP 和 UDP 套接字服務器等網絡編程。html

Netty 底層基於 JDK 的 NIO,咱們爲何不直接基於 JDK 的 NIO 或者其餘NIO框架:git

  1. 使用 JDK 自帶的 NIO 須要瞭解太多的概念,編程複雜。
  2. Netty 底層 IO 模型隨意切換,而這一切只須要作微小的改動。
  3. Netty自帶的拆包解包,異常檢測等機制讓咱們從 NIO 的繁重細節中脫離出來,只需關心業務邏輯便可。
  4. Netty解決了JDK 的不少包括空輪訓在內的 Bug。
  5. Netty底層對線程,Selector 作了不少細小的優化,精心設計的 Reactor 線程作到很是高效的併發處理。
  6. 自帶各類協議棧,讓咱們處理任何一種通用協議都幾乎不用親自動手。
  7. Netty社區活躍,遇到問題隨時郵件列表或者 issue。
  8. Netty已經歷各大RPC框架(Dubbo),消息中間件(RocketMQ),大數據通訊(Hadoop)框架的普遍的線上驗證,健壯性無比強大。

背景

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

誠然,任何開源框架都避免不了 Bug 的存在,咱們在使用這個開源框架時,就遇到一個堆外內存泄露的 Bug。美團的價值觀一直都是「追求卓越」,因此咱們就想挑戰一下,找到那隻臭蟲(Bug),而本文就是遇到的問題以及排查的過程。固然,想看結論的同窗能夠直接跳到最後,閱讀總結便可。編程

問題

某天早上,咱們忽然收到告警,Nginx 服務端出現大量5xx。瀏覽器

image.png

咱們使用 Nginx 做爲服務端 WebSocket 的七層負載,5xx的爆發一般代表服務端不可用。因爲目前 Nginx 告警沒有細分具體哪臺機器不可用,接下來,咱們就到 CAT(美團點評統一監控平臺,目前已經開源)去檢查一下整個集羣的各項指標,就發現以下兩個異常:服務器

image.png

某臺機器在同一時間點爆發 GC(垃圾回收),並且在同一時間,JVM 線程阻塞。微信

image.png

接下來,咱們就就開始了漫長的堆外內存泄露「排查之旅」。網絡

排查過程

階段1: 懷疑是log4j2

由於線程被大量阻塞,咱們首先想到的是定位哪些線程被阻塞,最後查出來是 Log4j2 狂打日誌致使 Netty 的 NIO 線程阻塞(因爲沒有及時保留現場,因此截圖缺失)。NIO 線程阻塞以後,因咱們的服務器沒法處理客戶端的請求,因此對Nginx來講就是5xx。併發

接下來,咱們查看了 Log4j2 的配置文件。app

image.png

咱們發現打印到控制檯的這個 appender 忘記註釋掉了,因此初步猜想:由於這個項目打印的日誌過多,而 Log4j2 打印到控制檯是同步阻塞打印的,因此就致使了這個問題。那麼接下來,咱們把線上全部機器的這行註釋掉,本覺得會「大功告成」,但沒想到僅僅過了幾天,5xx告警又來「敲門」。看來,這個問題並沒咱們最初想象的那麼簡單。

階段2:可疑日誌浮現

接下來,咱們只能硬着頭皮去查日誌,特別是故障發生點先後的日誌,因而又發現了一處可疑的地方:

image.png

能夠看到:在極短的時間內,狂打 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 這個類裏面。

image.png

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

接下來,就驗證一下這個方法是不是在堆外內存分配的時候被調用。

image.png

果真,在 Netty 每次分配堆外內存以前,都會計數。想到這,思路就開始慢慢清晰,而心情也開始從「秋風瑟瑟」變成「春光明媚」。

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

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

image.png

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

image.png

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

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

階段5:究竟是緩慢增加仍是瞬間飆升?

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

image.png

可是沒過一會,內存就開始緩慢飆升,而且沒有釋放的跡象,二十幾分鍾以後,內存使用狀況以下:

image.png

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

週末以後,咱們到公司第一時間就連上了跳板機,登陸線上機器,開始 tail -f 繼續查看日誌。在輸完命令以後,懷着期待的心情重重的敲下了回車鍵:

image.png

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

此時,咱們開始自問自答環節:內存爲啥會緩慢增加,伴隨着什麼而增加?由於咱們的應用是面向用戶端的WebSocket,那麼,會不會是每一次有用戶進來,交互完以後離開,內存都會增加一些,而後不釋放呢?帶着這個疑問,咱們開始了線下模擬過程。

階段6:線下模擬

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

image.png

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

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

image.png

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

階段7:線下排查

接下來,咱們將本地服務重啓,開始完整的線下排查過程。同時將目光定位到 netty-socketio 這個框架的 Disconnect 事件(客戶端WebSocket鏈接關閉時會調用到這裏),基本上能夠肯定,在 Disconnect 事件先後申請的內存並無釋放。

image.png

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

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

image.png

Debug 鬆掉以後,內存立馬飆升了!!此時,咱們已經知道,這隻「臭蟲」飛不了多遠了。在 Debug 時,掛起的是當前線程,那麼確定是當前線程某個地方申請了堆外內存,而後沒有釋放,繼續「馬不停蹄「,深刻源碼。

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

image.png

在這一行沒執行以前,控制檯的內存依然是 263B。而後,當執行完該行以後,馬上從 263B漲到519B(漲了256B)。

image.png

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

image.png

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

image.png

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

階段8:Bug解決

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

image.png

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

image.png

咱們給這個字段賦值便可,因爲這裏是鏈接關閉事件,因此咱們給他指定了一個名爲 DISCONNECT 的字段(能夠改天深刻去研究 Socket.IO 的協議),反正這個 Bug 是在鏈接關閉的時候觸發的,就粗暴一點了 !

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

改完 Bug 以後,習慣性地去 GitHub上找到引起這段 Bug 的 Commit:
image.png
好奇的是,爲啥這位 dzn commiter 會寫出這麼一段如此明顯的 Bug,並且時間就在今年3月30號,項目啓動的前夕!

階段9:線下驗證

一切準備就緒以後,咱們就來進行本地驗證,在服務起來以後,咱們瘋狂地創建鏈接,瘋狂地斷開鏈接,並觀察堆外內存的狀況:

image.png

Bingo!無論咱們如何斷開鏈接,堆外內存不漲了。至此,Bug 基本 Fix,固然最後一步,咱們把代碼推到線上驗證。

階段10:線上驗證

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

image.png

過完一段時間,堆外內存已經穩定不漲了。此刻,咱們的「捉蟲之旅」到此結束。最後,咱們還爲你們作一個小小的總結,但願對您有所幫助。

總結

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

  2. 若是使用了 Netty 堆外內存,那麼能夠自行監控堆外內存的使用狀況,不須要藉助第三方工具,咱們是使用的「反射」拿到的堆外內存的狀況。

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

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

最後,祝願你們都能找到本身的「心儀已久」 Bug!

做者簡介

閃電俠,2014年加入美團點評,主要負責美團點評移動端統一長連工做,歡迎同行進行技術交流。

招聘

目前咱們團隊負責美團點評長連基礎設施的建設,支持美團酒旅、外賣、到店、打車、金融等幾乎公司全部業務的快速發展。加入咱們,你能夠親身體驗到千萬級在線鏈接、日吞吐百億請求的場景,你會直面互聯網高併發、高可用的挑戰,有機會接觸到 Netty 在長連領域的各個場景。咱們誠邀有激情、有想法、有經驗、有能力的同窗,和咱們一塊兒並肩奮鬥!歡迎感興趣的同窗投遞簡歷至 chao.yu#dianping.com 諮詢。

參考文獻

  1. Netty 是什麼
  2. Netty 源碼分析之服務端啓動全解析

發現文章有錯誤、對內容有疑問,均可以關注美團技術團隊微信公衆號(meituantech),在後臺給咱們留言。咱們每週會挑選出一位熱心小夥伴,送上一份精美的小禮品。快來掃碼關注咱們吧!

相關文章
相關標籤/搜索