Netty堆外内存泄露排查与总结

导读

Netty 是一个异步事件驱动的网络通讯层框架,用于快速开发高可用高性能的服务端网络框架与客户端程序,它极大地简化了 TCP 和 UDP 套接字服务器等网络编程。html

Netty 底层基于 JDK 的 NIO,咱们为何不直接基于 JDK 的 NIO 或者其余NIO框架:git

  1. 使用 JDK 自带的 NIO 须要了解太多的概念,编程复杂。
  2. Netty 底层 IO 模型随意切换,而这一切只须要作微小的改动。
  3. Netty自带的拆包解包,异常检测等机制让咱们从 NIO 的繁重细节中脱离出来,只需关心业务逻辑便可。
  4. Netty解决了JDK 的不少包括空轮训在内的 Bug。
  5. Netty底层对线程,Selector 作了不少细小的优化,精心设计的 Reactor 线程作到很是高效的并发处理。
  6. 自带各类协议栈,让咱们处理任何一种通用协议都几乎不用亲自动手。
  7. Netty社区活跃,遇到问题随时邮件列表或者 issue。
  8. Netty已经历各大RPC框架(Dubbo),消息中间件(RocketMQ),大数据通讯(Hadoop)框架的普遍的线上验证,健壮性无比强大。

背景

最近在作一个基于 Websocket 的长连中间件,服务端使用实现了 Socket.IO 协议(基于WebSocket协议,提供长轮询降级能力) 的 netty-socketio 框架,该框架为 Netty 实现,鉴于本人对 Netty 比较熟,而且对比一样实现了 Socket.IO 协议的其余框架,Netty 的口碑都要更好一些,所以选择这个框架做为底层核心。github

诚然,任何开源框架都避免不了 Bug 的存在,咱们在使用这个开源框架时,就遇到一个堆外内存泄露的 Bug。美团的价值观一直都是“追求卓越”,因此咱们就想挑战一下,找到那只臭虫(Bug),而本文就是遇到的问题以及排查的过程。固然,想看结论的同窗能够直接跳到最后,阅读总结便可。编程

问题

某天早上,咱们忽然收到告警,Nginx 服务端出现大量5xx。浏览器

image.png

咱们使用 Nginx 做为服务端 WebSocket 的七层负载,5xx的爆发一般代表服务端不可用。因为目前 Nginx 告警没有细分具体哪台机器不可用,接下来,咱们就到 CAT(美团点评统一监控平台,目前已经开源)去检查一下整个集群的各项指标,就发现以下两个异常:服务器

image.png

某台机器在同一时间点爆发 GC(垃圾回收),并且在同一时间,JVM 线程阻塞。网络

image.png

接下来,咱们就就开始了漫长的堆外内存泄露“排查之旅”。并发

排查过程

阶段1: 怀疑是log4j2

由于线程被大量阻塞,咱们首先想到的是定位哪些线程被阻塞,最后查出来是 Log4j2 狂打日志致使 Netty 的 NIO 线程阻塞(因为没有及时保留现场,因此截图缺失)。NIO 线程阻塞以后,因咱们的服务器没法处理客户端的请求,因此对Nginx来讲就是5xx。app

接下来,咱们查看了 Log4j2 的配置文件。框架

image.png

咱们发现打印到控制台的这个 appender 忘记注释掉了,因此初步猜想:由于这个项目打印的日志过多,而 Log4j2 打印到控制台是同步阻塞打印的,因此就致使了这个问题。那么接下来,咱们把线上全部机器的这行注释掉,本觉得会“大功告成”,但没想到仅仅过了几天,5xx告警又来“敲门”。看来,这个问题并没咱们最初想象的那么简单。

阶段2:可疑日志浮现

接下来,咱们只能硬着头皮去查日志,特别是故障发生点先后的日志,因而又发现了一处可疑的地方:

image.png

能够看到:在极短的时间内,狂打 failed to allocate 64(bytes) of direct memory(...)日志(瞬间十几个日志文件,每一个日志文件几百M),日志里抛出一个 Netty 本身封装的 OutOfDirectMemoryError。说白了,就是堆外内存不够用,Netty 一直在“喊冤”。

