這篇文章對于排查使用了 netty 引發(fā)的堆外內(nèi)存泄露問題欲低，有一定的通用性组底，希望對你有所啟發(fā)

背景

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

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

現(xiàn)象

某天早上突然收到告警绰寞，nginx 服務(wù)端大量5xx

image.png

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

image.png

某臺機(jī)器在同一時(shí)間點(diǎn)爆發(fā) gc件缸，同一時(shí)間铜靶，jvm 線程阻塞

image.png

接下來，便開始漫長的 堆外內(nèi)存泄露排查之旅行他炊。

排查過程

階段1: 懷疑是log4j2

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

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

image.png

發(fā)現(xiàn)打印到控制臺的這個(gè) appender 忘記注釋掉了盒件，所以我初步猜測是因?yàn)檫@個(gè)項(xiàng)目打印的日志過多蹬碧，而 log4j2 打印到控制臺是同步阻塞打印的，接下來炒刁，把線上所有機(jī)器的這行注釋掉恩沽，以為大功告成，沒想到切心，過不了幾天飒筑，5xx告警又來敲門了，看來绽昏，這個(gè)問題沒那么簡單。

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

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

image.png

在極短的時(shí)間內(nèi)爷贫，狂打 failed to allocate 64(bytes) of direct memory(...)日志（瞬間十幾個(gè)日志文件认然，每個(gè)日志文件幾百M(fèi)）补憾，日志里拋出一個(gè) netty 自己封裝的OutOfDirectMemoryError，說白了卷员，就是堆外內(nèi)存不夠用了盈匾，netty 一直在喊冤。

堆外內(nèi)存泄露毕骡，我去削饵，聽到這個(gè)名詞就有點(diǎn)沮喪，因?yàn)檫@個(gè)問題的排查就像 c 語言內(nèi)存泄露一樣難以排查未巫，首先想到的是窿撬，在 OOM 爆發(fā)之前，查看有無異常叙凡，然后查遍了 cat 上與機(jī)器相關(guān)的所有指標(biāo)劈伴，查遍了 OOM 日志之前的所有日志，均未發(fā)現(xiàn)任何異常握爷！這個(gè)時(shí)候心里開始罵了……

階段3：定位OOM源

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

image.png

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

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

image.png

果然航缀，在 netty 每次分配堆外內(nèi)存之前商架，都會(huì)計(jì)數(shù)，想到這芥玉，思路開始慢慢清晰起來蛇摸，心情也開始變好。

階段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)存已快超過上限，并且已經(jīng)知道 netty 底層是使用哪個(gè)字段來統(tǒng)計(jì)的砸烦，那么接下來要做的第一件事情弃鸦，就是反射拿到這個(gè)字段，然后我們自己統(tǒng)計(jì) netty 使用堆外內(nèi)存的情況幢痘。

image.png

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

image.png

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

因?yàn)椋ㄟ^我們前面的分析玄妈，在爆發(fā)大量 OOM 現(xiàn)象之前乾吻，沒有任何可疑的現(xiàn)象，那么只有兩種情況拟蜻，一種是突然某個(gè)瞬間分配了大量的堆外內(nèi)存導(dǎo)致OOM绎签，一種是堆外內(nèi)存緩慢增長，到達(dá)某個(gè)點(diǎn)之后酝锅，最后一根稻草將機(jī)器壓垮诡必。這段代碼加上去之后，打包上線搔扁。

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

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

image.png

沒過一會(huì)剖效，內(nèi)存就開始緩慢飆升嫉入，并且沒有釋放的跡象焰盗，20幾分鐘之后璧尸，內(nèi)存如下

image.png

到了這里，猜測可能是前面提到的第二種情況熬拒，也就是內(nèi)存緩慢增長造成的 OOM爷光，由于內(nèi)存實(shí)在增長太慢，于是調(diào)整機(jī)器負(fù)載權(quán)重為其他機(jī)器的兩倍澎粟，但是仍然是以幾K級別在增長蛀序，這天剛好是周五，索性就過他個(gè)一個(gè)周末再開看活烙。

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

image.png

