记一次线上内存泄漏问题的排查过程

近期需要对公司的接口做线上的巡查监控,需要写一个脚本放到服务器上,定时运行脚本监测线上接口是否正常。

测试的接口不是HTTP协议,而是公司基于TCP协议开发的私有协议,因此不能直接用现成的一些接口测试工具,需要自己写代码来调用接口

由于是私有协议,为了方便各业务项目进行通信,开发部门统一提供了一个TClient的jar包,底层使用了netty框架进行通信。调用方只需要按照协议的格式组装二进制的包,然后直接调用TClient的sendMessage方法就可以把数据发送出去,服务端处理完成后会异步回调,将响应数据返回给客户端。

脚本写完了,伪代码如下

public class Demo{

       public void invoke(){

              // 创建TClient并初始化

              TClient client = new TClient(xxx);

              // 组装接口数据包

              Data data = new Data(xxx);

              // 发送数据

              Response res = client.sendMessage(data);

              // 检查结果、存储结果、发送邮件

              doSomething();

              // 关闭client

              client.close();

      }

}

测试脚本中,每隔一分钟,创建一个Demo对象,调用invoke方法

Demo demo = new Demo();

demo.invoke();

脚本写好后在服务器上调试了下,接口返回数据正常,于是正式启动定时任务,观察了一会,运行一切正常,Perfect!

第二天早上到公司,登上服务器,查看昨晚脚本的运行情况,看了下日志。

打开日志我就震惊了,What?OutOfMemoryError!竟然内存泄漏了!

平常都是开发写bug时出现内存泄漏,今天终于轮到我自己了!

最后一条日志显示为下午17:17左右,也就是脚本大概运行了4小时后出现了内存泄漏。查看了下脚本进程,果然已经崩溃了,并且生成了一个dump文件。

经常做性能测试的同学,对内存泄漏都不陌生。内存泄漏总结来说就是JVM中存储的对象太多了,占满了全部内存空间,并且这些对象都是不可回收的。这样程序就不能再继续运行了,因为已经没有空间了。

举个例子,就好像去饭馆吃饭,饭馆里总是不断的有人进去,也有人出来。如果某天来了一帮人占满了饭店,并且赖着不走了,这样新顾客就进不来了,这个时候估计老板就崩溃了。

我先review了脚本的代码,没发现什么异常的问题。有的朋友可能会说,你不是每个1分钟创建一个Demo对象吗,运行这么长时间,会不会是Demo对象太多了?

其实并不会,写脚本的时候也考虑过这个问题,每次new Demo对象,因为上一次脚本已经执行完了,那么上一次的Demo对象就没有引用了,这样JVM在垃圾回收的时候会把上一次的Demo对象清理掉。这样并不会造成内存泄漏。

目光再回到服务器上,Java进程在崩溃时,自动生成了一个堆dump文件,如果已经发生了内存泄漏,可以分析这个dump文件,看看里面那些对象比较多,这样就能确定原因了。

一般在工作中分析内存泄漏时,可以把dump文件下载到本地,然后通过jvisualvm或者jprofiler打开文件,工具自动会分析哪些对象数量最多。

但是这个文件有1.3G,公司服务器下载有限速,想下载下来估计得等到7月7号testfan性能测试实战班开课那天了。

突然想到另外一个分析内存泄漏的工具MAT,之前都是在windows下使用MAT,其实MAT也有Linux版本,可以直接在服务器上对dump文件进行分析。

简单介绍下工具的使用方法:

1、 登录官网,下载Linux x86_64/GTK+版本

https://www.eclipse.org/mat/downloads.php

2、 解压后修改MemoryAnalyzer.ini配置文件,配置jvm参数(要比dump文件大)

3、 执行.mat提供的脚本

./ParseHeapDump.sh /home/xxx.hprof org.eclipse.mat.api:suspects

(/home/xxx.hprof是dump文件的路径)

4、 在xxx.hprof目录下,生成了java_pid32523_Leak_Suspects.zip压缩文件

5、 下载到windows下,解压,打开index.html

在分析页面中可以看到,io.netty.channel.nio.NioEventLoopGroup对象占用了JVM中61.36%的空间。其次是io.netty.buffer.PoolThreadCache对象,占用了21.38%。

看名字这俩对象都是netty框架中的类,在网上查了下资料,“NioEventLoopGroup”是netty中的一个线程池对象。

