解决Java Web应用线上系统偶发宕机的情况

前言:事情是酱紫的,系统上线两个月后,风平浪静。在一个秋天宁静的下午,老衲正喝着茶听着歌敲着代码,顺便欣赏下妹纸,独享这难得的惬意。突然手机响了,一看来电,心中一沉,项目经理来电,必有蹊跷。匆忙接起电话,没有问候,直奔主题,“赶紧看下系统,个别客户反馈系统不能用了,先恢复系统,再排查问题”。老衲撂下电话,一哆嗦,赶紧连上VPN,直奔服务器主机。

PS:三台服务器(centos、128G内存、32核CPU),tomcat1.7,jdk1.8,通过F5负载

解决步骤:

1、top命令查看CPU占用情况

9F3FCA2C-CE35-4641-8CA0-93B11861588B.png

可以看到11042进程占用了非常多的CPU资源

2、查看F5并发曲线:为什么应用耗费了这么多的线程,难道是用户量突然上来了,调取了F5的访问曲线图,可以看到在15:57左右并发量突然猛涨,当时根据曲线怀疑是请求量徒增导致

597480B6-FE02-BC6E-56CF-5395ACB9EE06.png

3、查看系统请求量:根据应用系统日志、以及localhost_access_log日志 查看此节点用户访问日志,发现使用人数并未徒增,根据请求量绘制的曲线如下:58830552-7DE0-D16C-B137-FC677850EF7E.png

可以看到曲线并未出现请求量徒增。

4、查看进程内线程运行情况:没有大量请求,为什么CPU会被使用这么多,难道是有线程的死锁,

执行top -p 11042 -H 查看进程内所有线程的运行情况:

FB21CA14-C5E8-463A-8734-4BB118425B09.png

可以看到有很多线程正在执行

5、接着打内存快照执行命令打内存快照 在 jdk1.8.0_131/bin下面执行 ./jstack -l 11042>log01.txt,然后又隔了一分钟再次执行./jstack -l 11042>log02.txt,生产两个文件好对比里面的线程交集

打开日志,并未发现死锁的线程,但是在两个文件里面却发现大量的GC线程在执行如图:

BCF27D31-22A4-925C-3E16-A5F1D80E182A.png

6、分析GC回收情况,在jdk bin目录下执行 ./jstat -gcutil 11042 1000 100

38A41AE6-7738-BB5D-EA3A-830E32448509.png

看到了没有,虚拟机正在疯狂的进行full GC 回收,垃圾回收线程占用了非常多的CPU资源,问题已经有了明确的方向了,接下来需要分析到底是什么导致了full GC的频繁触发。

7、分析堆内存:

打印堆内存 在jdk bin目录下执行 ./jmap -dump:live,format=b,file=problem.bin 11042 ,将日志文件下载到本地使用jprofiler分析,5ED33FE4-B0F6-75A4-6B48-B807B9EA9D8E.png

发现有大量char[],String ,map 占用,那么是什么业务代码造成了以上大量的数据呢,打开 char[],String 没有找到与之关联的业务代码, 在map中发现大量的相同的业务对象,但是却无法直接发现出是什么操作造成了大量业务对象的存在,因为此业务对象代码中大量使用一一排除的话工作量极大。一时陷入困境,灵机一动,是不是还有别的内存快照分析工具,一查有个mat,在eclipse装好插件,打开内存快照:

36789770-822E-41EF-3C8D-5D5917B33222.png

点击leak suspects,如图

32B781A7-C8FD-A342-BE4A-4D3FB02840D4.png

在个给出问题中一一查看,这时问题出现了如图:

EA3891A9-7FDA-B440-7A96-D1F3B9B57F21.png

BaseDatagridRest 的export导出数据方法,突然想到系统中有某个表数据的导出,立即登录系统查看此项导出功能,发现这个导出未对数据量做限制,而且BaseDatagridRest 的export方法实现是将数据库中的表数据抽取到内存中然后回写到excle中,让用户下载。我登录测试环境,用大数据量测试了下导出果然出现了同样的问题,至此问题水落石出,解决方案很简单,导出数据量加上限制,为了防止因为导出过慢时用户多次点击加上和遮罩。

总结:GC不只是用来面试的,更是来解决问题的。

收藏 (0)
评论列表
正在载入评论列表...
我是有底线的