導(dǎo)讀

Netty 是一個(gè)異步事件驅(qū)動(dòng)的網(wǎng)絡(luò)通信層框架，用于快速開發(fā)高可用高性能的服務(wù)端網(wǎng)絡(luò)框架與客戶端程序，它極大地簡(jiǎn)化了 TCP 和 UDP 套接字服務(wù)器等網(wǎng)絡(luò)編程。

Netty 底層基于 JDK 的 NIO，我們?yōu)槭裁床恢苯踊?JDK 的 NIO 或者其他NIO框架：

使用 JDK 自帶的 NIO 需要了解太多的概念，編程復(fù)雜。

Netty 底層 IO 模型隨意切換，而這一切只需要做微小的改動(dòng)。

Netty自帶的拆包解包，異常檢測(cè)等機(jī)制讓我們從 NIO 的繁重細(xì)節(jié)中脫離出來(lái)，只需關(guān)心業(yè)務(wù)邏輯即可。

Netty解決了JDK 的很多包括空輪訓(xùn)在內(nèi)的 Bug。

Netty底層對(duì)線程，Selector 做了很多細(xì)小的優(yōu)化，精心設(shè)計(jì)的 Reactor 線程做到非常高效的并發(fā)處理。

自帶各種協(xié)議棧，讓我們處理任何一種通用協(xié)議都幾乎不用親自動(dòng)手。

Netty社區(qū)活躍，遇到問(wèn)題隨時(shí)郵件列表或者 issue。

Netty已經(jīng)歷各大RPC框架（Dubbo），消息中間件（RocketMQ），大數(shù)據(jù)通信（Hadoop）框架的廣泛的線上驗(yàn)證，健壯性無(wú)比強(qiáng)大。

背景

最近在做一個(gè)基于 Websocket 的長(zhǎng)連中間件，服務(wù)端使用實(shí)現(xiàn)了 Socket.IO 協(xié)議（基于WebSocket協(xié)議，提供長(zhǎng)輪詢降級(jí)能力） 的 netty-socketio 框架，該框架為 Netty 實(shí)現(xiàn)，鑒于本人對(duì) Netty 比較熟，并且對(duì)比同樣實(shí)現(xiàn)了 Socket.IO 協(xié)議的其他框架，Netty 的口碑都要更好一些，因此選擇這個(gè)框架作為底層核心。

誠(chéng)然，任何開源框架都避免不了 Bug 的存在，我們?cè)谑褂眠@個(gè)開源框架時(shí)，就遇到一個(gè)堆外內(nèi)存泄露的 Bug。美團(tuán)的價(jià)值觀一直都是“追求卓越”，所以我們就想挑戰(zhàn)一下，找到那只臭蟲（Bug），而本文就是遇到的問(wèn)題以及排查的過(guò)程。當(dāng)然，想看結(jié)論的同學(xué)可以直接跳到最后，閱讀總結(jié)即可。

問(wèn)題

某天早上，我們突然收到告警，Nginx 服務(wù)端出現(xiàn)大量5xx。

我們使用 Nginx 作為服務(wù)端 WebSocket 的七層負(fù)載，5xx的爆發(fā)通常表明服務(wù)端不可用。由于目前 Nginx 告警沒有細(xì)分具體哪臺(tái)機(jī)器不可用，接下來(lái)，我們就到 CAT（美團(tuán)點(diǎn)評(píng)統(tǒng)一監(jiān)控平臺(tái)，目前已經(jīng)開源）去檢查一下整個(gè)集群的各項(xiàng)指標(biāo)，就發(fā)現(xiàn)如下兩個(gè)異常:

某臺(tái)機(jī)器在同一時(shí)間點(diǎn)爆發(fā) GC（垃圾回收），而且在同一時(shí)間，JVM 線程阻塞。

接下來(lái)，我們就就開始了漫長(zhǎng)的堆外內(nèi)存泄露“排查之旅”。

排查過(guò)程

階段1: 懷疑是log4j2

因?yàn)榫€程被大量阻塞，我們首先想到的是定位哪些線程被阻塞，最后查出來(lái)是 Log4j2 狂打日志導(dǎo)致 Netty 的 NIO 線程阻塞（由于沒有及時(shí)保留現(xiàn)場(chǎng)，所以截圖缺失）。NIO 線程阻塞之后，因我們的服務(wù)器無(wú)法處理客戶端的請(qǐng)求，所以對(duì)Nginx來(lái)說(shuō)就是5xx。