堆外内存泄露,听到这个名词就感到很沮丧。由于这个问题的排查就像 C 语言内存泄露同样难以排查,首先能想到的就是,在 OOM 爆发以前,查看有无异常。而后查遍了 CAT 上与机器相关的全部指标,查遍了 OOM 日志以前的全部日志,均未发现任何异常!这个时候内心已经“万马奔腾”了......

阶段3:定位OOM源

没办法,只能看着这堆讨厌的 OOM 日志发着呆,但愿答案可以“蹦到”眼前,可是那只是妄想。束手无策之际,忽然一道光在眼前一闪而过,在 OOM 下方的几行日志变得耀眼起来(为啥以前就没想认真查看日志?估计是被堆外内存泄露这几个词吓怕了吧 ==!),这几行字是 ....PlatformDepedeng.incrementMemory()...

原来,堆外内存是否够用,是 Netty 这边本身统计的,那么是否是能够找到统计代码,找到统计代码以后咱们就能够看到 Netty 里面的对外内存统计逻辑了?因而,接下来翻翻代码,找到这段逻辑,就在 PlatformDepedent 这个类里面。

image.png

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

接下来,就验证一下这个方法是不是在堆外内存分配的时候被调用。

image.png

果真,在 Netty 每次分配堆外内存以前,都会计数。想到这,思路就开始慢慢清晰,而心情也开始从“秋风瑟瑟”变成“春光明媚”。

阶段4:反射进行堆外内存监控

CAT 上关于堆外内存的监控没有任何异常(应该是没有统计准确,一直维持在 1M),而这边咱们又确认堆外内存已快超过上限,而且已经知道 Netty 底层是使用的哪一个字段来统计。那么接下来要作的第一件事情,就是反射拿到这个字段,而后咱们本身统计 Netty 使用堆外内存的状况。

image.png

堆外内存统计字段是 DIRECT_MEMORY_COUNTER,咱们能够经过反射拿到这个字段,而后按期 Check 这个值,就能够监控 Netty 堆外内存的增加状况。

image.png

因而咱们经过反射拿到这个字段,而后每隔一秒打印,为何要这样作?

由于,经过咱们前面的分析,在爆发大量 OOM 现象以前,没有任何可疑的现象。那么只有两种状况,一种是忽然某个瞬间分配了大量的堆外内存致使OOM;一种是堆外内存缓慢增加,到达某个点以后,最后一根稻草将机器压垮。在这段代码加上去以后,咱们打包上线。

阶段5:究竟是缓慢增加仍是瞬间飙升?

代码上线以后,初始内存为 16384k(16M),这是由于线上咱们使用了池化堆外内存,默认一个 chunk 为16M,这里没必要过于纠结。

image.png

可是没过一会,内存就开始缓慢飙升,而且没有释放的迹象,二十几分钟以后,内存使用状况以下:

image.png

走到这里,咱们猜想多是前面提到的第二种状况,也就是内存缓慢增加形成的 OOM,因为内存实在增加太慢,因而调整机器负载权重为其余机器的两倍,可是仍然是以数K级别在持续增加。那天恰好是周五,索性就过一个周末再开看。

周末以后,咱们到公司第一时间就连上了跳板机,登陆线上机器,开始 tail -f 继续查看日志。在输完命令以后,怀着期待的心情重重的敲下了回车键:

image.png

果真不出所料,内存一直在缓慢增加,一个周末的时间,堆外内存已经飙到快一个 G 了。这个时候,我居然想到了一句成语:“只要功夫深,铁杵磨成针”。虽然堆外内存以几个K的速度在缓慢增加,可是只要一直持续下去,总有把内存打爆的时候(线上堆外内存上限设置的是2G)。

此时,咱们开始自问自答环节:内存为啥会缓慢增加,伴随着什么而增加?由于咱们的应用是面向用户端的WebSocket,那么,会不会是每一次有用户进来,交互完以后离开,内存都会增加一些,而后不释放呢?带着这个疑问,咱们开始了线下模拟过程。