看页面上的统计,JVM中有1145个netty的线程池对象,这是什么操作?线程池不就一个就行了吗?为什么有这么多?

看到线程池对象,就想到会不会JVM线程方面有问题?因为脚本进程现在已经崩溃了,只能重新运行脚本,然后再对线程进行监控。

脚本运行过程中,通过监控jvm,发现old区确实在不断的缓慢增加,这样长时间跑下去,应该就会重现昨天晚上的问题。

执行jstack命令打印线程堆栈信息

jstack pid > thread.log

打开thread.log看了下,线程状态倒没啥问题,但是堆栈中有大量的nioEventLoopGroup线程,看编号有1000+,通过命令统计了下,确实有1000+个nioEventLoopGroup线程。

这个数量跟上面MAT工具分析的实例数量也差不多对应上了,现在问题基本上就确定了。也就是说在内存泄漏发生前,JVM中存在1000+个nioEventLoopGroup线程,每个线程创建了一个NioEventLoopGroup对象,因为线程池的特性,所以这些线程处于都是运行状态的。

并且在脚本运行过程中发现,这个nioEventLoopGroup线程并不是开始就是1000+,而是从0慢慢涨上来的。也就是说随着脚本的运行,慢慢积累上来的。

这个时候目光又回到了我的脚本中,虽然并不是因为我不断的new

Demo对象造成了内存泄漏,但是肯定跟这个行为有关系,nioEventLoopGroup是netty框架用到的对象,于是就想到了代码中的TClient

client = new TClient(xxx);  

打开TClient的jar包看了下,在TClient的构造函数里,确实创建了一个nioEventLoopGroup对象

然后在connect方法中,使用了这个线程池对象bossGroup

现在基本上确定是什么原因了,如下:

a>   每隔1分钟,脚本会new一个Demo对象

b>   Demo对象的invoke方法里又new了一个TClient对象

c>   TClient对象内部在做netty连接初始化的时候,创建了NioEventLoopGroup线程池对象

虽然脚本中创建的Demo对象和TClient对象都会被JVM回收,但是可能是因为netty使用NioEventLoopGroup线程池和服务端建立了长连接,导致线程池对象并不会被回收。这样长时间跑下来,JVM中中的NioEventLoopGroup对象就会越来越多,最终导致了内存泄漏。

这么来看,还真是每次new Demo间接带来的影响。知道原因就好说了,Demo对象不能在每次运行的时候创建,而且放在类初始化的时候创建一个。无论脚本跑多少次,都只有一个NioEventLoopGroup对象了。

重新修改了下脚本,长时间运行监控了下,确实内存使用很稳定,没有出现内存泄漏的情况。

问题似乎是得到了解决,但是等等。我脑海中突然又想到另外一个问题,虽然我在脚本中每次都创建一个TClient对象,但是每次跑完后,都会调用TClient的close方法啊,close方法里应该会释放NioEventLoopGroup对象啊,难道没做吗?

打开TClient的jar包看了下close方法

在close方法中,确实把NioEventLoopGroup置为null了,对于一个普通的对象来说,只要对象引用为null,那么在下次JVM垃圾回收的时候,就会把这个对象回收掉。但是对于一个线程池对象来说,因为线程池中有活动线程存在,所以尽管置为null了,JVM也不会回收这个线程池。一般的线程池对象,都是通过shutdown方法来销毁线程池的。

查看了下netty的api文档,确实有shutdownGracefully方法(优雅关闭)

现在问题彻底搞清楚了,TClient的close方法中,只是简单的将线程池对象置为null,并没有进行shutdown操作,因此JVM并不能回收线程池对象。从而造成了,即便用户调用了close方法,其实资源也没有销毁,最终自然就会出现内存泄漏。

作为一个通用的工具包,内部的资源的释放,并不能靠调用者来保证。理论上来说,即便我每次都new TClient对象,只要我都关闭了。在业务层面来说,也是正常行为。不能让调用者必须缓存client对象,否则就会出现内存泄漏,这样是不合理的。

在跟相关开发沟通后,对代码做了修改加上了shutdown方法,仍然用老的脚本进行测试,在长时间的运行后,内存依然保持正常。因此这个问题终于解决了。

最后总结一下

1、 此问题的根本原因是client包中close方法没有成功销毁资源

2、 理论上来说,重复创建大量对象并不会造成内存泄漏,但是如果代码中同时也创建了第三方包的对象,在不了解其实现细节的情况了,可能其内部会创建一些不可被回收的对象,这个时候就会有内存泄漏的风险。因此还是尽量的复用对象,减少内存泄漏问题的发生。

