【转】一次由过量线程引发的OOM排查

时间:2021-02-06 20:53:17

  

     mac的话,还得进行下特殊处理:右键mat显示包内容,进入Contents->MacOS下面,会有一个MemoryAnalyzer的命令。
打开终端,进入此路径找到MemoryAnalyzer,运行 ./MemoryAnalyzer -data ./dump

      最近,公司的系统老是出现定时任务延迟执行的情况,一开始以为是由于基本上在那个点,需要执行的任务过多,而执行线程只有一个引起的正常列队(用的是springtask的定时任务,默认配置的线程池中最大线程数量为1),但在一个月黑风高的夜晚,客户反应没有任何的产品上架,而且已经离定时上架任务执行的时间过去了1个多小时,感觉肯定是系统出现了不可描述的问题。(由于没带电脑回家,是第二天去公司做的调试,当时以手动上架的方式先解决燃眉之急)

     第一步:查询了下完整的tomcat输出日志,发现了出现停顿的问题,就是OutOfMemoryError,如图:

【转】一次由过量线程引发的OOM排查

第二步:发生停顿的时间是在15号23.00左右,刚好是执行产品上架的时间,然后继续往下看日志,发现日志输出的时间有问题:

【转】一次由过量线程引发的OOM排查

第三步:所以可以推测,其实当时日志写入的时候,真正时间已经是16号00:21分,但由于以前阻塞的线程现在才开始继续活动,所以记录的还是他阻塞时候获得的时间;而且看default.log也能发现,15号23:00之后,就没有任何的日志输出,其实整个系统都已经处于挂起状态,所以联想到造成整个系统停止的原因应该是FullGC引起的,立马去看了下系统的gc情况(因为tomcat没有配gc日志输出,所以没法跟踪到当时的gc情况,只能看gc的总输出):

【转】一次由过量线程引发的OOM排查

看到总共做了18111次的FullGC,停顿时间5627秒,超过一个半小时。。。(瑟瑟发抖)

第四步:用指令:jmap -heap pid ,查看当前的内存使用情况,发现内存还是很吃紧,说明问题其实还是存在的;

【转】一次由过量线程引发的OOM排查

第五步:用指令: jmap -dump:format=b,file=fileName pid 获取下内存文件,然后下载到本地,再用eclipse的MAT内存分析工具进行分析,刚打开,就发现问题所在:

【转】一次由过量线程引发的OOM排查

Thead线程对象竟然创建了226M,而系统运行的总内存也就512M,所以问题一定是在线程的创建上了,继续往下看,打开overview ——>Actions中的Histogram:看到是byte[]所占的内存最多,继续追踪byte[]的生成对象,

【转】一次由过量线程引发的OOM排查

【转】一次由过量线程引发的OOM排查

【转】一次由过量线程引发的OOM排查

发现这2个所占的容量是最大的,继续点开,查看调用追踪,发现上面那个反射对象,应该是框架自身使用的原因,不是异常;

【转】一次由过量线程引发的OOM排查

【转】一次由过量线程引发的OOM排查

下面那个com.jcraft.jsch.Session经查代码,发现是连接sftp的一个session对象,而且他自身实现了RunAble接口,所以start之后,本身就是一个运行的线程,如果没有被正确关闭,就会运行停留代码里面设置的时间,所以在这期间,是不会被GC回收的;

【转】一次由过量线程引发的OOM排查

【转】一次由过量线程引发的OOM排查

继续看代码,发现确实是获取sftpChannel对象的方式有问题,如果在getChannel()方法中,发生异常,导致session已经启动,但返回的channel却是null,获取到的sftpChannel就是null的,也就是无法在后面进行关闭,只能等待他自己超时

【转】一次由过量线程引发的OOM排查

【转】一次由过量线程引发的OOM排查

【转】一次由过量线程引发的OOM排查

【转】一次由过量线程引发的OOM排查

所以针对上面的问题,给出的解决方案是,在getChannel()方法中,自己进行异常的捕获,如果发生异常,就立马进行session的关闭,且加大系统的内存到1G。

注:当时为了验证GC没有回收的原因是因为线程一直在运行造成的,所以还用指令:jstack pid 获取下了线程的运行状态文件,发现确实是4800多的sftpSession的连接线程,一直处于runable中,刚好能和内存中session对象个数进行对应。。。

【转】一次由过量线程引发的OOM排查