Netty 是一個異步事件驅動的網絡通訊層框架,用於快速開發高可用高性能的服務端網絡框架與客戶端程序,它極大地簡化了 TCP 和 UDP 套接字服務器等網絡編程。html
Netty 底層基於 JDK 的 NIO,咱們爲何不直接基於 JDK 的 NIO 或者其餘NIO框架:git
最近在作一個基於 Websocket 的長連中間件,服務端使用實現了 Socket.IO 協議(基於WebSocket協議,提供長輪詢降級能力) 的 netty-socketio 框架,該框架爲 Netty 實現,鑑於本人對 Netty 比較熟,而且對比一樣實現了 Socket.IO 協議的其餘框架,Netty 的口碑都要更好一些,所以選擇這個框架做爲底層核心。github
誠然,任何開源框架都避免不了 Bug 的存在,咱們在使用這個開源框架時,就遇到一個堆外內存泄露的 Bug。美團的價值觀一直都是「追求卓越」,因此咱們就想挑戰一下,找到那隻臭蟲(Bug),而本文就是遇到的問題以及排查的過程。固然,想看結論的同窗能夠直接跳到最後,閱讀總結便可。編程
某天早上,咱們忽然收到告警,Nginx 服務端出現大量5xx。瀏覽器
咱們使用 Nginx 做爲服務端 WebSocket 的七層負載,5xx的爆發一般代表服務端不可用。因爲目前 Nginx 告警沒有細分具體哪臺機器不可用,接下來,咱們就到 CAT(美團點評統一監控平臺,目前已經開源)去檢查一下整個集羣的各項指標,就發現以下兩個異常:服務器
某臺機器在同一時間點爆發 GC(垃圾回收),並且在同一時間,JVM 線程阻塞。微信
接下來,咱們就就開始了漫長的堆外內存泄露「排查之旅」。網絡
由於線程被大量阻塞,咱們首先想到的是定位哪些線程被阻塞,最後查出來是 Log4j2 狂打日誌致使 Netty 的 NIO 線程阻塞(因爲沒有及時保留現場,因此截圖缺失)。NIO 線程阻塞以後,因咱們的服務器沒法處理客戶端的請求,因此對Nginx來講就是5xx。併發
接下來,咱們查看了 Log4j2 的配置文件。app
咱們發現打印到控制檯的這個 appender 忘記註釋掉了,因此初步猜想:由於這個項目打印的日誌過多,而 Log4j2 打印到控制檯是同步阻塞打印的,因此就致使了這個問題。那麼接下來,咱們把線上全部機器的這行註釋掉,本覺得會「大功告成」,但沒想到僅僅過了幾天,5xx告警又來「敲門」。看來,這個問題並沒咱們最初想象的那麼簡單。
接下來,咱們只能硬着頭皮去查日誌,特別是故障發生點先後的日誌,因而又發現了一處可疑的地方:
能夠看到:在極短的時間內,狂打 failed to allocate 64(bytes) of direct memory(...)
日誌(瞬間十幾個日誌文件,每一個日誌文件幾百M),日誌裏拋出一個 Netty 本身封裝的OutOfDirectMemoryError
。說白了,就是堆外內存不夠用,Netty 一直在「喊冤」。
堆外內存泄露,聽到這個名詞就感到很沮喪。由於這個問題的排查就像 C 語言內存泄露同樣難以排查,首先能想到的就是,在 OOM 爆發以前,查看有無異常。而後查遍了 CAT 上與機器相關的全部指標,查遍了 OOM 日誌以前的全部日誌,均未發現任何異常!這個時候內心已經「萬馬奔騰」了......
沒辦法,只能看着這堆討厭的 OOM 日誌發着呆,但願答案可以「蹦到」眼前,可是那只是妄想。束手無策之際,忽然一道光在眼前一閃而過,在 OOM 下方的幾行日誌變得耀眼起來(爲啥以前就沒想認真查看日誌?估計是被堆外內存泄露這幾個詞嚇怕了吧 ==!),這幾行字是 ....PlatformDepedeng.incrementMemory()...
。
原來,堆外內存是否夠用,是 Netty 這邊本身統計的,那麼是否是能夠找到統計代碼,找到統計代碼以後咱們就能夠看到 Netty 裏面的對外內存統計邏輯了?因而,接下來翻翻代碼,找到這段邏輯,就在 PlatformDepedent
這個類裏面。
這個地方,是一個對已使用堆外內存計數的操做,計數器爲 DIRECT_MEMORY_COUNTER
,若是發現已使用內存大於堆外內存的上限(用戶自行指定),就拋出一個自定義 OOM Error,異常裏面的文本內容正是咱們在日誌裏面看到的。
接下來,就驗證一下這個方法是不是在堆外內存分配的時候被調用。
果真,在 Netty 每次分配堆外內存以前,都會計數。想到這,思路就開始慢慢清晰,而心情也開始從「秋風瑟瑟」變成「春光明媚」。
CAT 上關於堆外內存的監控沒有任何異常(應該是沒有統計準確,一直維持在 1M),而這邊咱們又確認堆外內存已快超過上限,而且已經知道 Netty 底層是使用的哪一個字段來統計。那麼接下來要作的第一件事情,就是反射拿到這個字段,而後咱們本身統計 Netty 使用堆外內存的狀況。
堆外內存統計字段是 DIRECT_MEMORY_COUNTER
,咱們能夠經過反射拿到這個字段,而後按期 Check 這個值,就能夠監控 Netty 堆外內存的增加狀況。
因而咱們經過反射拿到這個字段,而後每隔一秒打印,爲何要這樣作?
由於,經過咱們前面的分析,在爆發大量 OOM 現象以前,沒有任何可疑的現象。那麼只有兩種狀況,一種是忽然某個瞬間分配了大量的堆外內存致使OOM;一種是堆外內存緩慢增加,到達某個點以後,最後一根稻草將機器壓垮。在這段代碼加上去以後,咱們打包上線。
代碼上線以後,初始內存爲 16384k(16M),這是由於線上咱們使用了池化堆外內存,默認一個 chunk 爲16M,這裏沒必要過於糾結。
可是沒過一會,內存就開始緩慢飆升,而且沒有釋放的跡象,二十幾分鍾以後,內存使用狀況以下:
走到這裏,咱們猜想多是前面提到的第二種狀況,也就是內存緩慢增加形成的 OOM,因爲內存實在增加太慢,因而調整機器負載權重爲其餘機器的兩倍,可是仍然是以數K級別在持續增加。那天恰好是週五,索性就過一個週末再開看。
週末以後,咱們到公司第一時間就連上了跳板機,登陸線上機器,開始 tail -f 繼續查看日誌。在輸完命令以後,懷着期待的心情重重的敲下了回車鍵:
果真不出所料,內存一直在緩慢增加,一個週末的時間,堆外內存已經飆到快一個 G 了。這個時候,我居然想到了一句成語:「只要功夫深,鐵杵磨成針」。雖然堆外內存以幾個K的速度在緩慢增加,可是隻要一直持續下去,總有把內存打爆的時候(線上堆外內存上限設置的是2G)。
此時,咱們開始自問自答環節:內存爲啥會緩慢增加,伴隨着什麼而增加?由於咱們的應用是面向用戶端的WebSocket,那麼,會不會是每一次有用戶進來,交互完以後離開,內存都會增加一些,而後不釋放呢?帶着這個疑問,咱們開始了線下模擬過程。
本地起好服務,把監控堆外內存的單位改成以B爲單位(由於本地流量較小,打算一次一個客戶端鏈接),另外,本地也使用非池化內存(內存數字較小,容易看出問題),在服務端啓動以後,控制檯打印信息以下
在沒有客戶端接入的時候,堆外內存一直是0,在乎料之中。接下來,懷着着無比激動的心情,打開瀏覽器,而後輸入網址,開始咱們的模擬之旅。
咱們的模擬流程是:新建一個客戶端連接->斷開連接->再新建一個客戶端連接->再斷開連接。
如上圖所示,一次 Connect 和 Disconnect 爲一次鏈接的創建與關閉,上圖綠色框框的日誌分別是兩次鏈接的生命週期。咱們能夠看到,內存每次都是在鏈接被關閉的的時候暴漲 256B,而後也不釋放。走到這裏,問題進一步縮小,確定是鏈接被關閉的時候,觸發了框架的一個Bug,並且這個Bug在觸發以前分配了 256B 的內存,隨着Bug被觸發,內存也沒有釋放。問題縮小以後,接下來開始「擼源碼」,捉蟲!
接下來,咱們將本地服務重啓,開始完整的線下排查過程。同時將目光定位到 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的深坑,最後致使內存沒法釋放(最外層有堆外內存釋放邏輯,如今沒法執行到了)。並且越攢越多,直到被「最後一根稻草」壓垮,堆外內存就這樣爆了。這裏的源碼,有興趣的讀者能夠本身去分析一下,限於篇幅緣由,這裏就再也不展開敘述了。
既然 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號,項目啓動的前夕!
一切準備就緒以後,咱們就來進行本地驗證,在服務起來以後,咱們瘋狂地創建鏈接,瘋狂地斷開鏈接,並觀察堆外內存的狀況:
Bingo!無論咱們如何斷開鏈接,堆外內存不漲了。至此,Bug 基本 Fix,固然最後一步,咱們把代碼推到線上驗證。
此次線上驗證,咱們避免了比較土的打日誌方法,咱們把堆外內存的這個指標「噴射」到 CAT 上,而後再來觀察一段時間的堆外內存的狀況:
過完一段時間,堆外內存已經穩定不漲了。此刻,咱們的「捉蟲之旅」到此結束。最後,咱們還爲你們作一個小小的總結,但願對您有所幫助。
遇到堆外內存泄露不要怕,仔細耐心分析,總能找到思路,要多看日誌,多分析。
若是使用了 Netty 堆外內存,那麼能夠自行監控堆外內存的使用狀況,不須要藉助第三方工具,咱們是使用的「反射」拿到的堆外內存的狀況。
逐漸縮小範圍,直到 Bug 被找到。當咱們確認某個線程的執行帶來 Bug 時,可單步執行,可二分執行,定位到某行代碼以後,跟到這段代碼,而後繼續單步執行或者二分的方式來定位最終出 Bug 的代碼。這個方法屢試不爽,最後總能找到想要的 Bug。
熟練掌握 idea 的調試,讓咱們的「捉蟲」速度快如閃電(「閃電俠」就是這麼來的)。這裏,最多見的調試方式是預執行表達式,以及經過線程調用棧,死盯某個對象,就可以掌握這個對象的定義、賦值之類。
最後,祝願你們都能找到本身的「心儀已久」 Bug!
閃電俠,2014年加入美團點評,主要負責美團點評移動端統一長連工做,歡迎同行進行技術交流。
目前咱們團隊負責美團點評長連基礎設施的建設,支持美團酒旅、外賣、到店、打車、金融等幾乎公司全部業務的快速發展。加入咱們,你能夠親身體驗到千萬級在線鏈接、日吞吐百億請求的場景,你會直面互聯網高併發、高可用的挑戰,有機會接觸到 Netty 在長連領域的各個場景。咱們誠邀有激情、有想法、有經驗、有能力的同窗,和咱們一塊兒並肩奮鬥!歡迎感興趣的同窗投遞簡歷至 chao.yu#dianping.com 諮詢。
發現文章有錯誤、對內容有疑問,均可以關注美團技術團隊微信公衆號(meituantech),在後臺給咱們留言。咱們每週會挑選出一位熱心小夥伴,送上一份精美的小禮品。快來掃碼關注咱們吧!