果然不出所料回懦，內(nèi)存一直在緩慢增長气笙，一個(gè)周末的時(shí)間，堆外內(nèi)存已經(jīng)飆到快一個(gè) G 了怯晕，這個(gè)時(shí)候潜圃，我竟然想到了一句成語：只要功夫深，鐵杵磨成針舟茶！雖然堆外內(nèi)存幾個(gè)K幾個(gè)K的在增長谭期，但是只要一直持續(xù)下去，總有把內(nèi)存打爆的時(shí)候（線上堆外內(nèi)存上限設(shè)置的是2G）吧凉。

到了這里隧出，我又開始自問自答了：內(nèi)存為啥會(huì)緩慢增長，伴隨著什么而增長客燕？因?yàn)槲覀兊膽?yīng)用是面向用戶端的websocket鸳劳，那么，會(huì)不會(huì)是每一次有用戶進(jìn)來也搓，交互完之后赏廓，然后離開，內(nèi)存都會(huì)增長一些傍妒，然后不釋放呢幔摸？帶著這個(gè)疑問，我開始線下模擬颤练。

階段6：線下模擬

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

image.png

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

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

image.png

如上圖所示挪略，一次 connect 和 disconnect 為一次連接的建立與關(guān)閉，上圖綠色框框的日志分別是兩次連接的生命周期废酷。我們可以看到瘟檩，內(nèi)存每次都是在連接被關(guān)閉的的時(shí)候暴漲 256B 然后不釋放，到了這里澈蟆，問題進(jìn)一步縮小墨辛，肯定是連接被關(guān)閉的時(shí)候，觸發(fā)了框架的一個(gè)bug趴俘，這個(gè)bug在觸發(fā)之前分配了 256B 的內(nèi)存睹簇，然后bug觸發(fā)，內(nèi)存沒有釋放寥闪。問題縮小之后太惠，接下來開始擼源碼捉蟲！

階段7：線下排查

接下來疲憋，我將本地服務(wù)重啟凿渊，開始完整的線下排查過程。將目光定位到 netty-socketio 這個(gè)框架的 disconnect 事件（客戶端websocket連接關(guān)閉的時(shí)候回調(diào)用到這里）缚柳，基本上可以確定是在 disconnect 事件前后申請的內(nèi)存沒有釋放

image.png

這里埃脏，在使用 idea debug的時(shí)候，要選擇只掛起當(dāng)前線程秋忙，這樣我們在單步跟蹤的時(shí)候彩掐，控制臺仍然可以看到堆外內(nèi)存統(tǒng)計(jì)線程在打印日志。

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

image.png

debug 松掉之后，內(nèi)存立馬飆升了Ｒ粑濉惫撰！這個(gè)時(shí)候我已經(jīng)知道，這只臭蟲飛不了多遠(yuǎn)了躺涝。在 debug 的時(shí)候厨钻，掛起的是當(dāng)前線程，那么肯定是當(dāng)前線程某個(gè)地方申請了堆外內(nèi)存坚嗜，然后沒有釋放夯膀，接下來，快馬加鞭苍蔬，深入源碼诱建。

每一次單步調(diào)試，我都會(huì)觀察控制臺的內(nèi)存飆升的情況碟绑，很快俺猿，我們來到了這個(gè)地方

image.png

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

image.png

于是凯肋，bug的范圍進(jìn)一步縮小谊惭，我將本次程序跑完，釋然后客戶端再來一次連接侮东，斷點(diǎn)打在 client.send() 這行圈盔， 然后關(guān)閉客戶端連接，之后直接進(jìn)入到這個(gè)方法苗桂，隨后的過程有點(diǎn)長药磺，因?yàn)榕c netty 的時(shí)間傳播機(jī)制有關(guān)，這里就省略了煤伟，最后癌佩，我跟到了如下代碼木缝，handleWebsocket

image.png

在這個(gè)地方，我看了一處非澄д蓿可疑的地方我碟，在上圖的斷點(diǎn)上一行，調(diào)用 encoder 分配了一段內(nèi)存姚建，調(diào)用完之后矫俺，我們的控制臺立馬就彪了 256B，所以掸冤，我懷疑肯定是這里申請的內(nèi)存沒有釋放厘托，他這里接下來調(diào)用 encoder.encodePacket() 方法，猜想是把數(shù)據(jù)包的內(nèi)容以二進(jìn)制的方式寫到這段 256B的內(nèi)存稿湿，接下來铅匹，我跟到這段 encode 代碼，單步執(zhí)行之后饺藤，定位到這行代碼

