netty 堆外内存泄露排查盛宴

这篇文章对于排查使用了 netty 引起的堆外内存泄露问题，有必定的通用性，但愿对你有所启发nginx

背景

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

任何开源框架都避免不了 bug 的存在，咱们在使用这个开源框架的时候，就遇到一个堆外内存泄露的 bug，鉴于对 netty 比较熟，因而接下来便想挑战一下，找出那只臭虫（bug），接下来即是现象和排查过程，想看结论的同窗能够直接拉到最后总结。github

现象

某天早上忽然收到告警，nginx 服务端大量5xxweb

咱们使用 nginx 做为服务端 websocket 的七层负载，5xx爆发一般代表服务端不可用。因为目前 nginx 告警没有细分具体哪台机器不可用，接下来，到 cat（点评美团统一监控平台）去检查一下整个集群的各项指标，发现以下两个异常浏览器

某台机器在同一时间点爆发 gc，同一时间，jvm 线程阻塞服务器

接下来，便开始漫长的 堆外内存泄露排查之旅行。websocket

排查过程

阶段1: 怀疑是log4j2

线程被大量阻塞，首先想到的是定位哪些线程被阻塞，最后查出来是 log4j2 狂打日志致使 netty 的 nio 线程阻塞（因为没有及时保留现场，因此截图缺失），nio 线程阻塞以后，咱们的服务器没法处理客户端的请求，对nginx来讲是5xx。app

接下来，查看 log4j2 的配置文件框架

发现打印到控制台的这个 appender 忘记注释掉了，因此我初步猜想是由于这个项目打印的日志过多，而 log4j2 打印到控制台是同步阻塞打印的，接下来，把线上全部机器的这行注释掉，觉得大功告成，没想到，过不了几天，5xx告警又来敲门了，看来，这个问题没那么简单。jvm

阶段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，没必要过于纠结。

没过一会，内存就开始缓慢飙升，而且没有释放的迹象，20几分钟以后，内存以下

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

过完一个愉快的周末以后，到公司第一时间即是连上跳板机，登陆线上机器，开始 tail -f 继续查看日志，输完命令以后，怀着期待的心情重重的敲下了回车键

果真不出所料，内存一直在缓慢增加，一个周末的时间，堆外内存已经飙到快一个 G 了，这个时候，我居然想到了一句成语：只要功夫深，铁杵磨成针！虽然堆外内存几个K几个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：线下验证

一切就绪以后，首先，咱们来进行本地验证，服务起起来以后，我疯狂地创建链接，疯狂地断开链接，观察堆外内存的状况

好家伙，无论你如何断开链接，堆外内存一直不涨了，至此，bug 基本fix，固然，最后一步，咱们把代码推到线上验证。

阶段10：线上验证

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

发现过一段时间，堆外内存已经稳定不涨了，咱们的捉虫之旅到此结束！最后，我来给本地捉虫之旅作一次总结

总结

1.遇到堆外内存泄露不要怕，仔细耐心分析，总能找到思路，要多看日志，多分析。

2.若是使用了netty 堆外内存，那么你能够自行监控堆外内存的使用状况，不须要借助第三方工具，我这里是使用的反射拿到的堆外内存的状况。

3.逐渐缩小范围，直到bug被你找到。当你确认某个线程的执行带来 bug 的时候，可单步执行，可二分执行，定位到某行代码以后，跟到这段代码，而后继续单步执行或者二分的方式来定位最终出 bug 的代码，这个方法屡试不爽，最后总能找到bug。

4.熟练掌握 idea 的调试，让你的捉虫速度快如闪电，这里，最多见的调试方式是预执行表达式，以及经过线程调用栈，死盯某个对象，就可以掌握这个对象的定义，赋值之类。

最后，祝愿你们都能找到本身的 bug！