Netty堆外内存泄露排查

关注我,紧跟本系列专栏文章,咱们下篇再续!

作者简介:魔都架构师,多家大厂后端一线研发经验,在分布式系统设计、数据平台架构和AI应用开发等领域都有丰富实践经验。

各大技术社区头部专家博主。具有丰富的引领团队经验,深厚业务架构和解决方案的积累。

负责:

  • 中央/分销预订系统性能优化
  • 活动&券等营销中台建设
  • 交易平台及数据中台等架构和开发设计
  • 车联网核心平台-物联网连接平台、大数据平台架构设计及优化
  • LLM Agent应用开发
  • 区块链应用开发
  • 大数据开发挖掘经验
  • 推荐系统项目

目前主攻市级软件项目设计、构建服务全社会的应用系统。

参考:

0 导读

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)框架验证,健壮性毋庸置疑

1 背景

做基于 Websocket 的长连中间件,服务端使用实现了 Socket.IO 协议(基于WebSocket协议,提供长轮询降级能力) 的 netty-socketio 框架,该框架为 Netty 实现,对比同样实现了 Socket.IO 协议的其他框架,Netty 的口碑都要更好,因此选这框架作为底层核心。

任何开源框架避免不了Bug,使用这开源框架时,就遇到一个堆外内存泄露Bug。

2 告警

某早突然收到告警,Nginx 服务端出现大量5xx:

使用 Nginx 作为服务端 WebSocket 的七层负载,5xx通常表明服务端不可用。由于目前 Nginx 告警没有细分具体哪台机器不可用,接下来,就到 CAT 检查整个集群的各项指标,发现两个异常:

某台机器在同一时间点爆发GC,且在同一时间,JVM 线程阻塞:

3 排查过程

阶段1:怀疑log4j2

因为线程被大量阻塞,先想到定位哪些线程被阻塞,最后查出来是 Log4j2 狂打日志导致 Netty NIO 线程阻塞(由于没及时保留现场,截图缺失)。

NIO 线程阻塞后,因服务器无法处理客户端请求,所以对Nginx来说就是5xx。

接下来,查看 Log4j2 配置文件:

打印到控制台的这个 appender 忘记注释,初步猜测:因为项目打印日志过多,而 Log4j2 打印到控制台是同步阻塞打印,所以导致这问题。

接下来,把线上所有机器这行注释,以为“大功告成”,但没想到仅几天,5xx告警又来。看来,问题没想象那么简单。

阶段2:可疑日志浮现

查日志,特别是故障发生点前后的日志,又发现可疑地方:

极短时间内,狂打 failed to allocate 64(bytes) of direct memory(...)日志(瞬间十几个日志文件,每个日志文件几百M),日志里抛一个 Netty 自己封装的OutOfDirectMemoryError:堆外内存不够用,Netty 一直在“喊冤”。

堆外内存泄露,这问题排查就像 C 语言内存泄露一样难,先想到,OOM 爆发前,有无异常。然后查遍 CAT 上与机器相关所有指标,查遍 OOM 日志之前的所有日志,均未发现任何异常!……

阶段3:定位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:缓慢增长 or 瞬间飙升?

代码上线后,初始内存 16384k(16M),因为线上使用池化堆外内存,默认一个 chunk 16M:

没一会,内存开始缓慢飙升,且没有释放迹象,二十几min后内存使用:

猜测可能是第二种情况:内存缓慢增长造成OOM,由于内存实在增长太慢,于是调整机器负载权重为其他机器两倍,但仍以数K级别持续增长。过个周末再看,周一tail -f查看日志:

不出所料,内存一直缓慢增长,一周末时间,堆外内存已飙到快1G。虽然堆外内存以几个K的速度在缓慢增长,但只要一直持续下去,总有把内存打爆的时候(线上堆外内存上限设置2G)。

内存为啥缓慢增长,伴随啥而增长?因为应用是面向用户端的WebSocket,会不会每次有用户进来,交互后离开,内存都会增长些,然后不释放?

阶段6:线下模拟

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

在没有客户端接入的时候,堆外内存一直是0,意料之中。打开浏览器,输入网址,开始模拟流程:

  • 新建一个客户端链接
  • 断开链接
  • 再新建一个客户端链接
  • 再断开链接

