点击下方“JavaEdge”,选择“设为星标”
第一时间关注技术干货!
免责声明~ 任何文章不要过度深思!万事万物都经不起审视,因为世上没有同样的成长环境,也没有同样的认知水平,更「没有适用于所有人的解决方案」;
别急着评判文章列出的观点,只需代入其中,适度审视一番自己即可,能「跳脱出来从外人的角度看看现在的自己处在什么样的阶段」才不为俗人。
怎么想、怎么做,全在乎自己「不断实践中寻找适合自己的大道」
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 调试。最常见调试方式是预执行表达式和通过线程调用栈,死盯某个对象,就能够掌握这个对象的定义、赋值之类。
关注我,紧跟本系列专栏文章,咱们下篇再续!
★
作者简介:魔都架构师,多家大厂后端一线研发经验,在分布式系统设计、数据平台架构和AI应用开发等领域都有丰富实践经验。
各大技术社区头部专家博主。具有丰富的引领团队经验,深厚业务架构和解决方案的积累。
负责:
中央/分销预订系统性能优化
活动&券等营销中台建设
交易平台及数据中台等架构和开发设计
车联网核心平台-物联网连接平台、大数据平台架构设计及优化
LLM Agent应用开发
区块链应用开发
大数据开发挖掘经验
推荐系统项目
目前主攻市级软件项目设计、构建服务全社会的应用系统。
”
参考:
编程严选网
写在最后
编程严选网:
http://www.javaedge.cn/
专注分享软件开发全生态相关
技术文章
、视频教程
资源、热点资讯等,全站资源免费学习,快来看看吧~【编程严选】星球
欢迎长按图片加好友
,我会第一时间和你分享软件行业趋势
,面试资源
,学习方法
等等。
公众号后台私信:
回复【架构师】,获取架构师学习资源教程
回复【面试】,获取最新最全的互联网大厂面试资料
回复【简历】,获取各种样式精美、内容丰富的简历模板
回复 【路线图】,获取直升P7技术管理的全网最全学习路线图
回复 【大数据】,获取Java转型大数据研发的全网最全思维导图
更多教程资源应有尽有,欢迎关注并加技术交流群,慢慢获取
想先人一步获取以上所有资源?加入《编程严选》星球一键获取!