Netty OutOfDirectMemoryError捉臭蟲(bug)之旅

背景

最近在做實(shí)時(shí)推薦項(xiàng)目舷蒲,上線運(yùn)行幾天后發(fā)現(xiàn)部分服務(wù)器不可用腐缤,經(jīng)過對(duì)日志分析發(fā)現(xiàn)一個(gè)關(guān)于Netty的堆外內(nèi)存錯(cuò)誤日志:

io.netty.util.internal.OutOfDirectMemoryError: failed to allocate 16777216 byte(s) of direct memory (used: 520093703, max: 536870912)
        at io.netty.util.internal.PlatformDependent.incrementMemoryCounter(PlatformDependent.java:592)
        at io.netty.util.internal.PlatformDependent.allocateDirectNoCleaner(PlatformDependent.java:546)
        at io.netty.buffer.PoolArena$DirectArena.allocateDirect(PoolArena.java:699)
        at io.netty.buffer.PoolArena$DirectArena.newChunk(PoolArena.java:688)
        at io.netty.buffer.PoolArena.allocateNormal(PoolArena.java:237)
        at io.netty.buffer.PoolArena.allocate(PoolArena.java:213)
        at io.netty.buffer.PoolArena.allocate(PoolArena.java:141)
        at io.netty.buffer.PooledByteBufAllocator.newDirectBuffer(PooledByteBufAllocator.java:262)
        at io.netty.buffer.AbstractByteBufAllocator.directBuffer(AbstractByteBufAllocator.java:179)
        at io.netty.buffer.AbstractByteBufAllocator.directBuffer(AbstractByteBufAllocator.java:170)
        at io.netty.buffer.AbstractByteBufAllocator.ioBuffer(AbstractByteBufAllocator.java:131)
        at io.netty.channel.DefaultMaxMessagesRecvByteBufAllocator$MaxMessageHandle.allocate(DefaultMaxMessagesRecvByteBufAllocator.java:73)
        at io.netty.channel.nio.AbstractNioByteChannel$NioByteUnsafe.read(AbstractNioByteChannel.java:111)
        at io.netty.channel.nio.NioEventLoop.processSelectedKey(NioEventLoop.java:563)
        at io.netty.channel.nio.NioEventLoop.processSelectedKeysOptimized(NioEventLoop.java:504)
        at io.netty.channel.nio.NioEventLoop.processSelectedKeys(NioEventLoop.java:418)
        at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:390)
        at io.netty.util.concurrent.SingleThreadEventExecutor$5.run(SingleThreadEventExecutor.java:742)
        at io.netty.util.concurrent.DefaultThreadFactory$DefaultRunnableDecorator.run(DefaultThreadFactory.java:145)
        at java.lang.Thread.run(Thread.java:745)

因?yàn)轫?xiàng)目中有一個(gè)定時(shí)任務(wù)每個(gè)一段時(shí)間會(huì)加載一些靜態(tài)數(shù)據(jù)巧颈,當(dāng)時(shí)以為是java內(nèi)存不足導(dǎo)致的谍椅,沒有具體的去分析為什么會(huì)拋OutOfDirectMemoryError(堆外內(nèi)存溢出)滚澜,總覺得是內(nèi)存不足八酒。調(diào)整內(nèi)存后重新上線。清明節(jié)后第一天早上習(xí)慣性的打開服務(wù)器查看運(yùn)行情況锅铅,結(jié)果發(fā)現(xiàn)部分服務(wù)器又出現(xiàn)這個(gè)問題酪呻。先是查看了服務(wù)器相關(guān)配置。

從服務(wù)器上下載了一份dump文件盐须,分析一波內(nèi)存使用情況:

發(fā)現(xiàn)靜態(tài)數(shù)據(jù)實(shí)例對(duì)象占用內(nèi)存很大玩荠,同時(shí)定時(shí)任務(wù)在加載靜態(tài)數(shù)據(jù)時(shí)會(huì)導(dǎo)致Survivor區(qū)內(nèi)存飆升,Survivor區(qū)默認(rèn)占年輕代20%的內(nèi)存贼邓。
是不是因?yàn)橥粋€(gè)時(shí)間點(diǎn)查讀數(shù)據(jù)庫數(shù)據(jù)量太大導(dǎo)致的內(nèi)存溢出阶冈?把定時(shí)任務(wù)拆分成多個(gè),分不同時(shí)間段加載數(shù)據(jù)來降低Survior使用率塑径,重新上線部署女坑。

Survivor區(qū)優(yōu)化前后內(nèi)存使用率對(duì)比圖:

從對(duì)比圖上看還是有明顯性能提升的。

本以為已經(jīng)解決了這個(gè)問題统舀,在線上運(yùn)行幾天后又出現(xiàn)上面的問題匆骗;心頭一涼劳景,意識(shí)到這個(gè)問題沒這么簡單,靜下心開啟漫長的捉臭蟲(bug)之旅碉就。盟广。。心想項(xiàng)目里沒有明確使用netty瓮钥,會(huì)不會(huì)是引用的maven包有依賴netty jar包筋量?帶著這個(gè)疑問搜了一下pom文件依賴,果然:

終于有些頭緒了骏庸,然后重新打開日志毛甲,看著這堆討厭的 OOM 日志發(fā)著呆,突然一道光在眼前一閃而過具被,在 OOM 下方的幾行日志變得耀眼起來:

這幾行字是 ....PlatformDepedeng.incrementMemory()...玻募。我去,原來一姿,堆外內(nèi)存是否夠用七咧,是 netty 這邊自己統(tǒng)計(jì)的,那是不是可以找到統(tǒng)計(jì)代碼叮叹,找到統(tǒng)計(jì)代碼之后我們就可以看到 netty 里面的對(duì)外內(nèi)存統(tǒng)計(jì)邏輯了艾栋?于是,接下來翻翻代碼,找到這段邏輯,在 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>

接下來扣猫,從pom文件中看是hadoop-hdfs這個(gè)依賴包下使用了Netty,而HDFS是在加載模型時(shí)使用的翘地。有些興奮申尤,懷疑是模型SDK項(xiàng)目有問題,但是沒有依據(jù)也不好質(zhì)疑同事的項(xiàng)目衙耕;總感覺前面漏掉了什么細(xì)節(jié)昧穿,重新打開dump文件,哈哈哈 發(fā)現(xiàn)了另一個(gè)細(xì)節(jié):


TreeNode節(jié)點(diǎn)數(shù)800多萬(驚悚臉)橙喘,絕逼就問題时鸵。和算法同事確認(rèn),一個(gè)模型的節(jié)點(diǎn)數(shù)最多也就幾萬渴杆。會(huì)不會(huì)是每次加載模型后之前的節(jié)點(diǎn)沒有得到及時(shí)釋放才導(dǎo)致直接內(nèi)存溢出的寥枝?更加堅(jiān)定了我的之前的想法。接著磁奖,打開一臺(tái)服務(wù)器抱著試試的心態(tài)囊拜,敲下一行命令:


什么鬼,為什么TCP鏈接數(shù)這么高比搭,而且每個(gè)TCP都是CLOSE_WAIT狀態(tài)冠跷。把這個(gè)問題反饋給同事的同時(shí)我研究了一下TCP/IP協(xié)議。

簡單介紹TCP/IP協(xié)議:

引用https://www.cnblogs.com/sunxucool/p/3449068.html 這個(gè)博主的文章:

如果你使用的是HttpClient并且你遇到了大量CLOSE_WAIT的情況身诺,那么這篇日志也許對(duì)你有用:http://blog.csdn.net/shootyou/article/details/6615051
在那邊日志里頭舉了個(gè)場景蜜托,來說明CLOSE_WAITTIME_WAIT的區(qū)別,這里重新描述一下:
服務(wù)器A是一臺(tái)爬蟲服務(wù)器霉赡,它使用簡單的HttpClient去請(qǐng)求資源服務(wù)器B上面的apache獲取文件資源橄务,正常情況下,如果請(qǐng)求成功穴亏,那么在抓取完 資源后蜂挪,服務(wù)器A會(huì)主動(dòng)發(fā)出關(guān)閉連接的請(qǐng)求,這個(gè)時(shí)候就是主動(dòng)關(guān)閉連接嗓化,服務(wù)器A的連接狀態(tài)我們可以看到是TIME_WAIT棠涮。如果一旦發(fā)生異常呢?假設(shè) 請(qǐng)求的資源服務(wù)器B上并不存在刺覆,那么這個(gè)時(shí)候就會(huì)由服務(wù)器B發(fā)出關(guān)閉連接的請(qǐng)求严肪,服務(wù)器A就是被動(dòng)的關(guān)閉了連接,如果服務(wù)器A被動(dòng)關(guān)閉連接之后程序員忘了 讓HttpClient釋放連接谦屑,那就會(huì)造成CLOSE_WAIT的狀態(tài)了驳糯。

所以如果將大量CLOSE_WAIT的解決辦法總結(jié)為一句話那就是:查代碼。因?yàn)閱栴}出在服務(wù)器程序里頭啊伦仍。

到這里已經(jīng)基本確定是模型SDK的問題了结窘,接著同事幫忙開通了模型SDK項(xiàng)目的權(quán)限,開啟長途漫漫的模型SDK分析之旅充蓝。沿著上面的思路隧枫,應(yīng)該是請(qǐng)求HDFS加載模型這個(gè)環(huán)節(jié)有問題,找到相關(guān)代碼后對(duì)著電腦發(fā)呆谓苟,突然眼前劃過一道閃電官脓,仿佛看到了希望。


FSDataInputStream在讀取完數(shù)據(jù)后IO流沒有關(guān)閉涝焙,應(yīng)該就是這個(gè)問題了卑笨,哈哈哈。把問題反饋給負(fù)責(zé)模型SDK的同事之后仑撞,修復(fù)了bug赤兴,然后重新上線妖滔。

觀察TCP數(shù)量

完美解決。桶良。座舍。

參考資料:
http://www.bubuko.com/infodetail-2593976.html
https://www.cnblogs.com/sunxucool/p/3449068.html
https://www.cnblogs.com/dukuan/p/8178728.html

