Netty 是一个异步事件驱动的网络通讯层框架,用于快速开发高可用高性能的服务端网络框架与客户端程序,它极大地简化了 TCP 和 UDP 套接字服务器等网络编程。html
Netty 底层基于 JDK 的 NIO,咱们为何不直接基于 JDK 的 NIO 或者其余NIO框架:git
最近在作一个基于 Websocket 的长连中间件,服务端使用实现了 Socket.IO 协议(基于WebSocket协议,提供长轮询降级能力) 的 netty-socketio 框架,该框架为 Netty 实现,鉴于本人对 Netty 比较熟,而且对比一样实现了 Socket.IO 协议的其余框架,Netty 的口碑都要更好一些,所以选择这个框架做为底层核心。github
诚然,任何开源框架都避免不了 Bug 的存在,咱们在使用这个开源框架时,就遇到一个堆外内存泄露的 Bug。美团的价值观一直都是“追求卓越”,因此咱们就想挑战一下,找到那只臭虫(Bug),而本文就是遇到的问题以及排查的过程。固然,想看结论的同窗能够直接跳到最后,阅读总结便可。编程
某天早上,咱们忽然收到告警,Nginx 服务端出现大量5xx。浏览器
咱们使用 Nginx 做为服务端 WebSocket 的七层负载,5xx的爆发一般代表服务端不可用。因为目前 Nginx 告警没有细分具体哪台机器不可用,接下来,咱们就到 CAT(美团点评统一监控平台,目前已经开源)去检查一下整个集群的各项指标,就发现以下两个异常:服务器
某台机器在同一时间点爆发 GC(垃圾回收),并且在同一时间,JVM 线程阻塞。网络
接下来,咱们就就开始了漫长的堆外内存泄露“排查之旅”。并发
由于线程被大量阻塞,咱们首先想到的是定位哪些线程被阻塞,最后查出来是 Log4j2 狂打日志致使 Netty 的 NIO 线程阻塞(因为没有及时保留现场,因此截图缺失)。NIO 线程阻塞以后,因咱们的服务器没法处理客户端的请求,因此对Nginx来讲就是5xx。app
接下来,咱们查看了 Log4j2 的配置文件。框架
咱们发现打印到控制台的这个 appender 忘记注释掉了,因此初步猜想:由于这个项目打印的日志过多,而 Log4j2 打印到控制台是同步阻塞打印的,因此就致使了这个问题。那么接下来,咱们把线上全部机器的这行注释掉,本觉得会“大功告成”,但没想到仅仅过了几天,5xx告警又来“敲门”。看来,这个问题并没咱们最初想象的那么简单。
接下来,咱们只能硬着头皮去查日志,特别是故障发生点先后的日志,因而又发现了一处可疑的地方:
能够看到:在极短的时间内,狂打 failed to allocate 64(bytes) of direct memory(...)
日志(瞬间十几个日志文件,每一个日志文件几百M),日志里抛出一个 Netty 本身封装的 OutOfDirectMemoryError
。说白了,就是堆外内存不够用,Netty 一直在“喊冤”。
堆外内存泄露,听到这个名词就感到很沮丧。由于这个问题的排查就像 C 语言内存泄露同样难以排查,首先能想到的就是,在 OOM 爆发以前,查看有无异常。而后查遍了 CAT 上与机器相关的全部指标,查遍了 OOM 日志以前的全部日志,均未发现任何异常!这个时候内心已经“万马奔腾”了......
没办法,只能看着这堆讨厌的 OOM 日志发着呆,但愿答案可以“蹦到”眼前,可是那只是妄想。束手无策之际,忽然一道光在眼前一闪而过,在 OOM 下方的几行日志变得耀眼起来(为啥以前就没想认真查看日志?估计是被堆外内存泄露这几个词吓怕了吧 ==!),这几行字是 ....PlatformDepedeng.incrementMemory()...
。
原来,堆外内存是否够用,是 Netty 这边本身统计的,那么是否是能够找到统计代码,找到统计代码以后咱们就能够看到 Netty 里面的对外内存统计逻辑了?因而,接下来翻翻代码,找到这段逻辑,就在 PlatformDepedent
这个类里面。
这个地方,是一个对已使用堆外内存计数的操做,计数器为 DIRECT_MEMORY_COUNTER
,若是发现已使用内存大于堆外内存的上限(用户自行指定),就抛出一个自定义 OOM Error,异常里面的文本内容正是咱们在日志里面看到的。
接下来,就验证一下这个方法是不是在堆外内存分配的时候被调用。
果真,在 Netty 每次分配堆外内存以前,都会计数。想到这,思路就开始慢慢清晰,而心情也开始从“秋风瑟瑟”变成“春光明媚”。
CAT 上关于堆外内存的监控没有任何异常(应该是没有统计准确,一直维持在 1M),而这边咱们又确认堆外内存已快超过上限,而且已经知道 Netty 底层是使用的哪一个字段来统计。那么接下来要作的第一件事情,就是反射拿到这个字段,而后咱们本身统计 Netty 使用堆外内存的状况。
堆外内存统计字段是 DIRECT_MEMORY_COUNTER
,咱们能够经过反射拿到这个字段,而后按期 Check 这个值,就能够监控 Netty 堆外内存的增加状况。
因而咱们经过反射拿到这个字段,而后每隔一秒打印,为何要这样作?
由于,经过咱们前面的分析,在爆发大量 OOM 现象以前,没有任何可疑的现象。那么只有两种状况,一种是忽然某个瞬间分配了大量的堆外内存致使OOM;一种是堆外内存缓慢增加,到达某个点以后,最后一根稻草将机器压垮。在这段代码加上去以后,咱们打包上线。
代码上线以后,初始内存为 16384k(16M),这是由于线上咱们使用了池化堆外内存,默认一个 chunk 为16M,这里没必要过于纠结。
可是没过一会,内存就开始缓慢飙升,而且没有释放的迹象,二十几分钟以后,内存使用状况以下:
走到这里,咱们猜想多是前面提到的第二种状况,也就是内存缓慢增加形成的 OOM,因为内存实在增加太慢,因而调整机器负载权重为其余机器的两倍,可是仍然是以数K级别在持续增加。那天恰好是周五,索性就过一个周末再开看。
周末以后,咱们到公司第一时间就连上了跳板机,登陆线上机器,开始 tail -f 继续查看日志。在输完命令以后,怀着期待的心情重重的敲下了回车键:
果真不出所料,内存一直在缓慢增加,一个周末的时间,堆外内存已经飙到快一个 G 了。这个时候,我居然想到了一句成语:“只要功夫深,铁杵磨成针”。虽然堆外内存以几个K的速度在缓慢增加,可是只要一直持续下去,总有把内存打爆的时候(线上堆外内存上限设置的是2G)。
此时,咱们开始自问自答环节:内存为啥会缓慢增加,伴随着什么而增加?由于咱们的应用是面向用户端的WebSocket,那么,会不会是每一次有用户进来,交互完以后离开,内存都会增加一些,而后不释放呢?带着这个疑问,咱们开始了线下模拟过程。
本地起好服务,把监控堆外内存的单位改成以B为单位(由于本地流量较小,打算一次一个客户端链接),另外,本地也使用非池化内存(内存数字较小,容易看出问题),在服务端启动以后,控制台打印信息以下
在没有客户端接入的时候,堆外内存一直是0,在乎料之中。接下来,怀着着无比激动的心情,打开浏览器,而后输入网址,开始咱们的模拟之旅。
咱们的模拟流程是:新建一个客户端连接->断开连接->再新建一个客户端连接->再断开连接。
如上图所示,一次 Connect 和 Disconnect 为一次链接的创建与关闭,上图绿色框框的日志分别是两次链接的生命周期。咱们能够看到,内存每次都是在链接被关闭的的时候暴涨 256B,而后也不释放。走到这里,问题进一步缩小,确定是链接被关闭的时候,触发了框架的一个Bug,并且这个Bug在触发以前分配了 256B 的内存,随着Bug被触发,内存也没有释放。问题缩小以后,接下来开始“撸源码”,捉虫!
接下来,咱们将本地服务重启,开始完整的线下排查过程。同时将目光定位到 netty-socketio 这个框架的 Disconnect 事件(客户端WebSocket链接关闭时会调用到这里),基本上能够肯定,在 Disconnect 事件先后申请的内存并无释放。
在使用 idea debug 时,要选择只挂起当前线程,这样咱们在单步跟踪的时候,控制台仍然能够看到堆外内存统计线程在打印日志。
在客户端链接上以后而后关闭,断点进入到 onDisconnect
回调,咱们特地在此多停留了一会,发现控制台内存并无飙升(7B这个内存暂时没有去分析,只须要知道,客户端链接断开以后,咱们断点hold住,内存还未开始涨)。接下来,神奇的一幕出现了,咱们将断点放开,让程序跑完:
Debug 松掉以后,内存立马飙升了!!此时,咱们已经知道,这只“臭虫”飞不了多远了。在 Debug 时,挂起的是当前线程,那么确定是当前线程某个地方申请了堆外内存,而后没有释放,继续“马不停蹄“,深刻源码。
其实,每一次单步调试,咱们都会观察控制台的内存飙升的状况。很快,咱们来到了这个地方:
在这一行没执行以前,控制台的内存依然是 263B。而后,当执行完该行以后,马上从 263B涨到519B(涨了256B)。
因而,Bug 范围进一步缩小。咱们将本次程序跑完,释而后客户端再来一次链接,断点打在 client.send()
这行, 而后关闭客户端链接,以后直接进入到这个方法,随后的过程有点长,由于与 Netty 的时间传播机制有关,这里就省略了。最后,咱们跟踪到了以下代码,handleWebsocket
:
在这个地方,咱们看到一处很是可疑的地方,在上图的断点上一行,调用 encoder
分配了一段内存,调用完以后,咱们的控制台立马就彪了 256B。因此,咱们怀疑确定是这里申请的内存没有释放,它这里接下来调用 encoder.encodePacket()
方法,猜测是把数据包的内容以二进制的方式写到这段 256B的内存。接下来,咱们追踪到这段 encode 代码,单步执行以后,就定位到这行代码:
这段代码是把 packet 里面一个字段的值转换为一个 char。然而,当咱们使用 idea 预执行的时候,却抛出类一个愤怒的 NPE!!也就是说,框架申请到一段内存以后,在 encoder 的时候,本身 GG 了,还给本身挖了个NPE的深坑,最后致使内存没法释放(最外层有堆外内存释放逻辑,如今没法执行到了)。并且越攒越多,直到被“最后一根稻草”压垮,堆外内存就这样爆了。这里的源码,有兴趣的读者能够本身去分析一下,限于篇幅缘由,这里就再也不展开叙述了。
既然 Bug 已经找到,接下来就要解决问题了。这里只须要解决这个NPE异常,就能够 Fix 掉。咱们的目标就是,让这个 subType
字段不为空。因而咱们先经过 idea 的线程调用栈,定位到这个 packet 是在哪一个地方定义的:
咱们找到 idea 的 debugger 面板,眼睛盯着 packet 这个对象不放,而后上线移动光标,便光速定位到。原来,定义 packet 对象这个地方在咱们前面的代码其实已经出现过,咱们查看了一下 subType
这个字段,果真是 null。接下来,解决 Bug 就很容易了。
咱们给这个字段赋值便可,因为这里是链接关闭事件,因此咱们给他指定了一个名为 DISCONNECT 的字段(能够改天深刻去研究 Socket.IO 的协议),反正这个 Bug 是在链接关闭的时候触发的,就粗暴一点了 !
解决这个 Bug 的过程是:将这个框架的源码下载到本地,而后加上这一行,最后从新 Build一下,pom 里改了一下名字,推送到咱们公司的仓库。这样,项目就能够直接进行使用了。
改完 Bug 以后,习惯性地去 GitHub上找到引起这段 Bug 的 Commit:
好奇的是,为啥这位 dzn
commiter 会写出这么一段如此明显的 Bug,并且时间就在今年3月30号,项目启动的前夕!
一切准备就绪以后,咱们就来进行本地验证,在服务起来以后,咱们疯狂地创建链接,疯狂地断开链接,并观察堆外内存的状况:
Bingo!无论咱们如何断开链接,堆外内存不涨了。至此,Bug 基本 Fix,固然最后一步,咱们把代码推到线上验证。
此次线上验证,咱们避免了比较土的打日志方法,咱们把堆外内存的这个指标“喷射”到 CAT 上,而后再来观察一段时间的堆外内存的状况:
过完一段时间,堆外内存已经稳定不涨了。此刻,咱们的“捉虫之旅”到此结束。最后,咱们还为你们作一个小小的总结,但愿对您有所帮助。
最后,祝愿你们都能找到本身的“心仪已久” Bug!
闪电侠,2014年加入美团点评,主要负责美团点评移动端统一长连工做,欢迎同行进行技术交流。
目前咱们团队负责美团点评长连基础设施的建设,支持美团酒旅、外卖、到店、打车、金融等几乎公司全部业务的快速发展。加入咱们,你能够亲身体验到千万级在线链接、日吞吐百亿请求的场景,你会直面互联网高并发、高可用的挑战,有机会接触到 Netty 在长连领域的各个场景。咱们诚邀有激情、有想法、有经验、有能力的同窗,和咱们一块儿并肩奋斗!欢迎感兴趣的同窗投递简历至 chao.yu#dianping.com 咨询。