阶段6:线下模拟

本地起好服务,把监控堆外内存的单位改成以B为单位(由于本地流量较小,打算一次一个客户端链接),另外,本地也使用非池化内存(内存数字较小,容易看出问题),在服务端启动以后,控制台打印信息以下

image.png

在没有客户端接入的时候,堆外内存一直是0,在乎料之中。接下来,怀着着无比激动的心情,打开浏览器,而后输入网址,开始咱们的模拟之旅。

咱们的模拟流程是:新建一个客户端连接->断开连接->再新建一个客户端连接->再断开连接。

image.png

如上图所示,一次 Connect 和 Disconnect 为一次链接的创建与关闭,上图绿色框框的日志分别是两次链接的生命周期。咱们能够看到,内存每次都是在链接被关闭的的时候暴涨 256B,而后也不释放。走到这里,问题进一步缩小,确定是链接被关闭的时候,触发了框架的一个Bug,并且这个Bug在触发以前分配了 256B 的内存,随着Bug被触发,内存也没有释放。问题缩小以后,接下来开始“撸源码”,捉虫!

阶段7:线下排查

接下来,咱们将本地服务重启,开始完整的线下排查过程。同时将目光定位到 netty-socketio 这个框架的 Disconnect 事件(客户端WebSocket链接关闭时会调用到这里),基本上能够肯定,在 Disconnect 事件先后申请的内存并无释放。

image.png

在使用 idea debug 时,要选择只挂起当前线程,这样咱们在单步跟踪的时候,控制台仍然能够看到堆外内存统计线程在打印日志。

在客户端链接上以后而后关闭,断点进入到 onDisconnect 回调,咱们特地在此多停留了一会,发现控制台内存并无飙升(7B这个内存暂时没有去分析,只须要知道,客户端链接断开以后,咱们断点hold住,内存还未开始涨)。接下来,神奇的一幕出现了,咱们将断点放开,让程序跑完:

image.png

Debug 松掉以后,内存立马飙升了!!此时,咱们已经知道,这只“臭虫”飞不了多远了。在 Debug 时,挂起的是当前线程,那么确定是当前线程某个地方申请了堆外内存,而后没有释放,继续“马不停蹄“,深刻源码。

其实,每一次单步调试,咱们都会观察控制台的内存飙升的状况。很快,咱们来到了这个地方:

image.png

在这一行没执行以前,控制台的内存依然是 263B。而后,当执行完该行以后,马上从 263B涨到519B(涨了256B)。

image.png

因而,Bug 范围进一步缩小。咱们将本次程序跑完,释而后客户端再来一次链接,断点打在 client.send() 这行, 而后关闭客户端链接,以后直接进入到这个方法,随后的过程有点长,由于与 Netty 的时间传播机制有关,这里就省略了。最后,咱们跟踪到了以下代码,handleWebsocket

image.png

在这个地方,咱们看到一处很是可疑的地方,在上图的断点上一行,调用 encoder 分配了一段内存,调用完以后,咱们的控制台立马就彪了 256B。因此,咱们怀疑确定是这里申请的内存没有释放,它这里接下来调用 encoder.encodePacket() 方法,猜测是把数据包的内容以二进制的方式写到这段 256B的内存。接下来,咱们追踪到这段 encode 代码,单步执行以后,就定位到这行代码:

image.png

这段代码是把 packet 里面一个字段的值转换为一个 char。然而,当咱们使用 idea 预执行的时候,却抛出类一个愤怒的 NPE!!也就是说,框架申请到一段内存以后,在 encoder 的时候,本身 GG 了,还给本身挖了个NPE的深坑,最后致使内存没法释放(最外层有堆外内存释放逻辑,如今没法执行到了)。并且越攒越多,直到被“最后一根稻草”压垮,堆外内存就这样爆了。这里的源码,有兴趣的读者能够本身去分析一下,限于篇幅缘由,这里就再也不展开叙述了。

