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

导读

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。

我们使用 Nginx 作为服务端 WebSocket 的七层负载，5xx的爆发通常表明服务端不可用。由于目前 Nginx 告警没有细分具体哪台机器不可用，接下来，我们就到 CAT（美团点评统一监控平台，目前已经开源）去检查一下整个集群的各项指标，就发现如下两个异常:

某台机器在同一时间点爆发 GC（垃圾回收），而且在同一时间，JVM 线程阻塞。

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

排查过程

阶段1: 怀疑是log4j2

因为线程被大量阻塞，我们首先想到的是定位哪些线程被阻塞，最后查出来是 Log4j2 狂打日志导致 Netty 的 NIO 线程阻塞（由于没有及时保留现场，所以截图缺失）。NIO 线程阻塞之后，因我们的服务器无法处理客户端的请求，所以对Nginx来说就是5xx。

接下来，我们查看了 Log4j2 的配置文件。

我们发现打印到控制台的这个 appender 忘记注释掉了，所以初步猜测：因为这个项目打印的日志过多，而 Log4j2 打印到控制台是同步阻塞打印的，所以就导致了这个问题。那么接下来，我们把线上所有机器的这行注释掉，本以为会“大功告成”，但没想到仅仅过了几天，5xx告警又来“敲门”。看来，这个问题并没我们最初想象的那么简单。

阶段2：可疑日志浮现

接下来，我们只能硬着头皮去查日志，特别是故障发生点前后的日志，于是又发现了一处可疑的地方：

可以看到：在极短的时间内，狂打 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 这个类里面。

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

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

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

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

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

堆外内存统计字段是 DIRECT_MEMORY_COUNTER，我们可以通过反射拿到这个字段，然后定期 Check 这个值，就可以监控 Netty 堆外内存的增长情况。

于是我们通过反射拿到这个字段，然后每隔一秒打印，为什么要这样做？

因为，通过我们前面的分析，在爆发大量 OOM 现象之前，没有任何可疑的现象。那么只有两种情况，一种是突然某个瞬间分配了大量的堆外内存导致OOM；一种是堆外内存缓慢增长，到达某个点之后，最后一根稻草将机器压垮。在这段代码加上去之后，我们打包上线。

阶段5：到底是缓慢增长还是瞬间飙升？

代码上线之后，初始内存为 16384k（16M），这是因为线上我们使用了池化堆外内存，默认一个 chunk 为16M，这里不必过于纠结。

但是没过一会，内存就开始缓慢飙升，并且没有释放的迹象，二十几分钟之后，内存使用情况如下：

走到这里，我们猜测可能是前面提到的第二种情况，也就是内存缓慢增长造成的 OOM，由于内存实在增长太慢，于是调整机器负载权重为其他机器的两倍，但是仍然是以数K级别在持续增长。那天刚好是周五，索性就过一个周末再开看。

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

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

此时，我们开始自问自答环节：内存为啥会缓慢增长，伴随着什么而增长？因为我们的应用是面向用户端的WebSocket，那么，会不会是每一次有用户进来，交互完之后离开，内存都会增长一些，然后不释放呢？带着这个疑问，我们开始了线下模拟过程。

阶段6：线下模拟

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

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

我们的模拟流程是：新建一个客户端链接->断开链接->再新建一个客户端链接->再断开链接。

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

阶段7：线下排查

接下来，我们将本地服务重启，开始完整的线下排查过程。同时将目光定位到 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的深坑，最后导致内存无法释放（最外层有堆外内存释放逻辑，现在无法执行到了）。而且越攒越多，直到被“最后一根稻草”压垮，堆外内存就这样爆了。这里的源码，有兴趣的读者可以自己去分析一下，限于篇幅原因，这里就不再展开叙述了。

阶段8：Bug解决

既然 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号，项目启动的前夕！

阶段9：线下验证

一切准备就绪之后，我们就来进行本地验证，在服务起来之后，我们疯狂地建立连接，疯狂地断开连接，并观察堆外内存的情况：

Bingo！不管我们如何断开连接，堆外内存不涨了。至此，Bug 基本 Fix，当然最后一步，我们把代码推到线上验证。

阶段10：线上验证

这次线上验证，我们避免了比较土的打日志方法，我们把堆外内存的这个指标“喷射”到 CAT 上，然后再来观察一段时间的堆外内存的情况：

过完一段时间，堆外内存已经稳定不涨了。此刻，我们的“捉虫之旅”到此结束。最后，我们还为大家做一个小小的总结，希望对您有所帮助。