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

<h2>导读</h2> <p>Netty 是一个异步事件驱动的网络通讯层框架，用于快速开发高可用高性能的服务端网络框架与客户端程序，它极大地简化了 TCP 和 UDP 套接字服务器等网络编程。</p> <p>Netty 底层基于 JDK 的 NIO，咱们为何不直接基于 JDK 的 NIO 或者其余NIO框架：</p> <ol> <li>使用 JDK 自带的 NIO 须要了解太多的概念，编程复杂。</li> <li>Netty 底层 IO 模型随意切换，而这一切只须要作微小的改动。</li> <li>Netty自带的拆包解包，异常检测等机制让咱们从 NIO 的繁重细节中脱离出来，只需关心业务逻辑便可。</li> <li>Netty解决了JDK 的不少包括空轮训在内的 Bug。</li> <li>Netty底层对线程，Selector 作了不少细小的优化，精心设计的 Reactor 线程作到很是高效的并发处理。</li> <li>自带各类协议栈，让咱们处理任何一种通用协议都几乎不用亲自动手。</li> <li>Netty社区活跃，遇到问题随时邮件列表或者 issue。</li> <li>Netty已经历各大RPC框架（Dubbo），消息中间件（RocketMQ），大数据通讯（Hadoop）框架的普遍的线上验证，健壮性无比强大。</li> </ol> <h2>背景</h2> <p>最近在作一个基于 Websocket 的长连中间件，服务端使用实现了 Socket.IO 协议（基于WebSocket协议，提供长轮询降级能力）的 <a href="https://github.com/mrniko/netty-socketio/" title="netty-socketio">netty-socketio</a> 框架，该框架为 Netty 实现，鉴于本人对 Netty 比较熟，而且对比一样实现了 Socket.IO 协议的其余框架，Netty 的口碑都要更好一些，所以选择这个框架做为底层核心。</p> <p>诚然，任何开源框架都避免不了 Bug 的存在，咱们在使用这个开源框架时，就遇到一个堆外内存泄露的 Bug。美团的价值观一直都是“追求卓越”，因此咱们就想挑战一下，找到那只臭虫（Bug），而本文就是遇到的问题以及排查的过程。固然，想看结论的同窗能够直接跳到最后，阅读总结便可。</p> <h2>问题</h2> <p>某天早上，咱们忽然收到告警，Nginx 服务端出现大量5xx。</p> <p><img src="https://user-gold-cdn.xitu.io/2018/10/19/1668a06fc9a23e8b?w=1240&h=722&f=png&s=278951" alt="image.png" /></p> <p>咱们使用 Nginx 做为服务端 WebSocket 的七层负载，5xx的爆发一般代表服务端不可用。因为目前 Nginx 告警没有细分具体哪台机器不可用，接下来，咱们就到 <a href="https://tech.meituan.com/CAT_in_Depth_Java_Application_Monitoring.html">CAT</a>（美团点评统一监控平台，目前已经开源）去检查一下整个集群的各项指标，就发现以下两个异常:</p> <p><img src="https://user-gold-cdn.xitu.io/2018/10/19/1668a07449da7c6c?w=1240&h=403&f=png&s=52496" alt="image.png" /></p> <p>某台机器在同一时间点爆发 GC（垃圾回收），并且在同一时间，JVM 线程阻塞。</p> <p><img src="https://user-gold-cdn.xitu.io/2018/10/19/1668a07647235371?w=1240&h=438&f=png&s=49160" alt="image.png" /></p> <p>接下来，咱们就就开始了漫长的堆外内存泄露“排查之旅”。</p> <h2>排查过程</h2> <h3>阶段1: 怀疑是log4j2</h3> <p>由于线程被大量阻塞，咱们首先想到的是定位哪些线程被阻塞，最后查出来是 Log4j2 狂打日志致使 Netty 的 NIO 线程阻塞（因为没有及时保留现场，因此截图缺失）。NIO 线程阻塞以后，因咱们的服务器没法处理客户端的请求，因此对Nginx来讲就是5xx。</p> <p>接下来，咱们查看了 Log4j2 的配置文件。</p> <p><img src="https://user-gold-cdn.xitu.io/2018/10/19/1668a07904bcbf54?w=640&h=133&f=png&s=60210" alt="image.png" /></p> <p>咱们发现打印到控制台的这个 appender 忘记注释掉了，因此初步猜想：由于这个项目打印的日志过多，而 Log4j2 打印到控制台是同步阻塞打印的，因此就致使了这个问题。那么接下来，咱们把线上全部机器的这行注释掉，本觉得会“大功告成”，但没想到仅仅过了几天，5xx告警又来“敲门”。看来，这个问题并没咱们最初想象的那么简单。</p> <h2>阶段2：可疑日志浮现</h2> <p>接下来，咱们只能硬着头皮去查日志，特别是故障发生点先后的日志，因而又发现了一处可疑的地方：</p> <p><img src="https://user-gold-cdn.xitu.io/2018/10/19/1668a07bc9790965?w=1240&h=581&f=png&s=713215" alt="image.png" /></p> <p>能够看到：在极短的时间内，狂打 <code>failed to allocate 64(bytes) of direct memory(...)</code>日志（瞬间十几个日志文件，每一个日志文件几百M），日志里抛出一个 Netty 本身封装的<code>OutOfDirectMemoryError</code>。说白了，就是堆外内存不够用，Netty 一直在“喊冤”。</p> <p><strong>堆外内存泄露</strong>，听到这个名词就感到很沮丧。由于这个问题的排查就像 C 语言内存泄露同样难以排查，首先能想到的就是，在 OOM 爆发以前，查看有无异常。而后查遍了 CAT 上与机器相关的全部指标，查遍了 OOM 日志以前的全部日志，均未发现任何异常！这个时候内心已经“万马奔腾”了......</p> <h3>阶段3：定位OOM源</h3> <p>没办法，只能看着这堆讨厌的 OOM 日志发着呆，但愿答案可以“蹦到”眼前，可是那只是妄想。束手无策之际，忽然一道光在眼前一闪而过，在 OOM 下方的几行日志变得耀眼起来（为啥以前就没想认真查看日志？估计是被堆外内存泄露这几个词吓怕了吧 ==！），这几行字是 <code>....PlatformDepedeng.incrementMemory()...</code>。</p> <p>原来，堆外内存是否够用，是 Netty 这边本身统计的，那么是否是能够找到统计代码，找到统计代码以后咱们就能够看到 Netty 里面的对外内存统计逻辑了？因而，接下来翻翻代码，找到这段逻辑，就在 <code>PlatformDepedent</code> 这个类里面。</p> <p><img src="https://user-gold-cdn.xitu.io/2018/10/19/1668a07f01069501?w=1240&h=378&f=png&s=178952" alt="image.png" /></p> <p>这个地方，是一个对已使用堆外内存计数的操做，计数器为 <code>DIRECT_MEMORY_COUNTER</code>，若是发现已使用内存大于堆外内存的上限（用户自行指定），就抛出一个自定义 OOM Error，异常里面的文本内容正是咱们在日志里面看到的。</p> <p>接下来，就验证一下这个方法是不是在堆外内存分配的时候被调用。</p> <p><img src="https://user-gold-cdn.xitu.io/2018/10/19/1668a081c6be2179?w=1240&h=715&f=png&s=357914" alt="image.png" /></p> <p>果真，在 Netty 每次分配堆外内存以前，都会计数。想到这，思路就开始慢慢清晰，而心情也开始从“秋风瑟瑟”变成“春光明媚”。</p> <h3>阶段4：反射进行堆外内存监控</h3> <p><a href="https://tech.meituan.com/CAT_in_Depth_Java_Application_Monitoring.html">CAT</a> 上关于堆外内存的监控没有任何异常（应该是没有统计准确，一直维持在 1M），而这边咱们又确认堆外内存已快超过上限，而且已经知道 Netty 底层是使用的哪一个字段来统计。那么接下来要作的第一件事情，就是反射拿到这个字段，而后咱们本身统计 Netty 使用堆外内存的状况。</p> <p><img src="https://user-gold-cdn.xitu.io/2018/10/19/1668a084636ff096?w=1240&h=841&f=png&s=513475" alt="image.png" /></p> <p>堆外内存统计字段是 <code>DIRECT_MEMORY_COUNTER</code>，咱们能够经过反射拿到这个字段，而后按期 Check 这个值，就能够监控 Netty 堆外内存的增加状况。</p> <p><img src="https://user-gold-cdn.xitu.io/2018/10/19/1668a086dcdd11a4?w=1240&h=694&f=png&s=287213" alt="image.png" /></p> <p>因而咱们经过反射拿到这个字段，而后每隔一秒打印，为何要这样作？</p> <p>由于，经过咱们前面的分析，在爆发大量 OOM 现象以前，没有任何可疑的现象。那么只有两种状况，一种是忽然某个瞬间分配了大量的堆外内存致使OOM；一种是堆外内存缓慢增加，到达某个点以后，最后一根稻草将机器压垮。在这段代码加上去以后，咱们打包上线。</p> <h3>阶段5：究竟是缓慢增加仍是瞬间飙升？</h3> <p>代码上线以后，初始内存为 16384k（16M），这是由于线上咱们使用了池化堆外内存，默认一个 chunk 为16M，这里没必要过于纠结。</p> <p><img src="https://user-gold-cdn.xitu.io/2018/10/19/1668a08949b919ca?w=1240&h=728&f=png&s=841877" alt="image.png" /></p> <p>可是没过一会，内存就开始缓慢飙升，而且没有释放的迹象，二十几分钟以后，内存使用状况以下：</p> <p><img src="https://user-gold-cdn.xitu.io/2018/10/19/1668a08c5d02310f?w=1240&h=997&f=png&s=1189490" alt="image.png" /></p> <p>走到这里，咱们猜想多是前面提到的第二种状况，也就是内存缓慢增加形成的 OOM，因为内存实在增加太慢，因而调整机器负载权重为其余机器的两倍，可是仍然是以数K级别在持续增加。那天恰好是周五，索性就过一个周末再开看。</p> <p>周末以后，咱们到公司第一时间就连上了跳板机，登陆线上机器，开始 tail -f 继续查看日志。在输完命令以后，怀着期待的心情重重的敲下了回车键：</p> <p><img src="https://user-gold-cdn.xitu.io/2018/10/19/1668a08eb4dc1cf9?w=1240&h=696&f=png&s=857181" alt="image.png" /></p> <p>果真不出所料，内存一直在缓慢增加，一个周末的时间，堆外内存已经飙到快一个 G 了。这个时候，我居然想到了一句成语：“只要功夫深，铁杵磨成针”。虽然堆外内存以几个K的速度在缓慢增加，可是只要一直持续下去，总有把内存打爆的时候（线上堆外内存上限设置的是2G）。</p> <p>此时，咱们开始自问自答环节：内存为啥会缓慢增加，伴随着什么而增加？由于咱们的应用是面向用户端的WebSocket，那么，会不会是每一次有用户进来，交互完以后离开，内存都会增加一些，而后不释放呢？带着这个疑问，咱们开始了线下模拟过程。</p> <h3>阶段6：线下模拟</h3> <p>本地起好服务，把监控堆外内存的单位改成以B为单位（由于本地流量较小，打算一次一个客户端链接），另外，本地也使用非池化内存（内存数字较小，容易看出问题），在服务端启动以后，控制台打印信息以下</p> <p><img src="https://user-gold-cdn.xitu.io/2018/10/19/1668a091a9e94051?w=1240&h=739&f=png&s=1021332" alt="image.png" /></p> <p>在没有客户端接入的时候，堆外内存一直是0，在乎料之中。接下来，怀着着无比激动的心情，打开浏览器，而后输入网址，开始咱们的模拟之旅。</p> <p>咱们的模拟流程是：新建一个客户端连接->断开连接->再新建一个客户端连接->再断开连接。</p> <p><img src="https://user-gold-cdn.xitu.io/2018/10/19/1668a0940cecb745?w=1240&h=697&f=png&s=883148" alt="image.png" /></p> <p>如上图所示，一次 Connect 和 Disconnect 为一次链接的创建与关闭，上图绿色框框的日志分别是两次链接的生命周期。咱们能够看到，内存每次都是在链接被关闭的的时候暴涨 256B，而后也不释放。走到这里，问题进一步缩小，确定是链接被关闭的时候，触发了框架的一个Bug，并且这个Bug在触发以前分配了 256B 的内存，随着Bug被触发，内存也没有释放。问题缩小以后，接下来开始“撸源码”，捉虫！</p> <h3>阶段7：线下排查</h3> <p>接下来，咱们将本地服务重启，开始完整的线下排查过程。同时将目光定位到 netty-socketio 这个框架的 Disconnect 事件（客户端WebSocket链接关闭时会调用到这里），基本上能够肯定，在 Disconnect 事件先后申请的内存并无释放。</p> <p><img src="https://user-gold-cdn.xitu.io/2018/10/19/1668a096805e8815?w=1240&h=681&f=png&s=563540" alt="image.png" /></p> <p>在使用 idea debug 时，要选择只挂起当前线程，这样咱们在单步跟踪的时候，控制台仍然能够看到堆外内存统计线程在打印日志。</p> <p>在客户端链接上以后而后关闭，断点进入到 <code>onDisconnect</code> 回调，咱们特地在此多停留了一会，发现控制台内存并无飙升（7B这个内存暂时没有去分析，只须要知道，客户端链接断开以后，咱们断点hold住，内存还未开始涨）。接下来，神奇的一幕出现了，咱们将断点放开，让程序跑完：</p> <p><img src="https://user-gold-cdn.xitu.io/2018/10/19/1668a09976e3ad7e?w=1240&h=670&f=png&s=587857" alt="image.png" /></p> <p>Debug 松掉以后，内存立马飙升了！！此时，咱们已经知道，这只“臭虫”飞不了多远了。在 Debug 时，挂起的是当前线程，那么确定是当前线程某个地方申请了堆外内存，而后没有释放，继续“马不停蹄“，深刻源码。</p> <p>其实，每一次单步调试，咱们都会观察控制台的内存飙升的状况。很快，咱们来到了这个地方：</p> <p><img src="https://user-gold-cdn.xitu.io/2018/10/19/1668a09c634dfb2a?w=1240&h=790&f=png&s=1148753" alt="image.png" /></p> <p>在这一行没执行以前，控制台的内存依然是 263B。而后，当执行完该行以后，马上从 263B涨到519B（涨了256B）。</p> <p><img src="https://user-gold-cdn.xitu.io/2018/10/19/1668a09ef79e5f42?w=1240&h=721&f=png&s=604830" alt="image.png" /></p> <p>因而，Bug 范围进一步缩小。咱们将本次程序跑完，释而后客户端再来一次链接，断点打在 <code>client.send()</code> 这行，而后关闭客户端链接，以后直接进入到这个方法，随后的过程有点长，由于与 Netty 的时间传播机制有关，这里就省略了。最后，咱们跟踪到了以下代码，<code>handleWebsocket</code>：</p> <p><img src="https://user-gold-cdn.xitu.io/2018/10/19/1668a0a1f6872ffe?w=1240&h=703&f=png&s=870817" alt="image.png" /></p> <p>在这个地方，咱们看到一处很是可疑的地方，在上图的断点上一行，调用 <code>encoder</code> 分配了一段内存，调用完以后，咱们的控制台立马就彪了 256B。因此，咱们怀疑确定是这里申请的内存没有释放，它这里接下来调用 <code>encoder.encodePacket()</code> 方法，猜测是把数据包的内容以二进制的方式写到这段 256B的内存。接下来，咱们追踪到这段 encode 代码，单步执行以后，就定位到这行代码：</p> <p><img src="https://user-gold-cdn.xitu.io/2018/10/19/1668a0a4808351a5?w=1240&h=605&f=png&s=305508" alt="image.png" /></p> <p>这段代码是把 packet 里面一个字段的值转换为一个 char。然而，当咱们使用 idea 预执行的时候，却抛出类一个愤怒的 NPE！！也就是说，框架申请到一段内存以后，在 encoder 的时候，本身 GG 了，还给本身挖了个NPE的深坑，最后致使内存没法释放（最外层有堆外内存释放逻辑，如今没法执行到了）。并且越攒越多，直到被“最后一根稻草”压垮，堆外内存就这样爆了。这里的源码，有兴趣的读者能够本身去分析一下，限于篇幅缘由，这里就再也不展开叙述了。</p> <h3>阶段8：Bug解决</h3> <p>既然 Bug 已经找到，接下来就要解决问题了。这里只须要解决这个NPE异常，就能够 Fix 掉。咱们的目标就是，让这个 <code>subType</code> 字段不为空。因而咱们先经过 idea 的线程调用栈，定位到这个 packet 是在哪一个地方定义的：</p> <p><img src="https://user-gold-cdn.xitu.io/2018/10/19/1668a0a7f30053f0?w=1240&h=1013&f=png&s=543975" alt="image.png" /></p> <p>咱们找到 idea 的 debugger 面板，眼睛盯着 packet 这个对象不放，而后上线移动光标，便光速定位到。原来，定义 packet 对象这个地方在咱们前面的代码其实已经出现过，咱们查看了一下 <code>subType</code> 这个字段，果真是 null。接下来，解决 Bug 就很容易了。</p> <p><img src="https://user-gold-cdn.xitu.io/2018/10/19/1668a0aa7edc1932?w=1240&h=621&f=png&s=389677" alt="image.png" /></p> <p>咱们给这个字段赋值便可，因为这里是链接关闭事件，因此咱们给他指定了一个名为 DISCONNECT 的字段（能够改天深刻去研究 Socket.IO 的协议），反正这个 Bug 是在链接关闭的时候触发的，就粗暴一点了！</p> <p>解决这个 Bug 的过程是：将这个框架的源码下载到本地，而后加上这一行，最后从新 Build一下，pom 里改了一下名字，推送到咱们公司的仓库。这样，项目就能够直接进行使用了。</p> <p>改完 Bug 以后，习惯性地去 GitHub上找到引起这段 Bug 的 Commit： <img src="https://user-gold-cdn.xitu.io/2018/10/19/1668a0ae1bc71925?w=1240&h=1022&f=png&s=308044" alt="image.png" /> 好奇的是，为啥这位 <code>dzn</code> commiter 会写出这么一段如此明显的 Bug，并且时间就在今年3月30号，项目启动的前夕！</p> <h3>阶段9：线下验证</h3> <p>一切准备就绪以后，咱们就来进行本地验证，在服务起来以后，咱们疯狂地创建链接，疯狂地断开链接，并观察堆外内存的状况：</p> <p><img src="https://user-gold-cdn.xitu.io/2018/10/19/1668a0b089672775?w=1240&h=597&f=png&s=749093" alt="image.png" /></p> <p>Bingo！无论咱们如何断开链接，堆外内存不涨了。至此，Bug 基本 Fix，固然最后一步，咱们把代码推到线上验证。</p> <h3>阶段10：线上验证</h3> <p>此次线上验证，咱们避免了比较土的打日志方法，咱们把堆外内存的这个指标“喷射”到 CAT 上，而后再来观察一段时间的堆外内存的状况：</p> <p><img src="https://user-gold-cdn.xitu.io/2018/10/19/1668a0b33512e9ea?w=1240&h=1067&f=png&s=118664" alt="image.png" /></p> <p>过完一段时间，堆外内存已经稳定不涨了。此刻，咱们的“捉虫之旅”到此结束。最后，咱们还为你们作一个小小的总结，但愿对您有所帮助。</p> <h2>总结</h2> <ol> <li> <p>遇到堆外内存泄露不要怕，仔细耐心分析，总能找到思路，要多看日志，多分析。</p> </li> <li> <p>若是使用了 Netty 堆外内存，那么能够自行监控堆外内存的使用状况，不须要借助第三方工具，咱们是使用的“反射”拿到的堆外内存的状况。</p> </li> <li> <p>逐渐缩小范围，直到 Bug 被找到。当咱们确认某个线程的执行带来 Bug 时，可单步执行，可二分执行，定位到某行代码以后，跟到这段代码，而后继续单步执行或者二分的方式来定位最终出 Bug 的代码。这个方法屡试不爽，最后总能找到想要的 Bug。</p> </li> <li> <p>熟练掌握 idea 的调试，让咱们的“捉虫”速度快如闪电（“闪电侠”就是这么来的）。这里，最多见的调试方式是预执行表达式，以及经过线程调用栈，死盯某个对象，就可以掌握这个对象的定义、赋值之类。</p> </li> </ol> <p>最后，祝愿你们都能找到本身的“心仪已久” Bug！</p> <h1>做者简介</h1> <p>闪电侠，2014年加入美团点评，主要负责美团点评移动端统一长连工做，欢迎同行进行技术交流。</p> <h1>招聘</h1> <p>目前咱们团队负责美团点评长连基础设施的建设，支持美团酒旅、外卖、到店、打车、金融等几乎公司全部业务的快速发展。加入咱们，你能够亲身体验到千万级在线链接、日吞吐百亿请求的场景，你会直面互联网高并发、高可用的挑战，有机会接触到 Netty 在长连领域的各个场景。咱们诚邀有激情、有想法、有经验、有能力的同窗，和咱们一块儿并肩奋斗！欢迎感兴趣的同窗投递简历至 chao.yu#dianping.com 咨询。</p> <h1>参考文献</h1> <ol> <li><a href="https://www.jianshu.com/p/a4e03835921a">Netty 是什么</a></li> <li><a href="https://www.jianshu.com/p/c5068caab217">Netty 源码分析之服务端启动全解析</a></li> </ol> <p><img src="https://user-gold-cdn.xitu.io/2018/10/19/1668a0b82bef31f6?w=1875&h=835&f=png&s=142461" alt="" /></p>html

原文连接：https://my.oschina.net/meituantech/blog/2249206git