背景
最近在做實(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_WAIT
和TIME_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