Netty OutOfDirectMemoryError捉臭虫(bug)之旅

背景

最近在做实时推荐项目,上线运行几天后发现部分服务器不可用,经过对日志分析发现一个关于Netty的堆外内存错误日志:

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)

因为项目中有一个定时任务每个一段时间会加载一些静态数据,当时以为是java内存不足导致的,没有具体的去分析为什么会抛OutOfDirectMemoryError(堆外内存溢出),总觉得是内存不足。调整内存后重新上线。清明节后第一天早上习惯性的打开服务器查看运行情况,结果发现部分服务器又出现这个问题。先是查看了服务器相关配置。

从服务器上下载了一份dump文件,分析一波内存使用情况:

发现静态数据实例对象占用内存很大,同时定时任务在加载静态数据时会导致Survivor区内存飙升,Survivor区默认占年轻代20%的内存。
是不是因为同一个时间点查读数据库数据量太大导致的内存溢出?把定时任务拆分成多个,分不同时间段加载数据来降低Survior使用率,重新上线部署。

Survivor区优化前后内存使用率对比图:

从对比图上看还是有明显性能提升的。

本以为已经解决了这个问题,在线上运行几天后又出现上面的问题;心头一凉,意识到这个问题没这么简单,静下心开启漫长的捉臭虫(bug)之旅。。。心想项目里没有明确使用netty,会不会是引用的maven包有依赖netty jar包?带着这个疑问搜了一下pom文件依赖,果然:

终于有些头绪了,然后重新打开日志,看着这堆讨厌的 OOM 日志发着呆,突然一道光在眼前一闪而过,在 OOM 下方的几行日志变得耀眼起来:

这几行字是 ....PlatformDepedeng.incrementMemory()...。我去,原来,堆外内存是否够用,是 netty 这边自己统计的,那是不是可以找到统计代码,找到统计代码之后我们就可以看到 netty 里面的对外内存统计逻辑了?于是,接下来翻翻代码,找到这段逻辑,在 PlatformDepedent 这个类里面


这个地方,是一个对已使用堆外内存计数的操作,计数器为DIRECT_MEMORY_COUNTER,如果发现已使用内存大于堆外内存的上限(用户自行指定),就抛出一个自定义 OOM Error,异常里面的文本内容正是我们在日志里面看到的。

接下来,从pom文件中看是hadoop-hdfs这个依赖包下使用了Netty,而HDFS是在加载模型时使用的。有些兴奋,怀疑是模型SDK项目有问题,但是没有依据也不好质疑同事的项目;总感觉前面漏掉了什么细节,重新打开dump文件,哈哈哈 发现了另一个细节:


TreeNode节点数800多万(惊悚脸),绝逼就问题。和算法同事确认,一个模型的节点数最多也就几万。会不会是每次加载模型后之前的节点没有得到及时释放才导致直接内存溢出的?更加坚定了我的之前的想法。接着,打开一台服务器抱着试试的心态,敲下一行命令:


什么鬼,为什么TCP链接数这么高,而且每个TCP都是CLOSE_WAIT状态。把这个问题反馈给同事的同时我研究了一下TCP/IP协议。

简单介绍TCP/IP协议:

引用https://www.cnblogs.com/sunxucool/p/3449068.html 这个博主的文章:

如果你使用的是HttpClient并且你遇到了大量CLOSE_WAIT的情况,那么这篇日志也许对你有用:http://blog.csdn.net/shootyou/article/details/6615051
在那边日志里头举了个场景,来说明CLOSE_WAITTIME_WAIT的区别,这里重新描述一下:
服务器A是一台爬虫服务器,它使用简单的HttpClient去请求资源服务器B上面的apache获取文件资源,正常情况下,如果请求成功,那么在抓取完 资源后,服务器A会主动发出关闭连接的请求,这个时候就是主动关闭连接,服务器A的连接状态我们可以看到是TIME_WAIT。如果一旦发生异常呢?假设 请求的资源服务器B上并不存在,那么这个时候就会由服务器B发出关闭连接的请求,服务器A就是被动的关闭了连接,如果服务器A被动关闭连接之后程序员忘了 让HttpClient释放连接,那就会造成CLOSE_WAIT的状态了。

所以如果将大量CLOSE_WAIT的解决办法总结为一句话那就是:查代码。因为问题出在服务器程序里头啊。

到这里已经基本确定是模型SDK的问题了,接着同事帮忙开通了模型SDK项目的权限,开启长途漫漫的模型SDK分析之旅。沿着上面的思路,应该是请求HDFS加载模型这个环节有问题,找到相关代码后对着电脑发呆,突然眼前划过一道闪电,仿佛看到了希望。