接下來(lái)，我們查看了 Log4j2 的配置文件。

我們發(fā)現(xiàn)打印到控制臺(tái)的這個(gè) appender 忘記注釋掉了，所以初步猜測(cè)：因?yàn)檫@個(gè)項(xiàng)目打印的日志過(guò)多，而 Log4j2 打印到控制臺(tái)是同步阻塞打印的，所以就導(dǎo)致了這個(gè)問(wèn)題。那么接下來(lái)，我們把線上所有機(jī)器的這行注釋掉，本以為會(huì)“大功告成”，但沒想到僅僅過(guò)了幾天，5xx告警又來(lái)“敲門”?？磥?lái)，這個(gè)問(wèn)題并沒我們最初想象的那么簡(jiǎn)單。

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

接下來(lái)，我們只能硬著頭皮去查日志，特別是故障發(fā)生點(diǎn)前后的日志，于是又發(fā)現(xiàn)了一處可疑的地方：

可以看到：在極短的時(shí)間內(nèi)，狂打 failed to allocate 64(bytes) of direct memory(...)日志（瞬間十幾個(gè)日志文件，每個(gè)日志文件幾百M(fèi)），日志里拋出一個(gè) Netty 自己封裝的OutOfDirectMemoryError。說(shuō)白了，就是堆外內(nèi)存不夠用，Netty 一直在“喊冤”。

堆外內(nèi)存泄露，聽到這個(gè)名詞就感到很沮喪。因?yàn)檫@個(gè)問(wèn)題的排查就像 C 語(yǔ)言內(nèi)存泄露一樣難以排查，首先能想到的就是，在 OOM 爆發(fā)之前，查看有無(wú)異常。然后查遍了 CAT 上與機(jī)器相關(guān)的所有指標(biāo)，查遍了 OOM 日志之前的所有日志，均未發(fā)現(xiàn)任何異常！這個(gè)時(shí)候心里已經(jīng)“萬(wàn)馬奔騰”了……

階段3：定位OOM源

沒辦法，只能看著這堆討厭的 OOM 日志發(fā)著呆，希望答案能夠“蹦到”眼前，但是那只是妄想。一籌莫展之際，突然一道光在眼前一閃而過(guò)，在 OOM 下方的幾行日志變得耀眼起來(lái)（為啥之前就沒想認(rèn)真查看日志？估計(jì)是被堆外內(nèi)存泄露這幾個(gè)詞嚇怕了吧 ==！），這幾行字是 ....PlatformDepedeng.incrementMemory()...。

原來(lái)，堆外內(nèi)存是否夠用，是 Netty 這邊自己統(tǒng)計(jì)的，那么是不是可以找到統(tǒng)計(jì)代碼，找到統(tǒng)計(jì)代碼之后我們就可以看到 Netty 里面的對(duì)外內(nèi)存統(tǒng)計(jì)邏輯了？于是，接下來(lái)翻翻代碼，找到這段邏輯，就在 PlatformDepedent 這個(gè)類里面。

這個(gè)地方，是一個(gè)對(duì)已使用堆外內(nèi)存計(jì)數(shù)的操作，計(jì)數(shù)器為 DIRECT_MEMORY_COUNTER，如果發(fā)現(xiàn)已使用內(nèi)存大于堆外內(nèi)存的上限（用戶自行指定），就拋出一個(gè)自定義 OOM Error，異常里面的文本內(nèi)容正是我們?cè)谌罩纠锩婵吹降摹?/p>

接下來(lái)，就驗(yàn)證一下這個(gè)方法是否是在堆外內(nèi)存分配的時(shí)候被調(diào)用。

果然，在 Netty 每次分配堆外內(nèi)存之前，都會(huì)計(jì)數(shù)。想到這，思路就開始慢慢清晰，而心情也開始從“秋風(fēng)瑟瑟”變成“春光明媚”。

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

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

堆外內(nèi)存統(tǒng)計(jì)字段是 DIRECT_MEMORY_COUNTER，我們可以通過(guò)反射拿到這個(gè)字段，然后定期 Check 這個(gè)值，就可以監(jiān)控 Netty 堆外內(nèi)存的增長(zhǎng)情況。