阶段8:Bug解决

既然 Bug 已经找到,接下来就要解决问题了。这里只须要解决这个NPE异常,就能够 Fix 掉。咱们的目标就是,让这个 subType 字段不为空。因而咱们先经过 idea 的线程调用栈,定位到这个 packet 是在哪一个地方定义的:

image.png

咱们找到 idea 的 debugger 面板,眼睛盯着 packet 这个对象不放,而后上线移动光标,便光速定位到。原来,定义 packet 对象这个地方在咱们前面的代码其实已经出现过,咱们查看了一下 subType 这个字段,果真是 null。接下来,解决 Bug 就很容易了。

image.png

咱们给这个字段赋值便可,因为这里是链接关闭事件,因此咱们给他指定了一个名为 DISCONNECT 的字段(能够改天深刻去研究 Socket.IO 的协议),反正这个 Bug 是在链接关闭的时候触发的,就粗暴一点了 !

解决这个 Bug 的过程是:将这个框架的源码下载到本地,而后加上这一行,最后从新 Build一下,pom 里改了一下名字,推送到咱们公司的仓库。这样,项目就能够直接进行使用了。

改完 Bug 以后,习惯性地去 GitHub上找到引起这段 Bug 的 Commit:
image.png
好奇的是,为啥这位 dzn commiter 会写出这么一段如此明显的 Bug,并且时间就在今年3月30号,项目启动的前夕!

阶段9:线下验证

一切准备就绪以后,咱们就来进行本地验证,在服务起来以后,咱们疯狂地创建链接,疯狂地断开链接,并观察堆外内存的状况:

image.png

Bingo!无论咱们如何断开链接,堆外内存不涨了。至此,Bug 基本 Fix,固然最后一步,咱们把代码推到线上验证。

阶段10:线上验证

此次线上验证,咱们避免了比较土的打日志方法,咱们把堆外内存的这个指标“喷射”到 CAT 上,而后再来观察一段时间的堆外内存的状况:

image.png

过完一段时间,堆外内存已经稳定不涨了。此刻,咱们的“捉虫之旅”到此结束。最后,咱们还为你们作一个小小的总结,但愿对您有所帮助。

总结

  1. 遇到堆外内存泄露不要怕,仔细耐心分析,总能找到思路,要多看日志,多分析。
  2. 若是使用了 Netty 堆外内存,那么能够自行监控堆外内存的使用状况,不须要借助第三方工具,咱们是使用的“反射”拿到的堆外内存的状况。
  3. 逐渐缩小范围,直到 Bug 被找到。当咱们确认某个线程的执行带来 Bug 时,可单步执行,可二分执行,定位到某行代码以后,跟到这段代码,而后继续单步执行或者二分的方式来定位最终出 Bug 的代码。这个方法屡试不爽,最后总能找到想要的 Bug。
  4. 熟练掌握 idea 的调试,让咱们的“捉虫”速度快如闪电(“闪电侠”就是这么来的)。这里,最多见的调试方式是预执行表达式,以及经过线程调用栈,死盯某个对象,就可以掌握这个对象的定义、赋值之类。

最后,祝愿你们都能找到本身的“心仪已久” Bug!

做者简介

闪电侠,2014年加入美团点评,主要负责美团点评移动端统一长连工做,欢迎同行进行技术交流。

招聘

目前咱们团队负责美团点评长连基础设施的建设,支持美团酒旅、外卖、到店、打车、金融等几乎公司全部业务的快速发展。加入咱们,你能够亲身体验到千万级在线链接、日吞吐百亿请求的场景,你会直面互联网高并发、高可用的挑战,有机会接触到 Netty 在长连领域的各个场景。咱们诚邀有激情、有想法、有经验、有能力的同窗,和咱们一块儿并肩奋斗!欢迎感兴趣的同窗投递简历至 chao.yu#dianping.com 咨询。

参考文献

  1. Netty 是什么
  2. Netty 源码分析之服务端启动全解析

相关文章
相关标签/搜索