最后編輯于
?著作權(quán)歸作者所有,轉(zhuǎn)載或內(nèi)容合作請(qǐng)聯(lián)系作者
  • 序言:七十年代末,一起剝皮案震驚了整個(gè)濱河市陨帆,隨后出現(xiàn)的幾起案子曲秉,更是在濱河造成了極大的恐慌,老刑警劉巖疲牵,帶你破解...
    沈念sama閱讀 221,576評(píng)論 6 515
  • 序言:濱河連續(xù)發(fā)生了三起死亡事件承二,死亡現(xiàn)場離奇詭異,居然都是意外死亡纲爸,警方通過查閱死者的電腦和手機(jī)亥鸠,發(fā)現(xiàn)死者居然都...
    沈念sama閱讀 94,515評(píng)論 3 399
  • 文/潘曉璐 我一進(jìn)店門,熙熙樓的掌柜王于貴愁眉苦臉地迎上來缩焦,“玉大人读虏,你說我怎么就攤上這事≡模” “怎么了盖桥?”我有些...
    開封第一講書人閱讀 168,017評(píng)論 0 360
  • 文/不壞的土叔 我叫張陵,是天一觀的道長题翻。 經(jīng)常有香客問我揩徊,道長,這世上最難降的妖魔是什么嵌赠? 我笑而不...
    開封第一講書人閱讀 59,626評(píng)論 1 296
  • 正文 為了忘掉前任塑荒,我火速辦了婚禮,結(jié)果婚禮上姜挺,老公的妹妹穿的比我還像新娘齿税。我一直安慰自己,他們只是感情好炊豪,可當(dāng)我...
    茶點(diǎn)故事閱讀 68,625評(píng)論 6 397
  • 文/花漫 我一把揭開白布凌箕。 她就那樣靜靜地躺著,像睡著了一般词渤。 火紅的嫁衣襯著肌膚如雪牵舱。 梳的紋絲不亂的頭發(fā)上,一...
    開封第一講書人閱讀 52,255評(píng)論 1 308
  • 那天缺虐,我揣著相機(jī)與錄音芜壁,去河邊找鬼。 笑死,一個(gè)胖子當(dāng)著我的面吹牛慧妄,可吹牛的內(nèi)容都是我干的顷牌。 我是一名探鬼主播,決...
    沈念sama閱讀 40,825評(píng)論 3 421
  • 文/蒼蘭香墨 我猛地睜開眼塞淹,長吁一口氣:“原來是場噩夢(mèng)啊……” “哼韧掩!你這毒婦竟也來了?” 一聲冷哼從身側(cè)響起窖铡,我...
    開封第一講書人閱讀 39,729評(píng)論 0 276
  • 序言:老撾萬榮一對(duì)情侶失蹤,失蹤者是張志新(化名)和其女友劉穎坊谁,沒想到半個(gè)月后费彼,有當(dāng)?shù)厝嗽跇淞掷锇l(fā)現(xiàn)了一具尸體,經(jīng)...
    沈念sama閱讀 46,271評(píng)論 1 320
  • 正文 獨(dú)居荒郊野嶺守林人離奇死亡口芍,尸身上長有42處帶血的膿包…… 初始之章·張勛 以下內(nèi)容為張勛視角 年9月15日...
    茶點(diǎn)故事閱讀 38,363評(píng)論 3 340
  • 正文 我和宋清朗相戀三年箍铲,在試婚紗的時(shí)候發(fā)現(xiàn)自己被綠了。 大學(xué)時(shí)的朋友給我發(fā)了我未婚夫和他白月光在一起吃飯的照片鬓椭。...
    茶點(diǎn)故事閱讀 40,498評(píng)論 1 352
  • 序言:一個(gè)原本活蹦亂跳的男人離奇死亡颠猴,死狀恐怖,靈堂內(nèi)的尸體忽然破棺而出小染,到底是詐尸還是另有隱情翘瓮,我是刑警寧澤,帶...
    沈念sama閱讀 36,183評(píng)論 5 350
  • 正文 年R本政府宣布裤翩,位于F島的核電站资盅,受9級(jí)特大地震影響,放射性物質(zhì)發(fā)生泄漏踊赠。R本人自食惡果不足惜呵扛,卻給世界環(huán)境...
    茶點(diǎn)故事閱讀 41,867評(píng)論 3 333
  • 文/蒙蒙 一、第九天 我趴在偏房一處隱蔽的房頂上張望筐带。 院中可真熱鬧今穿,春花似錦、人聲如沸伦籍。這莊子的主人今日做“春日...
    開封第一講書人閱讀 32,338評(píng)論 0 24
  • 文/蒼蘭香墨 我抬頭看了看天上的太陽鸽斟。三九已至拔创,卻和暖如春,著一層夾襖步出監(jiān)牢的瞬間富蓄,已是汗流浹背剩燥。 一陣腳步聲響...
    開封第一講書人閱讀 33,458評(píng)論 1 272
  • 我被黑心中介騙來泰國打工, 沒想到剛下飛機(jī)就差點(diǎn)兒被人妖公主榨干…… 1. 我叫王不留,地道東北人灭红。 一個(gè)月前我還...
    沈念sama閱讀 48,906評(píng)論 3 376
  • 正文 我出身青樓侣滩,卻偏偏與公主長得像,于是被迫代替她去往敵國和親变擒。 傳聞我的和親對(duì)象是個(gè)殘疾皇子君珠,可洞房花燭夜當(dāng)晚...
    茶點(diǎn)故事閱讀 45,507評(píng)論 2 359