于是我們通過(guò)反射拿到這個(gè)字段，然后每隔一秒打印，為什么要這樣做？

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

階段5：到底是緩慢增長(zhǎng)還是瞬間飆升？

代碼上線之后，初始內(nèi)存為 16384k（16M），這是因?yàn)榫€上我們使用了池化堆外內(nèi)存，默認(rèn)一個(gè) chunk 為16M，這里不必過(guò)于糾結(jié)。

但是沒過(guò)一會(huì)，內(nèi)存就開始緩慢飆升，并且沒有釋放的跡象，二十幾分鐘之后，內(nèi)存使用情況如下：

走到這里，我們猜測(cè)可能是前面提到的第二種情況，也就是內(nèi)存緩慢增長(zhǎng)造成的 OOM，由于內(nèi)存實(shí)在增長(zhǎng)太慢，于是調(diào)整機(jī)器負(fù)載權(quán)重為其他機(jī)器的兩倍，但是仍然是以數(shù)K級(jí)別在持續(xù)增長(zhǎng)。那天剛好是周五，索性就過(guò)一個(gè)周末再開看。

周末之后，我們到公司第一時(shí)間就連上了跳板機(jī)，登錄線上機(jī)器，開始 tail -f 繼續(xù)查看日志。在輸完命令之后，懷著期待的心情重重的敲下了回車鍵：

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

此時(shí)，我們開始自問(wèn)自答環(huán)節(jié)：內(nèi)存為啥會(huì)緩慢增長(zhǎng)，伴隨著什么而增長(zhǎng)？因?yàn)槲覀兊膽?yīng)用是面向用戶端的WebSocket，那么，會(huì)不會(huì)是每一次有用戶進(jìn)來(lái)，交互完之后離開，內(nèi)存都會(huì)增長(zhǎng)一些，然后不釋放呢？帶著這個(gè)疑問(wèn)，我們開始了線下模擬過(guò)程。

階段6：線下模擬

本地起好服務(wù)，把監(jiān)控堆外內(nèi)存的單位改為以B為單位（因?yàn)楸镜亓髁枯^小，打算一次一個(gè)客戶端連接），另外，本地也使用非池化內(nèi)存（內(nèi)存數(shù)字較小，容易看出問(wèn)題），在服務(wù)端啟動(dòng)之后，控制臺(tái)打印信息如下

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

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

如上圖所示，一次 Connect 和 Disconnect 為一次連接的建立與關(guān)閉，上圖綠色框框的日志分別是兩次連接的生命周期。我們可以看到，內(nèi)存每次都是在連接被關(guān)閉的的時(shí)候暴漲 256B，然后也不釋放。走到這里，問(wèn)題進(jìn)一步縮小，肯定是連接被關(guān)閉的時(shí)候，觸發(fā)了框架的一個(gè)Bug，而且這個(gè)Bug在觸發(fā)之前分配了 256B 的內(nèi)存，隨著Bug被觸發(fā)，內(nèi)存也沒有釋放。問(wèn)題縮小之后，接下來(lái)開始“擼源碼”，捉蟲！

階段7：線下排查

接下來(lái)，我們將本地服務(wù)重啟，開始完整的線下排查過(guò)程。同時(shí)將目光定位到 netty-socketio 這個(gè)框架的 Disconnect 事件（客戶端WebSocket連接關(guān)閉時(shí)會(huì)調(diào)用到這里），基本上可以確定，在 Disconnect 事件前后申請(qǐng)的內(nèi)存并沒有釋放。

在使用 idea debug 時(shí)，要選擇只掛起當(dāng)前線程，這樣我們?cè)趩尾礁櫟臅r(shí)候，控制臺(tái)仍然可以看到堆外內(nèi)存統(tǒng)計(jì)線程在打印日志。

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

Debug 松掉之后，內(nèi)存立馬飆升了！！此時(shí)，我們已經(jīng)知道，這只“臭蟲”飛不了多遠(yuǎn)了。在 Debug 時(shí)，掛起的是當(dāng)前線程，那么肯定是當(dāng)前線程某個(gè)地方申請(qǐng)了堆外內(nèi)存，然后沒有釋放，繼續(xù)“快馬加鞭“，深入源碼。