FSDataInputStream在读取完数据后IO流没有关闭,应该就是这个问题了,哈哈哈。把问题反馈给负责模型SDK的同事之后,修复了bug,然后重新上线。

观察TCP数量

完美解决。。。

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

最后编辑于
©著作权归作者所有,转载或内容合作请联系作者
  • 序言:七十年代末,一起剥皮案震惊了整个滨河市,随后出现的几起案子,更是在滨河造成了极大的恐慌,老刑警刘岩,带你破解...
    沈念sama阅读 215,076评论 6 497
  • 序言:滨河连续发生了三起死亡事件,死亡现场离奇诡异,居然都是意外死亡,警方通过查阅死者的电脑和手机,发现死者居然都...
    沈念sama阅读 91,658评论 3 389
  • 文/潘晓璐 我一进店门,熙熙楼的掌柜王于贵愁眉苦脸地迎上来,“玉大人,你说我怎么就摊上这事。” “怎么了?”我有些...
    开封第一讲书人阅读 160,732评论 0 350
  • 文/不坏的土叔 我叫张陵,是天一观的道长。 经常有香客问我,道长,这世上最难降的妖魔是什么? 我笑而不...
    开封第一讲书人阅读 57,493评论 1 288
  • 正文 为了忘掉前任,我火速办了婚礼,结果婚礼上,老公的妹妹穿的比我还像新娘。我一直安慰自己,他们只是感情好,可当我...
    茶点故事阅读 66,591评论 6 386
  • 文/花漫 我一把揭开白布。 她就那样静静地躺着,像睡着了一般。 火红的嫁衣衬着肌肤如雪。 梳的纹丝不乱的头发上,一...
    开封第一讲书人阅读 50,598评论 1 293
  • 那天,我揣着相机与录音,去河边找鬼。 笑死,一个胖子当着我的面吹牛,可吹牛的内容都是我干的。 我是一名探鬼主播,决...
    沈念sama阅读 39,601评论 3 415
  • 文/苍兰香墨 我猛地睁开眼,长吁一口气:“原来是场噩梦啊……” “哼!你这毒妇竟也来了?” 一声冷哼从身侧响起,我...
    开封第一讲书人阅读 38,348评论 0 270
  • 序言:老挝万荣一对情侣失踪,失踪者是张志新(化名)和其女友刘颖,没想到半个月后,有当地人在树林里发现了一具尸体,经...
    沈念sama阅读 44,797评论 1 307
  • 正文 独居荒郊野岭守林人离奇死亡,尸身上长有42处带血的脓包…… 初始之章·张勋 以下内容为张勋视角 年9月15日...
    茶点故事阅读 37,114评论 2 330
  • 正文 我和宋清朗相恋三年,在试婚纱的时候发现自己被绿了。 大学时的朋友给我发了我未婚夫和他白月光在一起吃饭的照片。...
    茶点故事阅读 39,278评论 1 344
  • 序言:一个原本活蹦乱跳的男人离奇死亡,死状恐怖,灵堂内的尸体忽然破棺而出,到底是诈尸还是另有隐情,我是刑警宁泽,带...
    沈念sama阅读 34,953评论 5 339
  • 正文 年R本政府宣布,位于F岛的核电站,受9级特大地震影响,放射性物质发生泄漏。R本人自食恶果不足惜,却给世界环境...
    茶点故事阅读 40,585评论 3 322
  • 文/蒙蒙 一、第九天 我趴在偏房一处隐蔽的房顶上张望。 院中可真热闹,春花似锦、人声如沸。这庄子的主人今日做“春日...
    开封第一讲书人阅读 31,202评论 0 21
  • 文/苍兰香墨 我抬头看了看天上的太阳。三九已至,却和暖如春,着一层夹袄步出监牢的瞬间,已是汗流浃背。 一阵脚步声响...
    开封第一讲书人阅读 32,442评论 1 268
  • 我被黑心中介骗来泰国打工, 没想到刚下飞机就差点儿被人妖公主榨干…… 1. 我叫王不留,地道东北人。 一个月前我还...
    沈念sama阅读 47,180评论 2 367
  • 正文 我出身青楼,却偏偏与公主长得像,于是被迫代替她去往敌国和亲。 传闻我的和亲对象是个残疾皇子,可洞房花烛夜当晚...
    茶点故事阅读 44,139评论 2 352