WARNING
任何开源框架都避免不了 Bug 的存在，我们在使用这个开源框架Netty时，就遇到一个堆外内存泄露的 Bug。本文主要记录排查遇到的问题以及排查的过程。
# 一、问题
背景： 最近在做一个基于Websocket的长连中间件，服务端使用实现了Socket.IO协议（基于WebSocket协议，提供长轮询降级能力） 的netty-socketio框架，该框架为Netty实现，鉴于本人对Netty比较熟，并且对比同样实现了Socket.IO协议的其他框架，Netty的口碑都要更好一些，因此选择这个框架作为底层核心。
某天早上，我们突然收到告警，Nginx服务端出现大量5xx。
我们使用Nginx作为服务端WebSocket的七层负载，5xx的爆发通常表明服务端不可用。由于目前Nginx告警没有细分具体哪台机器不可用，接下来，我们就到CAT去检查一下整个集群的各项指标，就发现如下两个异常:
某台机器在同一时间点爆发GC（垃圾回收），而且在同一时间，JVM线程阻塞。
# 二、堆外内存泄露的排查过程
# 阶段一: 怀疑是log4j2
因为线程被大量阻塞，我们首先想到的是定位哪些线程被阻塞，最后查出来是Log4j2狂打日志导致Netty的NIO线程阻塞（由于没有及时保留现场，所以截图缺失）。NIO线程阻塞之后，因我们的服务器无法处理客户端的请求，所以对Nginx来说就是5xx。
接下来，我们查看了Log4j2的配置文件。
我们发现打印到控制台的这个appender忘记注释掉了，所以初步猜测：因为这个项目打印的日志过多，而Log4j2打印到控制台是同步阻塞打印的，所以就导致了这个问题。那么接下来，我们把线上所有机器的这行注释掉，本以为会“大功告成”，但没想到仅仅过了几天，5xx告警又来“敲门”。看来，这个问题并没我们最初想象的那么简单。
# 阶段二：可疑日志浮现
接下来，我们只能硬着头皮去查日志，特别是故障发生点前后的日志，于是又发现了一处可疑的地方：
可以看到：在极短的时间内，狂打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上，然后再来观察一段时间的堆外内存的情况：
过完一段时间，堆外内存已经稳定不涨了。此刻，我们的“捉虫之旅”到此结束。最后，我们还为大家做一个小小的总结，希望对您有所帮助。
# 三、总结
【1】遇到堆外内存泄露不要怕，仔细耐心分析，总能找到思路，要多看日志，多分析。
【2】如果使用了Netty堆外内存，那么可以自行监控堆外内存的使用情况，不需要借助第三方工具，我们是使用的“反射”拿到的堆外内存的情况。
【3】逐渐缩小范围，直到Bug被找到。当我们确认某个线程的执行带来Bug时，可单步执行，可二分执行，定位到某行代码之后，跟到这段代码，然后继续单步执行或者二分的方式来定位最终出Bug的代码。这个方法屡试不爽，最后总能找到想要的Bug。
【4】熟练掌握idea的调试，让我们的“捉虫”速度快如闪电（“闪电侠”就是这么来的）。这里，最常见的调试方式是预执行表达式，以及通过线程调用栈，死盯某个对象，就能够掌握这个对象的定义、赋值之类。