其實(shí)，每一次單步調(diào)試，我們都會(huì)觀察控制臺(tái)的內(nèi)存飆升的情況。很快，我們來(lái)到了這個(gè)地方：

在這一行沒執(zhí)行之前，控制臺(tái)的內(nèi)存依然是 263B。然后，當(dāng)執(zhí)行完該行之后，立刻從 263B漲到519B（漲了256B）。

于是，Bug 范圍進(jìn)一步縮小。我們將本次程序跑完，釋然后客戶端再來(lái)一次連接，斷點(diǎn)打在 client.send() 這行， 然后關(guān)閉客戶端連接，之后直接進(jìn)入到這個(gè)方法，隨后的過(guò)程有點(diǎn)長(zhǎng)，因?yàn)榕c Netty 的時(shí)間傳播機(jī)制有關(guān)，這里就省略了。最后，我們跟蹤到了如下代碼，handleWebsocket：

在這個(gè)地方，我們看到一處非?？梢傻牡胤?#xff0c;在上圖的斷點(diǎn)上一行，調(diào)用 encoder 分配了一段內(nèi)存，調(diào)用完之后，我們的控制臺(tái)立馬就彪了 256B。所以，我們懷疑肯定是這里申請(qǐng)的內(nèi)存沒有釋放，它這里接下來(lái)調(diào)用 encoder.encodePacket() 方法，猜想是把數(shù)據(jù)包的內(nèi)容以二進(jìn)制的方式寫到這段 256B的內(nèi)存。接下來(lái)，我們追蹤到這段 encode 代碼，單步執(zhí)行之后，就定位到這行代碼：

這段代碼是把 packet 里面一個(gè)字段的值轉(zhuǎn)換為一個(gè) char。然而，當(dāng)我們使用 idea 預(yù)執(zhí)行的時(shí)候，卻拋出類一個(gè)憤怒的 NPE！！也就是說(shuō)，框架申請(qǐng)到一段內(nèi)存之后，在 encoder 的時(shí)候，自己 GG 了，還給自己挖了個(gè)NPE的深坑，最后導(dǎo)致內(nèi)存無(wú)法釋放（最外層有堆外內(nèi)存釋放邏輯，現(xiàn)在無(wú)法執(zhí)行到了）。而且越攢越多，直到被“最后一根稻草”壓垮，堆外內(nèi)存就這樣爆了。這里的源碼，有興趣的讀者可以自己去分析一下，限于篇幅原因，這里就不再展開敘述了。

階段8：Bug解決

既然 Bug 已經(jīng)找到，接下來(lái)就要解決問(wèn)題了。這里只需要解決這個(gè)NPE異常，就可以 Fix 掉。我們的目標(biāo)就是，讓這個(gè) subType 字段不為空。于是我們先通過(guò) idea 的線程調(diào)用棧，定位到這個(gè) packet 是在哪個(gè)地方定義的：

我們找到 idea 的 debugger 面板，眼睛盯著 packet 這個(gè)對(duì)象不放，然后上線移動(dòng)光標(biāo)，便光速定位到。原來(lái)，定義 packet 對(duì)象這個(gè)地方在我們前面的代碼其實(shí)已經(jīng)出現(xiàn)過(guò)，我們查看了一下 subType 這個(gè)字段，果然是 null。接下來(lái)，解決 Bug 就很容易了。

我們給這個(gè)字段賦值即可，由于這里是連接關(guān)閉事件，所以我們給他指定了一個(gè)名為 DISCONNECT 的字段（可以改天深入去研究 Socket.IO 的協(xié)議），反正這個(gè) Bug 是在連接關(guān)閉的時(shí)候觸發(fā)的，就粗暴一點(diǎn)了 ！

解決這個(gè) Bug 的過(guò)程是：將這個(gè)框架的源碼下載到本地，然后加上這一行，最后重新 Build一下，pom 里改了一下名字，推送到我們公司的倉(cāng)庫(kù)。這樣，項(xiàng)目就可以直接進(jìn)行使用了。

改完 Bug 之后，習(xí)慣性地去 GitHub上找到引發(fā)這段 Bug 的 Commit：

