Netty堆外内存泄露排查盛宴
[TOC]
原文链接：Netty堆外内存泄露排查盛宴
1. 导读
Netty 是一个异步事件驱动的网络通信层框架，用于快速开发高可用高性能的服务端网络框架与客户端程序，它极大地简化了 TCP 和 UDP 套接字服务器等网络编程。
Netty 底层基于 JDK 的 NIO，我们为什么不直接基于 JDK 的 NIO 或者其他NIO框架：
使用 JDK 自带的 NIO 需要了解太多的概念，编程复杂。
Netty 底层 IO 模型随意切换，而这一切只需要做微小的改动。
Netty自带的拆包解包，异常检测等机制让我们从 NIO 的繁重细节中脱离出来，只需关心业务逻辑即可。
Netty解决了JDK 的很多包括空轮训在内的 Bug。
Netty底层对线程，Selector 做了很多细小的优化，精心设计的 Reactor 线程做到非常高效的并发处理。
自带各种协议栈，让我们处理任何一种通用协议都几乎不用亲自动手。
Netty社区活跃，遇到问题随时邮件列表或者 issue。
Netty已经历各大RPC框架（Dubbo），消息中间件（RocketMQ），大数据通信（Hadoop）框架的广泛的线上验证，健壮性无比强大。
2. 背景
最近在做一个基于 Websocket 的长连中间件，服务端使用实现了 Socket.IO 协议（基于WebSocket协议，提供长轮询降级能力） 的 netty-socketio 框架，该框架为 Netty 实现，鉴于本人对 Netty 比较熟，并且对比同样实现了 Socket.IO 协议的其他框架，Netty 的口碑都要更好一些，因此选择这个框架作为底层核心。
诚然，任何开源框架都避免不了 Bug 的存在，我们在使用这个开源框架时，就遇到一个堆外内存泄露的 Bug。美团的价值观一直都是“追求卓越”，所以我们就想挑战一下，找到那只臭虫（Bug），而本文就是遇到的问题以及排查的过程。当然，想看结论的同学可以直接跳到最后，阅读总结即可。
3. 问题
某天早上，我们突然收到告警，Nginx 服务端出现大量5xx。
我们使用 Nginx 作为服务端 WebSocket 的七层负载，5xx的爆发通常表明服务端不可用。由于目前 Nginx 告警没有细分具体哪台机器不可用，接下来，我们就到 CAT（美团点评统一监控平台，目前已经开源）去检查一下整个集群的各项指标，就发现如下两个异常:
某台机器在同一时间点爆发 GC（垃圾回收），而且在同一时间，JVM 线程阻塞。
4. 排查过程
4.1 阶段1: 怀疑是log4j2
因为线程被大量阻塞，我们首先想到的是定位哪些线程被阻塞，最后查出来是 Log4j2 狂打日志导致 Netty 的 NIO 线程阻塞（由于没有及时保留现场，所以截图缺失）。NIO 线程阻塞之后，因我们的服务器无法处理客户端的请求，所以对Nginx来说就是5xx。
接下来，我们查看了 Log4j2 的配置文件。
我们发现打印到控制台的这个 appender 忘记注释掉了，所以初步猜测：因为这个项目打印的日志过多，而 Log4j2 打印到控制台是同步阻塞打印的，所以就导致了这个问题。那么接下来，我们把线上所有机器的这行注释掉，本以为会“大功告成”，但没想到仅仅过了几天，5xx告警又来“敲门”。看来，这个问题并没我们最初想象的那么简单。
4.2 阶段2：可疑日志浮现
接下来，我们只能硬着头皮去查日志，特别是故障发生点前后的日志，于是又发现了一处可疑的地方：
可以看到：在极短的时间内，狂打 failed to allocate 64(bytes) of direct memory(...)日志（瞬间十几个日志文件，每个日志文件几百M），日志里抛出一个 Netty 自己封装的OutOfDirectMemoryError。说白了，就是堆外内存不够用，Netty 一直在“喊冤”。
堆外内存泄露，听到这个名词就感到很沮丧。因为这个问题的排查就像 C 语言内存泄露一样难以排查，首先能想到的就是，在 OOM 爆发之前，查看有无异常。然后查遍了 CAT 上与机器相关的所有指标，查遍了 OOM 日志之前的所有日志，均未发现任何异常！这个时候心里已经“万马奔腾”了……
4.3 阶段3：定位OOM源
没办法，只能看着这堆讨厌的 OOM 日志发着呆，希望答案能够“蹦到”眼前，但是那只是妄想。一筹莫展之际，突然一道光在眼前一闪而过，在 OOM 下方的几行日志变得耀眼起来（为啥之前就没想认真查看日志？估计是被堆外内存泄露这几个词吓怕了吧 ==！），这几行字是 ....PlatformDepedeng.incrementMemory()...。
原来，堆外内存是否够用，是 Netty 这边自己统计的，那么是不是可以找到统计代码，找到统计代码之后我们就可以看到 Netty 里面的对外内存统计逻辑了？于是，接下来翻翻代码，找到这段逻辑，就在 PlatformDepedent 这个类里面。
这个地方，是一个对已使用堆外内存计数的操作，计数器为 DIRECT_MEMORY_COUNTER，如果发现已使用内存大于堆外内存的上限（用户自行指定），就抛出一个自定义 OOM Error，异常里面的文本内容正是我们在日志里面看到的。
接下来，就验证一下这个方法是否是在堆外内存分配的时候被调用。
果然，在 Netty 每次分配堆外内存之前，都会计数。想到这，思路就开始慢慢清晰，而心情也开始从“秋风瑟瑟”变成“春光明媚”。
4.4 阶段4：反射进行堆外内存监控
CAT 上关于堆外内存的监控没有任何异常（应该是没有统计准确，一直维持在 1M），而这边我们又确认堆外内存已快超过上限，并且已经知道 Netty 底层是使用的哪个字段来统计。那么接下来要做的第一件事情，就是反射拿到这个字段，然后我们自己统计 Netty 使用堆外内存的情况。
堆外内存统计字段是 DIRECT_MEMORY_COUNTER，我们可以通过反射拿到这个字段，然后定期 Check 这个值，就可以监控 Netty 堆外内存的增长情况。
于是我们通过反射拿到这个字段，然后每隔一秒打印，为什么要这样做？
因为，通过我们前面的分析，在爆发大量 OOM 现象之前，没有任何可疑的现象。那么只有两种情况，一种是突然某个瞬间分配了大量的堆外内存导致OOM；一种是堆外内存缓慢增长，到达某个点之后，最后一根稻草将机器压垮。在这段代码加上去之后，我们打包上线。
4.5 阶段5：到底是缓慢增长还是瞬间飙升？
代码上线之后，初始内存为 16384k（16M），这是因为线上我们使用了池化堆外内存，默认一个 chunk 为16M，这里不必过于纠结。
但是没过一会，内存就开始缓慢飙升，并且没有释放的迹象，二十几分钟之后，内存使用情况如下：
走到这里，我们猜测可能是前面提到的第二种情况，也就是内存缓慢增长造成的 OOM，由于内存实在增长太慢，于是调整机器负载权重为其他机器的两倍，但是仍然是以数K级别在持续增长。那天刚好是周五，索性就过一个周末再开看。
周末之后，我们到公司第一时间就连上了跳板机，登录线上机器，开始 tail -f 继续查看日志。在输完命令之后，怀着期待的心情重重的敲下了回车键：
果然不出所料，内存一直在缓慢增长，一个周末的时间，堆外内存已经飙到快一个 G 了。这个时候，我竟然想到了一句成语：“只要功夫深，铁杵磨成针”。虽然堆外内存以几个K的速度在缓慢增长，但是只要一直持续下去，总有把内存打爆的时候（线上堆外内存上限设置的是2G）。
此时，我们开始自问自答环节：**内存为啥会缓慢增长，伴随着什么而增长？**因为我们的应用是面向用户端的WebSocket，那么，会不会是每一次有用户进来，交互完之后离开，内存都会增长一些，然后不释放呢？带着这个疑问，我们开始了线下模拟过程。
4.6 阶段6：线下模拟
本地起好服务，把监控堆外内存的单位改为以B为单位（因为本地流量较小，打算一次一个客户端连接），另外，本地也使用非池化内存（内存数字较小，容易看出问题），在服务端启动之后，控制台打印信息如下
在没有客户端接入的时候，堆外内存一直是0，在意料之中。接下来，怀着着无比激动的心情，打开浏览器，然后输入网址，开始我们的模拟之旅。
我们的模拟流程是：新建一个客户端链接->断开链接->再新建一个客户端链接->再断开链接。
如上图所示，一次 Connect 和 Disconnect 为一次连接的建立与关闭，上图绿色框框的日志分别是两次连接的生命周期。我们可以看到，内存每次都是在连接被关闭的的时候暴涨 256B，然后也不释放。走到这里，问题进一步缩小，肯定是连接被关闭的时候，触发了框架的一个Bug，而且这个Bug在触发之前分配了 256B 的内存，随着Bug被触发，内存也没有释放。问题缩小之后，接下来开始“撸源码”，捉虫！
4.7 阶段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的深坑，最后导致内存无法释放（最外层有堆外内存释放逻辑，现在无法执行到了）。而且越攒越多，直到被“最后一根稻草”压垮，堆外内存就这样爆了。这里的源码，有兴趣的读者可以自己去分析一下，限于篇幅原因，这里就不再展开叙述了。
4.8 阶段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号，项目启动的前夕！
4.9 阶段9：线下验证
一切准备就绪之后，我们就来进行本地验证，在服务起来之后，我们疯狂地建立连接，疯狂地断开连接，并观察堆外内存的情况：
Bingo！不管我们如何断开连接，堆外内存不涨了。至此，Bug 基本 Fix，当然最后一步，我们把代码推到线上验证。
4.10 阶段10：线上验证
这次线上验证，我们避免了比较土的打日志方法，我们把堆外内存的这个指标“喷射”到 CAT 上，然后再来观察一段时间的堆外内存的情况：
过完一段时间，堆外内存已经稳定不涨了。此刻，我们的“捉虫之旅”到此结束。最后，我们还为大家做一个小小的总结，希望对您有所帮助。
5. 总结
遇到堆外内存泄露不要怕，仔细耐心分析，总能找到思路，要多看日志，多分析。
如果使用了 Netty 堆外内存，那么可以自行监控堆外内存的使用情况，不需要借助第三方工具，我们是使用的“反射”拿到的堆外内存的情况。
逐渐缩小范围，直到 Bug 被找到。当我们确认某个线程的执行带来 Bug 时，可单步执行，可二分执行，定位到某行代码之后，跟到这段代码，然后继续单步执行或者二分的方式来定位最终出 Bug 的代码。这个方法屡试不爽，最后总能找到想要的 Bug。
熟练掌握 idea 的调试，让我们的“捉虫”速度快如闪电（“闪电侠”就是这么来的）。这里，最常见的调试方式是预执行表达式，以及通过线程调用栈，死盯某个对象，就能够掌握这个对象的定义、赋值之类。
最后，祝愿大家都能找到自己的“心仪已久” Bug！
6. 参考文献
最后更新于
