一次堆外内存泄露的排查过程

转载自  一次堆外内存泄露的排查过程

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

任何开源框架都避免不了 bug 的存在,我们在使用这个开源框架的时候,就遇到一个堆外内存泄露的 bug,鉴于对 netty 比较熟,于是接下来便想挑战一下,找出那只臭虫(bug),接下来便是现象和排查过程,想看结论的同学可以直接拉到最后总结。

现象

某天早上突然收到告警,nginx 服务端大量5xx

 

我们使用 nginx 作为服务端 websocket 的七层负载,5xx爆发通常表明服务端不可用。由于目前 nginx 告警没有细分具体哪台机器不可用,接下来,到 cat(点评美团统一监控平台)去检查一下整个集群的各项指标,发现如下两个异常

 

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

 

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

排查过程

阶段1: 怀疑是log4j2

线程被大量阻塞,首先想到的是定位哪些线程被阻塞,最后查出来是 log4j2 狂打日志导致 netty 的 nio 线程阻塞(由于没有及时保留现场,所以截图缺失),nio 线程阻塞之后,我们的服务器无法处理客户端的请求,对nginx来说是5xx。

接下来,查看 log4j2 的配置文件

 

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

阶段2:可疑日志浮现

接下来,只能硬着头皮去查日志,查看故障发生点前后的日志,发现了一处可疑的地方

 