好奇的是，為啥這位 dzn commiter 會(huì)寫出這么一段如此明顯的 Bug，而且時(shí)間就在今年3月30號(hào)，項(xiàng)目啟動(dòng)的前夕！

階段9：線下驗(yàn)證

一切準(zhǔn)備就緒之后，我們就來(lái)進(jìn)行本地驗(yàn)證，在服務(wù)起來(lái)之后，我們瘋狂地建立連接，瘋狂地?cái)嚅_連接，并觀察堆外內(nèi)存的情況：

Bingo！不管我們?nèi)绾螖嚅_連接，堆外內(nèi)存不漲了。至此，Bug 基本 Fix，當(dāng)然最后一步，我們把代碼推到線上驗(yàn)證。

階段10：線上驗(yàn)證

這次線上驗(yàn)證，我們避免了比較土的打日志方法，我們把堆外內(nèi)存的這個(gè)指標(biāo)“噴射”到 CAT 上，然后再來(lái)觀察一段時(shí)間的堆外內(nèi)存的情況：

過(guò)完一段時(shí)間，堆外內(nèi)存已經(jīng)穩(wěn)定不漲了。此刻，我們的“捉蟲之旅”到此結(jié)束。最后，我們還為大家做一個(gè)小小的總結(jié)，希望對(duì)您有所幫助。

總結(jié)

遇到堆外內(nèi)存泄露不要怕，仔細(xì)耐心分析，總能找到思路，要多看日志，多分析。

如果使用了 Netty 堆外內(nèi)存，那么可以自行監(jiān)控堆外內(nèi)存的使用情況，不需要借助第三方工具，我們是使用的“反射”拿到的堆外內(nèi)存的情況。

逐漸縮小范圍，直到 Bug 被找到。當(dāng)我們確認(rèn)某個(gè)線程的執(zhí)行帶來(lái) Bug 時(shí)，可單步執(zhí)行，可二分執(zhí)行，定位到某行代碼之后，跟到這段代碼，然后繼續(xù)單步執(zhí)行或者二分的方式來(lái)定位最終出 Bug 的代碼。這個(gè)方法屢試不爽，最后總能找到想要的 Bug。

熟練掌握 idea 的調(diào)試，讓我們的“捉蟲”速度快如閃電（“閃電俠”就是這么來(lái)的）。這里，最常見的調(diào)試方式是預(yù)執(zhí)行表達(dá)式，以及通過(guò)線程調(diào)用棧，死盯某個(gè)對(duì)象，就能夠掌握這個(gè)對(duì)象的定義、賦值之類。

最后，祝愿大家都能找到自己的“心儀已久” Bug！

作者簡(jiǎn)介

• 閃電俠，2014年加入美團(tuán)點(diǎn)評(píng)，主要負(fù)責(zé)美團(tuán)點(diǎn)評(píng)移動(dòng)端統(tǒng)一長(zhǎng)連工作，歡迎同行進(jìn)行技術(shù)交流。

招聘

目前我們團(tuán)隊(duì)負(fù)責(zé)美團(tuán)點(diǎn)評(píng)長(zhǎng)連基礎(chǔ)設(shè)施的建設(shè)，支持美團(tuán)酒旅、外賣、到店、打車、金融等幾乎公司所有業(yè)務(wù)的快速發(fā)展。加入我們，你可以親身體驗(yàn)到千萬(wàn)級(jí)在線連接、日吞吐百億請(qǐng)求的場(chǎng)景，你會(huì)直面互聯(lián)網(wǎng)高并發(fā)、高可用的挑戰(zhàn)，有機(jī)會(huì)接觸到 Netty 在長(zhǎng)連領(lǐng)域的各個(gè)場(chǎng)景。我們誠(chéng)邀有激情、有想法、有經(jīng)驗(yàn)、有能力的同學(xué)，和我們一起并肩奮斗！歡迎感興趣的同學(xué)投遞簡(jiǎn)歷至 chao.yu#dianping.com 咨詢。

參考文獻(xiàn)

Netty 是什么

Netty 源碼分析之服務(wù)端啟動(dòng)全解析

總結(jié)

以上是生活随笔為你收集整理的Netty堆外内存泄露排查盛宴的全部?jī)?nèi)容，希望文章能夠幫你解決所遇到的問(wèn)題。

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