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

旧城等待， 2021-10-19 03:01 685阅读 0赞

近期需要对公司的接口做线上的巡查监控，需要写一个脚本放到服务器上，定时运行脚本监测线上接口是否正常。  
测试的接口不是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时出现内存泄漏，今天终于轮到我自己了！  
  
![1707603-20190708142649786-1814238440.png][]

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

经常做性能测试的同学，对内存泄漏都不陌生。内存泄漏总结来说就是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文件大）  
![1707603-20190708142742691-333909280.png][]  
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  
![1707603-20190708142755505-1497077910.png][]

在分析页面中可以看到，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线程。  
 ![1707603-20190708142837242-1909235858.png][]  
这个数量跟上面MAT工具分析的实例数量也差不多对应上了，现在问题基本上就确定了。也就是说在内存泄漏发生前，JVM中存在1000+个nioEventLoopGroup线程，每个线程创建了一个NioEventLoopGroup对象，因为线程池的特性，所以这些线程处于都是运行状态的。  
  
并且在脚本运行过程中发现，这个nioEventLoopGroup线程并不是开始就是1000+，而是从0慢慢涨上来的。也就是说随着脚本的运行，慢慢积累上来的。  
  
这个时候目光又回到了我的脚本中，虽然并不是因为我不断的new Demo对象造成了内存泄漏，但是肯定跟这个行为有关系，nioEventLoopGroup是netty框架用到的对象，于是就想到了代码中的TClient client = new TClient(xxx);   
  
打开TClient的jar包看了下，在TClient的构造函数里，确实创建了一个nioEventLoopGroup对象  
![1707603-20190708142859444-573506584.png][]

然后在connect方法中，使用了这个线程池对象bossGroup  
 ![1707603-20190708142915098-776906974.png][]  
  
现在基本上确定是什么原因了，如下：  
  
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方法  
![1707603-20190708142937169-1539608774.png][]  
在close方法中，确实把NioEventLoopGroup置为null了，对于一个普通的对象来说，只要对象引用为null，那么在下次JVM垃圾回收的时候，就会把这个对象回收掉。但是对于一个线程池对象来说，因为线程池中有活动线程存在，所以尽管置为null了，JVM也不会回收这个线程池。一般的线程池对象，都是通过shutdown方法来销毁线程池的。  
  
查看了下netty的api文档，确实有shutdownGracefully方法（优雅关闭）  
 ![1707603-20190708142952826-381409791.png][]

现在问题彻底搞清楚了，TClient的close方法中，只是简单的将线程池对象置为null，并没有进行shutdown操作，因此JVM并不能回收线程池对象。从而造成了，即便用户调用了close方法，其实资源也没有销毁，最终自然就会出现内存泄漏。  
  
作为一个通用的工具包，内部的资源的释放，并不能靠调用者来保证。理论上来说，即便我每次都new TClient对象，只要我都关闭了。在业务层面来说，也是正常行为。不能让调用者必须缓存client对象，否则就会出现内存泄漏，这样是不合理的。  
  
在跟相关开发沟通后，对代码做了修改，加上了shutdown方法，仍然用老的脚本进行测试，在长时间的运行后，内存依然保持正常。因此这个问题终于解决了。  
  
  
最后总结一下  
  
1、 此问题的根本原因是client包中close方法没有成功销毁资源  
  
2、 理论上来说，重复创建大量对象并不会造成内存泄漏，但是如果代码中同时也创建了第三方包的对象，在不了解其实现细节的情况了，可能其内部会创建一些不可被回收的对象，这个时候就会有内存泄漏的风险。因此还是尽量的复用对象，减少内存泄漏问题的发生。

作　　者：Testfan 北河

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

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

转载于:https://www.cnblogs.com/testfan2019/p/11151008.html

[1707603-20190708142649786-1814238440.png]: /images/20211018/c1c3b821366e4822a2e5a564be18852a.png
[1707603-20190708142701589-497333738.png]: /images/20211018/52e9415d04834fa49f3814b9263ffcc5.png
[1707603-20190708142742691-333909280.png]: /images/20211018/083c6fe7024547c1978b2272aeafded8.png
[1707603-20190708142755505-1497077910.png]: /images/20211018/7404de880e6f460cab492e66dbfb2845.png
[1707603-20190708142837242-1909235858.png]: /images/20211018/306a20d0087e4c72b0a5050c376d10fd.png
[1707603-20190708142859444-573506584.png]: /images/20211018/a0c438b465c4493cbd0b9dae683380e3.png
[1707603-20190708142915098-776906974.png]: /images/20211018/3ae9f62527b9479998f2a0149d30820a.png
[1707603-20190708142937169-1539608774.png]: /images/20211018/2d8d507a6aa14125892dd9393419c81c.png
[1707603-20190708142952826-381409791.png]: /images/20211018/ff13440eb08b464780035bede77f0185.png