在极短的时间内,狂打 failed to allocate64(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 的调试,让你的捉虫速度快如闪电,这里,最常见的调试方式是预执行表达式,以及通过线程调用栈,死盯某个对象,就能够掌握这个对象的定义,赋值之类。

本文来自互联网用户投稿,该文观点仅代表作者本人,不代表本站立场。本站仅提供信息存储空间服务,不拥有所有权,不承担相关法律责任。如若转载,请注明出处:http://www.mzph.cn/news/324104.shtml

如若内容造成侵权/违法违规/事实不符,请联系多彩编程网进行投诉反馈email:809451989@qq.com,一经查实,立即删除!

相关文章

.NET Core 2.0 特性介绍和使用指南

前言 这一篇会比较长,介绍了.NET Core 2.0新特性、工具支持及系统生态,现状及未来计划,可以作为一门技术的概述来读,也可以作为学习路径、提纲来用。 对于.NET Core 2.0的发布介绍,围绕2.0的架构体系,我想…

Lombok MyBatisX

Lombok的使用 [1] 什么是LomBok lombok是一个可以通过简单的注解的形式来帮助我们简化消除一些必须有但显得很臃肿的 Java 代码的工具,简单来说,比如我们新建了一个类,然后在其中写了几个属性,然后通常情况下我们需要手动去建立g…

一次堆外OOM问题的排查过程

转载自 一次堆外OOM问题的排查过程 背景 线上服务有一台机器访问不通(一个管理平台),在公司的服务治理平台上查看服务的状况是正常的,说明进程还在。进程并没有完全crash掉。去线上查看机器日志,发现了大量的OOM异常: 017-03-15 00:00:0…

Azure与Scott Guthrie:Azure安全中心和基于角色的访问控制

InfoQ有幸采访了Microsoft执行副总裁Scott Guthrie,请他谈了谈Azure以及他最近的Red Shirt Dev Tours(红杉开发之旅)【译注1】。昨天我们谈到了Azure提供了自定义仪表盘的功能,它能够使得开发者创建自定义工作任务流程&#xff0c…

什么时候才能都及格呢?

大家好,我是雄雄,欢迎关注公众号【雄雄的小课堂】。今天是周五,又到了周测的时候了,发现现在考试,学生们的抵触情绪不会那么强烈了,以前只要一说啥时啥时考试,下面一片哀嚎声,各种不…

解决Visual Studio For Mac Restore失败的问题

之前就了解到微软出了mac版的VS,没太多的关注,自己也就是使用 DotNet Core SDK VS Code 做一些小demo。 前两天发布了DotNet Core 2.0 ,Visual Studio For Mac 7.1 之后,感觉可以装起来用用,把win下面的项目转到Core…

来之不易的美团面试,结果居然挂了...(附面试答案)

转载自 来之不易的美团面试,结果居然挂了...(附面试答案) 一面 自我介绍 答:自我介绍是面试中唯一的自己主动介绍自己的环节,一定要好好把握好,你数据结构学的号可以手撕一个红黑树你就说我数据结构掌握…

三班的孩子们,你们现在还好吗?

大家好,我是雄雄,欢迎关注公众号【雄雄的小课堂】。三班的孩子们,你们还好吗?虽然已经就业,但还是会时不时的想起你们来,希望你们过的一切都好,在公司中也能快速适应。上午拿着电脑准备去四班上…

升级项目到.NET Core 2.0,在Linux上安装Docker,并成功部署

概述 容器,顾名思义是用来存放并容纳东西的器皿; 而容器技术伴着Docker的兴起也渐渐的映入大家的眼帘,它是一个抽象的概念,同时也是默默存在世上多年的技术,不仅能使应用程序间完全的隔离,而且还能在共享…

Spring Data Elasticsearch

文章目录一、 ELK二、 Elasticsearch简介三、 Linux安装Elasticsearch四、SpringData Elasticsearchpom.xmlapplication.yml创建实体创建索引 设置映射简单增删改查搜索五、 LogStash六、 使用Logback向Logstash中输出日志七、 在Kibana中查看日志信息八、 搭建日志系统九、 在…

项目参与度较低怎么办?

大家好,我是雄雄,欢迎关注公众号【雄雄的小课堂】。经过这两天做项目的表现,可以很明显的看的出来学生与学生之间掌握的还是有差距的,组内有的组员是可以为项目贡献代码的,但是有的组员可能只能是贡献素材,…

从 TFS 迁移源代码到 git

准备工具: https://github.com/git-tfs/git-tfs 具体的安装步骤上面的 readme.md 中有说明。通过 Chocolatey 安装,如果本地没有 git ,会自动安装 git 到本地。 迁移步骤: 从 Visual Studio 里面进入 Source Control Explorer…

缓存穿透、缓存并发、缓存失效之思路变迁

转载自 缓存穿透、缓存并发、缓存失效之思路变迁 在用缓存的时候,基本上会通用遇到以下三个问题: 缓存穿透缓存并发缓存失效 一、缓存穿透 上面三个图会有什么问题呢? 我们在项目中使用缓存通常都是先检查缓存中是否存在,如果…

jzoj3792,P2062-分队问题【贪心】

前言 题解上说: 然而我的贪心不仅A了,而且 反例也A了 自己的洛谷题解链接:https://www.luogu.org/blog/user52918/solution-p2062 正题 大意 n个人,每个人有一个要求a[i]表示他所在的队伍里不可以少于a[i]个人&#xff0…

.net core 2.0学习笔记(二):Hello World amp;amp; 进阶

官网已经有一个.net core的入手教程(https://www.microsoft.com/net/core#windowscmd),但这个教程完全没有顾及全宇宙第一IDE的感受。今天就跟大家体验一下在VS2017上开发.net core程序吧。VS2017开发环境的搭建请参考:http://www…

MyBatis】MyBatis一级缓存和二级缓存

转载自 MyBatis】MyBatis一级缓存和二级缓存 MyBatis自带的缓存有一级缓存和二级缓存 一级缓存 Mybatis的一级缓存是指Session缓存。一级缓存的作用域默认是一个SqlSession。Mybatis默认开启一级缓存。 也就是在同一个SqlSession中,执行相同的查询SQL&#xff…

.net core 2.0学习笔记(一):开发运行环境搭建

期待已久的.net core 2.0终于发布了!大家等的花儿都谢了。 不过比预期提前了一个多月,这在微软历史上还真的不多见。按照历史经验看,2.0版本应该比较靠谱,我猜这也是社区非常火爆的原因吧。下面就简单分享一下.net core2.0开发运行…

不好意思,你这个加分理由不行……

大家好,我是雄雄,欢迎关注微信公众号:雄雄的小课堂。周五了,又该周测了,今天和以往一样,上午前两节课都在上课,第三节课进行测试,这周的填空题有点儿多,所以考试的时间较…

SQL索引一步到位

转载自 SQL索引一步到位 SQL索引在数据库优化中占有一个非常大的比例, 一个好的索引的设计,可以让你的效率提高几十甚至几百倍,在这里将带你一步步揭开他的神秘面纱。 1.1 什么是索引? SQL索引有两种,聚集索引和非聚…

jzoj3794,P1383-高级打字机【欧拉序,离线O(n)】

正题 题目链接:https://www.luogu.org/problemnew/show/P1383 大意 三个操作 T c:加入一个字符c U x:撤销前x次操作(只包括T和U) Q x:询问当前第x个字符 解题思路 对于50%的数据U不会撤销到U 所以我们可…