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

忘是亡心i 2022-04-10 14:40 418阅读 0赞

## 导读 ##

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

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

1.  使用 JDK 自带的 NIO 需要了解太多的概念，编程复杂。
2.  [彻底理解Netty][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][image.png 1]

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

![image.png][image.png 2]

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

## 排查过程 ##

### 阶段1: 怀疑是log4j2 ###

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

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

![image.png][image.png 3]

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

## 阶段2：可疑日志浮现 ##

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

![image.png][image.png 4]

可以看到：在极短的时间内，狂打 `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][image.png 5]

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

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

![image.png][image.png 6]

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

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

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

![image.png][image.png 7]

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

![image.png][image.png 8]

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

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

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

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

![image.png][image.png 9]

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

![image.png][image.png 10]

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

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

![image.png][image.png 11]

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

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

### 阶段6：线下模拟 ###

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

![image.png][image.png 12]

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

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

![image.png][image.png 13]

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

### 阶段7：线下排查 ###

接下来，我们将本地服务重启，开始完整的线下排查过程。同时将目光定位到 netty-socketio 这个框架的 Disconnect 事件（客户端WebSocket连接关闭时会调用到这里），基本上可以确定，在 Disconnect 事件前后申请的内存并没有释放。

![image.png][image.png 14]

在使用 idea debug 时，要选择只挂起当前线程，这样我们在单步跟踪的时候，控制台仍然可以看到堆外内存统计线程在打印日志。

在客户端连接上之后然后关闭，断点进入到 `onDisconnect` 回调，我们特意在此多停留了一会，发现控制台内存并没有飙升（7B这个内存暂时没有去分析，只需要知道，客户端连接断开之后，我们断点hold住，内存还未开始涨）。接下来，神奇的一幕出现了，我们将断点放开，让程序跑完：

![image.png][image.png 15]

Debug 松掉之后，内存立马飙升了！！此时，我们已经知道，这只“臭虫”飞不了多远了。在 Debug 时，挂起的是当前线程，那么肯定是当前线程某个地方申请了堆外内存，然后没有释放，继续“快马加鞭“，深入源码。

其实，每一次单步调试，我们都会观察控制台的内存飙升的情况。很快，我们来到了这个地方：

![image.png][image.png 16]

在这一行没执行之前，控制台的内存依然是 263B。然后，当执行完该行之后，立刻从 263B涨到519B（涨了256B）。

![image.png][image.png 17]

于是，Bug 范围进一步缩小。我们将本次程序跑完，释然后客户端再来一次连接，断点打在 `client.send()` 这行， 然后关闭客户端连接，之后直接进入到这个方法，随后的过程有点长，因为与 Netty 的时间传播机制有关，这里就省略了。最后，我们跟踪到了如下代码，`handleWebsocket`：

![image.png][image.png 18]

在这个地方，我们看到一处非常可疑的地方，在上图的断点上一行，调用 `encoder` 分配了一段内存，调用完之后，我们的控制台立马就彪了 256B。所以，我们怀疑肯定是这里申请的内存没有释放，它这里接下来调用 `encoder.encodePacket()` 方法，猜想是把数据包的内容以二进制的方式写到这段 256B的内存。接下来，我们追踪到这段 encode 代码，单步执行之后，就定位到这行代码：

![image.png][image.png 19]

这段代码是把 packet 里面一个字段的值转换为一个 char。然而，当我们使用 idea 预执行的时候，却抛出类一个愤怒的 NPE！！也就是说，框架申请到一段内存之后，在 encoder 的时候，自己 GG 了，还给自己挖了个NPE的深坑，最后导致内存无法释放（最外层有堆外内存释放逻辑，现在无法执行到了）。而且越攒越多，直到被“最后一根稻草”压垮，堆外内存就这样爆了。这里的源码，有兴趣的读者可以自己去分析一下，限于篇幅原因，这里就不再展开叙述了。

### 阶段8：Bug解决 ###

既然 Bug 已经找到，接下来就要解决问题了。这里只需要解决这个NPE异常，就可以 Fix 掉。我们的目标就是，让这个 `subType` 字段不为空。于是我们先通过 idea 的线程调用栈，定位到这个 packet 是在哪个地方定义的：

![image.png][image.png 20]

我们找到 idea 的 debugger 面板，眼睛盯着 packet 这个对象不放，然后上线移动光标，便光速定位到。原来，定义 packet 对象这个地方在我们前面的代码其实已经出现过，我们查看了一下 `subType` 这个字段，果然是 null。接下来，解决 Bug 就很容易了。

![image.png][image.png 21]

我们给这个字段赋值即可，由于这里是连接关闭事件，所以我们给他指定了一个名为 DISCONNECT 的字段（可以改天深入去研究 Socket.IO 的协议），反正这个 Bug 是在连接关闭的时候触发的，就粗暴一点了 ！

解决这个 Bug 的过程是：将这个框架的源码下载到本地，然后加上这一行，最后重新 Build一下，pom 里改了一下名字，推送到我们公司的仓库。这样，项目就可以直接进行使用了。

改完 Bug 之后，习惯性地去 GitHub上找到引发这段 Bug 的 Commit： ![image.png][image.png 22] 好奇的是，为啥这位 `dzn` commiter 会写出这么一段如此明显的 Bug，而且时间就在今年3月30号，项目启动的前夕！

### 阶段9：线下验证 ###

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

![image.png][image.png 23]

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

### 阶段10：线上验证 ###

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

![image.png][image.png 24]

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

## 总结 ##

1.  遇到堆外内存泄露不要怕，仔细耐心分析，总能找到思路，要多看日志，多分析。
2.  如果使用了 Netty 堆外内存，那么可以自行监控堆外内存的使用情况，不需要借助第三方工具，我们是使用的“反射”拿到的堆外内存的情况。
3.  逐渐缩小范围，直到 Bug 被找到。当我们确认某个线程的执行带来 Bug 时，可单步执行，可二分执行，定位到某行代码之后，跟到这段代码，然后继续单步执行或者二分的方式来定位最终出 Bug 的代码。这个方法屡试不爽，最后总能找到想要的 Bug。
4.  熟练掌握 idea 的调试，让我们的“捉虫”速度快如闪电（“闪电侠”就是这么来的）。这里，最常见的调试方式是预执行表达式，以及通过线程调用栈，死盯某个对象，就能够掌握这个对象的定义、赋值之类。

最后，祝愿大家都能找到自己的“心仪已久” Bug！

# 作者简介 #

闪电侠，2014年加入美团点评，主要负责美团点评移动端统一长连工作，欢迎同行进行技术交流。

# 招聘 #

目前我们团队负责美团点评长连基础设施的建设，支持美团酒旅、外卖、到店、打车、金融等几乎公司所有业务的快速发展。加入我们，你可以亲身体验到千万级在线连接、日吞吐百亿请求的场景，你会直面互联网高并发、高可用的挑战，有机会接触到 Netty 在长连领域的各个场景。我们诚邀有激情、有想法、有经验、有能力的同学，和我们一起并肩奋斗！欢迎感兴趣的同学投递简历至 chao.yu\#dianping.com 咨询。

# 参考文献 #

1.  [Netty 是什么][Netty 1]
2.  [Netty 源码分析之服务端启动全解析][Netty 2]

![1668a0b82bef31f6_w_1875_h_835_f_png_s_142461][]

原文链接：[https://my.oschina.net/meituantech/blog/2249206][https_my.oschina.net_meituantech_blog_2249206]

[Netty]: http://www.jqhtml.com/20774.html
[netty-socketio]: https://github.com/mrniko/netty-socketio/
[image.png]: https://user-gold-cdn.xitu.io/2018/10/19/1668a06fc9a23e8b?w=1240&h=722&f=png&s=278951
[CAT]: https://tech.meituan.com/CAT_in_Depth_Java_Application_Monitoring.html
[image.png 1]: https://user-gold-cdn.xitu.io/2018/10/19/1668a07449da7c6c?w=1240&h=403&f=png&s=52496
[image.png 2]: https://user-gold-cdn.xitu.io/2018/10/19/1668a07647235371?w=1240&h=438&f=png&s=49160
[image.png 3]: https://user-gold-cdn.xitu.io/2018/10/19/1668a07904bcbf54?w=640&h=133&f=png&s=60210
[image.png 4]: https://user-gold-cdn.xitu.io/2018/10/19/1668a07bc9790965?w=1240&h=581&f=png&s=713215
[image.png 5]: https://user-gold-cdn.xitu.io/2018/10/19/1668a07f01069501?w=1240&h=378&f=png&s=178952
[image.png 6]: https://user-gold-cdn.xitu.io/2018/10/19/1668a081c6be2179?w=1240&h=715&f=png&s=357914
[image.png 7]: https://user-gold-cdn.xitu.io/2018/10/19/1668a084636ff096?w=1240&h=841&f=png&s=513475
[image.png 8]: https://user-gold-cdn.xitu.io/2018/10/19/1668a086dcdd11a4?w=1240&h=694&f=png&s=287213
[image.png 9]: https://user-gold-cdn.xitu.io/2018/10/19/1668a08949b919ca?w=1240&h=728&f=png&s=841877
[image.png 10]: https://user-gold-cdn.xitu.io/2018/10/19/1668a08c5d02310f?w=1240&h=997&f=png&s=1189490
[image.png 11]: https://user-gold-cdn.xitu.io/2018/10/19/1668a08eb4dc1cf9?w=1240&h=696&f=png&s=857181
[image.png 12]: https://user-gold-cdn.xitu.io/2018/10/19/1668a091a9e94051?w=1240&h=739&f=png&s=1021332
[image.png 13]: https://user-gold-cdn.xitu.io/2018/10/19/1668a0940cecb745?w=1240&h=697&f=png&s=883148
[image.png 14]: https://user-gold-cdn.xitu.io/2018/10/19/1668a096805e8815?w=1240&h=681&f=png&s=563540
[image.png 15]: https://user-gold-cdn.xitu.io/2018/10/19/1668a09976e3ad7e?w=1240&h=670&f=png&s=587857
[image.png 16]: https://user-gold-cdn.xitu.io/2018/10/19/1668a09c634dfb2a?w=1240&h=790&f=png&s=1148753
[image.png 17]: https://user-gold-cdn.xitu.io/2018/10/19/1668a09ef79e5f42?w=1240&h=721&f=png&s=604830
[image.png 18]: https://user-gold-cdn.xitu.io/2018/10/19/1668a0a1f6872ffe?w=1240&h=703&f=png&s=870817
[image.png 19]: https://user-gold-cdn.xitu.io/2018/10/19/1668a0a4808351a5?w=1240&h=605&f=png&s=305508
[image.png 20]: https://user-gold-cdn.xitu.io/2018/10/19/1668a0a7f30053f0?w=1240&h=1013&f=png&s=543975
[image.png 21]: https://user-gold-cdn.xitu.io/2018/10/19/1668a0aa7edc1932?w=1240&h=621&f=png&s=389677
[image.png 22]: https://user-gold-cdn.xitu.io/2018/10/19/1668a0ae1bc71925?w=1240&h=1022&f=png&s=308044
[image.png 23]: https://user-gold-cdn.xitu.io/2018/10/19/1668a0b089672775?w=1240&h=597&f=png&s=749093
[image.png 24]: https://user-gold-cdn.xitu.io/2018/10/19/1668a0b33512e9ea?w=1240&h=1067&f=png&s=118664
[Netty 1]: https://www.jianshu.com/p/a4e03835921a
[Netty 2]: https://www.jianshu.com/p/c5068caab217
[1668a0b82bef31f6_w_1875_h_835_f_png_s_142461]: https://user-gold-cdn.xitu.io/2018/10/19/1668a0b82bef31f6?w=1875&h=835&f=png&s=142461
[https_my.oschina.net_meituantech_blog_2249206]: https://my.oschina.net/meituantech/blog/2249206