作  者:Testfan 北河

出  处:微信公众号:自动化软件测试平台

版权说明:欢迎转载,但必须注明出处,并在文章页面明显位置给出文章链接

©著作权归作者所有,转载或内容合作请联系作者
  • 序言:七十年代末,一起剥皮案震惊了整个滨河市,随后出现的几起案子,更是在滨河造成了极大的恐慌,老刑警刘岩,带你破解...
    沈念sama阅读 203,547评论 6 477
  • 序言:滨河连续发生了三起死亡事件,死亡现场离奇诡异,居然都是意外死亡,警方通过查阅死者的电脑和手机,发现死者居然都...
    沈念sama阅读 85,399评论 2 381
  • 文/潘晓璐 我一进店门,熙熙楼的掌柜王于贵愁眉苦脸地迎上来,“玉大人,你说我怎么就摊上这事。” “怎么了?”我有些...
    开封第一讲书人阅读 150,428评论 0 337
  • 文/不坏的土叔 我叫张陵,是天一观的道长。 经常有香客问我,道长,这世上最难降的妖魔是什么? 我笑而不...
    开封第一讲书人阅读 54,599评论 1 274
  • 正文 为了忘掉前任,我火速办了婚礼,结果婚礼上,老公的妹妹穿的比我还像新娘。我一直安慰自己,他们只是感情好,可当我...
    茶点故事阅读 63,612评论 5 365
  • 文/花漫 我一把揭开白布。 她就那样静静地躺着,像睡着了一般。 火红的嫁衣衬着肌肤如雪。 梳的纹丝不乱的头发上,一...
    开封第一讲书人阅读 48,577评论 1 281
  • 那天,我揣着相机与录音,去河边找鬼。 笑死,一个胖子当着我的面吹牛,可吹牛的内容都是我干的。 我是一名探鬼主播,决...
    沈念sama阅读 37,941评论 3 395
  • 文/苍兰香墨 我猛地睁开眼,长吁一口气:“原来是场噩梦啊……” “哼!你这毒妇竟也来了?” 一声冷哼从身侧响起,我...
    开封第一讲书人阅读 36,603评论 0 258
  • 序言:老挝万荣一对情侣失踪,失踪者是张志新(化名)和其女友刘颖,没想到半个月后,有当地人在树林里发现了一具尸体,经...
    沈念sama阅读 40,852评论 1 297
  • 正文 独居荒郊野岭守林人离奇死亡,尸身上长有42处带血的脓包…… 初始之章·张勋 以下内容为张勋视角 年9月15日...
    茶点故事阅读 35,605评论 2 321
  • 正文 我和宋清朗相恋三年,在试婚纱的时候发现自己被绿了。 大学时的朋友给我发了我未婚夫和他白月光在一起吃饭的照片。...
    茶点故事阅读 37,693评论 1 329
  • 序言:一个原本活蹦乱跳的男人离奇死亡,死状恐怖,灵堂内的尸体忽然破棺而出,到底是诈尸还是另有隐情,我是刑警宁泽,带...
    沈念sama阅读 33,375评论 4 318
  • 正文 年R本政府宣布,位于F岛的核电站,受9级特大地震影响,放射性物质发生泄漏。R本人自食恶果不足惜,却给世界环境...
    茶点故事阅读 38,955评论 3 307
  • 文/蒙蒙 一、第九天 我趴在偏房一处隐蔽的房顶上张望。 院中可真热闹,春花似锦、人声如沸。这庄子的主人今日做“春日...
    开封第一讲书人阅读 29,936评论 0 19
  • 文/苍兰香墨 我抬头看了看天上的太阳。三九已至,却和暖如春,着一层夹袄步出监牢的瞬间,已是汗流浃背。 一阵脚步声响...
    开封第一讲书人阅读 31,172评论 1 259
  • 我被黑心中介骗来泰国打工, 没想到刚下飞机就差点儿被人妖公主榨干…… 1. 我叫王不留,地道东北人。 一个月前我还...
    沈念sama阅读 43,970评论 2 349
  • 正文 我出身青楼,却偏偏与公主长得像,于是被迫代替她去往敌国和亲。 传闻我的和亲对象是个残疾皇子,可洞房花烛夜当晚...
    茶点故事阅读 42,414评论 2 342

推荐阅读更多精彩内容