如上图,一次 Connect 和 Disconnect 为一次连接的建立与关闭,绿框日志分别是两次连接的生命周期。

内存每次都是在连接被关闭时暴涨 256B,然后不释放。问题进一步缩小,肯定是连接被关闭时,触发框架Bug,而且这Bug在触发之前分配了 256B 内存,随Bug被触发,内存也没释放。

开始“撸源码”!

阶段7:线下排查

将本地服务重启,开始线下排查。目光定位 netty-socketio 框架的 Disconnect 事件(客户端WebSocket连接关闭时会调用到这里),基本上可以确定,在 Disconnect 事件前后申请的内存没有释放。

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解决

只需解决这NPE。让这个 subType 字段不为空。先通过 idea 的线程调用栈,定位到这 packet 在哪定义:

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,再观察一段时间的堆外内存情况:

过完一段时间,堆外内存已稳定不涨。

总结

遇到堆外内存泄露别怕,耐心分析,总能找到思路,多看日志,多分析。

若用 Netty 堆外内存,可自行监控堆外内存的使用情况,无需借助第三方工具,“反射”拿到堆外内存情况。

逐渐缩小范围,直到 Bug 被找到。当我们确认某个线程的执行带来 Bug 时,可单步执行,可二分执行,定位到某行代码之后,跟到这段代码,然后继续单步执行或者二分的方式来定位最终出 Bug 的代码。这个方法屡试不爽,最后总能找到想要的 Bug。

熟练掌握 idea 调试。最常见调试方式是预执行表达式和通过线程调用栈,死盯某个对象,就能够掌握这个对象的定义、赋值之类。

参考:

  1. Netty 是啥
  2. Netty源码分析之服务端启动全解析
全部评论

相关推荐

09-14 14:42
门头沟学院 C++
旺旺米雪饼:举办了哥,你什么都没做错,全怪我那令人作呕的嫉妒和卑微的自尊心,看见你的文字我完全破防了,我直接丢盔弃甲了,看见你这图的那一秒,我满头大汗,浑身发冷,亿郁症瞬间发作了,生活仿佛没了颜色,像是被抓住尾巴的赛亚人,带着海楼石的能力者,抽离尾兽的人柱力,像是没了光的奥特曼,彻底断绝了生的希望。我几乎都快羡慕得疯了,倒在床上蒙住被子就开始抱着枕头尖叫流泪,嘴里一边喊着卧槽卧槽,一边又忍着,我边发边哭,打字的手都是抖的,后来我的手抖得越来越厉害,从心头涌起的思想、情怀和梦想,这份歆羡和悔恨交织在一起,我的笑还挂在脸上,可是眼泪一下子就掉下来了。求你了别发了,我生活再难再穷我都不会觉得难过,只有你们发这种东西的时候,我的心里像被刀割一样的痛,打着字泪水就忍不住的往下流。每天早上6点起床晚上11点睡觉,年复一年地学到现在,憧憬着一个月赚上万块的幸福生活,憧憬着美好阳光的未来。我打开了手机,看到你的图,我感到了深深的差距,我直接跳进了家门口的井里😭😭😭我真的😭我要嫉妒疯了😭为什么!!为什么这个人不是我😡我求你了😭求你了😭!不要在发了,我真的要羡慕嫉妒疯了😱怎么办我要嫉妒死了啊啊啊啊我急了,手机电脑全砸了,本来就有抑郁症的我,被别人说我破防了,我真的恼羞成怒了,仿佛被看穿了,躲在网络背后的我,这种感觉真的好难受,我被看穿的死死地,短短的破防两个字,我伪装出来的所有的坚强和强颜欢笑全都崩塌了,成了一个被人笑话的小丑🤡,我真的不想再故作坚强了,玩心态我输的什么都不剩😭😭😭
点赞 评论 收藏
分享
不愿透露姓名的神秘牛友
09-30 19:49
牛客798932866号:已经出薪资了嘛
投递汇川技术等公司10个岗位
点赞 评论 收藏
分享
点赞 3 评论
分享
牛客网
牛客企业服务