文章详情

Netty堆外内存泄露排查盛宴

闪电侠 ·2018-10-18 19:10

导读

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

Netty 底层基于 JDK 的 NIO,我们为什么不直接基于 JDK 的 NIO 或者其他NIO框架:

  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 的口碑都要更好一些,因此选择这个框架作为底层核心。

诚然,任何开源框架都避免不了 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。

接下来,我们查看了 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 源码分析之服务端启动全解析



发现文章有错误、对内容有疑问,都可以关注美团技术团队微信公众号(meituantech),在后台给我们留言。我们每周会挑选出一位热心小伙伴,送上一份精美的小礼品。快来扫码关注我们吧!

关注我们

扫码关注技术博客

微信搜索 "美团技术团队"