image.png

這段代碼是把 packet 里面一個(gè)字段的值轉(zhuǎn)換為一個(gè) char包斑，然而，當(dāng)我使用 idea 預(yù)執(zhí)行的時(shí)候涕俗，卻拋出類一個(gè)憤怒的 NPEＢ薹帷！也就是說再姑，框架申請到一段內(nèi)存之后萌抵，在encoder的時(shí)候，自己GG了询刹，自己給自己挖了個(gè)NPE的深坑谜嫉，最后導(dǎo)致內(nèi)存無法釋放（最外層有堆外內(nèi)存釋放邏輯，現(xiàn)在無法執(zhí)行到了）凹联，然后越攢越多沐兰，越攢越多，直到最后一根稻草蔽挠，堆外內(nèi)存就這樣爆了住闯，這里的源碼有興趣的讀者可以自己去分析一下，限于篇幅原因澳淑，這里就不再分析了比原。

階段8：bug解決

bug既然已經(jīng)找到，接下來便要解決了杠巡，這里只需要解決這個(gè)NPE異常量窘，就可以fix掉，我們的目標(biāo)就是氢拥，讓這個(gè) subType 字段不為空蚌铜，我們先通過 idea 的線程調(diào)用棧定位到這個(gè) packet 是在哪個(gè)地方定義的

image.png

我們找到 idea 的 debugger 面板锨侯，眼睛盯著 packet 這個(gè)對象不放，然后上線移動(dòng)光標(biāo)冬殃，便光速定位到囚痴，原來，定義 packet 對象這個(gè)地方在我們前面的代碼其實(shí)已經(jīng)出現(xiàn)過审葬，我們查看了一下 subType 這個(gè)字段深滚，果然是null，接下來涣觉，解決bug很容易痴荐。

image.png

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

解決這個(gè)bug的過程是：將這個(gè)框架的源碼下載到本地昆汹，然后加上這一行，最后婴栽，我重新build一下满粗，pom 里改改名字，推送到我們公司的倉庫愚争，這樣映皆，我項(xiàng)目就可以直接使用了。

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

image.png

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

一切就緒之后，首先诚撵，我們來進(jìn)行本地驗(yàn)證缭裆，服務(wù)起起來之后，我瘋狂地建立連接寿烟，瘋狂地?cái)嚅_連接澈驼，觀察堆外內(nèi)存的情況

image.png

好家伙，不管你如何斷開連接筛武，堆外內(nèi)存一直不漲了缝其，至此购桑，bug 基本fix终娃，當(dāng)然屏积，最后一步，我們把代碼推到線上驗(yàn)證骇径。

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

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

image.png

發(fā)現(xiàn)過一段時(shí)間辉懒，堆外內(nèi)存已經(jīng)穩(wěn)定不漲了阳惹，我們的捉蟲之旅到此結(jié)束！最后眶俩，我來給本地捉蟲之旅做一次總結(jié)

總結(jié)

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

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

3.逐漸縮小范圍喇闸，直到bug被你找到。當(dāng)你確認(rèn)某個(gè)線程的執(zhí)行帶來 bug 的時(shí)候询件，可單步執(zhí)行燃乍，可二分執(zhí)行，定位到某行代碼之后宛琅，跟到這段代碼刻蟹，然后繼續(xù)單步執(zhí)行或者二分的方式來定位最終出 bug 的代碼，這個(gè)方法屢試不爽夯秃，最后總能找到bug座咆。

4.熟練掌握 idea 的調(diào)試，讓你的捉蟲速度快如閃電仓洼，這里介陶，最常見的調(diào)試方式是預(yù)執(zhí)行表達(dá)式，以及通過線程調(diào)用棧色建，死盯某個(gè)對象哺呜，就能夠掌握這個(gè)對象的定義，賦值之類箕戳。

最后某残，祝愿大家都能找到自己的 bug国撵！