对于一般的项目而言,异常通知都还未完善的时候,作为开发人员,最好能每天都选个时间,进行下线上项目的日志的跟踪,看是否有出现异常,这样就能避免直到客户电话反馈才知道问题的尴尬,以及提升客户体验。好了废话不多说,直接进入主题。

     今天一早,刚打开其中一个线上项目的日志文件,一串:java.lang.OutOfMemoryError: Java heap space的异常,一次简单的线上OOM调试

分外显眼。于是第一个念头就是内存溢出,先查看下jvm的内存占量情况,用jmap -heap pid指令:

                                                                                                                                        一次简单的线上OOM调试

但事情就是这么奇怪,jvm各项内存指标都是正常的,用量远没达到jvm的上限,除非一次性建立xxM大小的对象,因为Eden+suvivor至少还有540M,old区也至少还有493M,所以除非生成的对象大于540M,第一个想到的就是大文件的上传,但问题又来了,根据异常之前的日志记录看,异常发生的区域函数只有一个图片的上传,虽然图片最大也能达到10几M,但是无论如何都不可能占满540M的空间。没办法了,只好dump出线上的对象文件进行定位,用jmap -dump:format=b,file=文件名 pid 指令生成dump文件:一次简单的线上OOM调试,然后用MAT(eclipse Memory Analyzer)工具导入文件,生成类报告:一次简单的线上OOM调试。然后蛋疼的事情又发生了,虽然报告显示存在3个可能出现溢出的问题,但总共10M的容量绝对不是异常的元凶,结论就是分析结果正常。于是只能去看GC日志:一次简单的线上OOM调试,结果发现在发生OOM期间,GC确实异常频繁,可以发现连续出现了2次Minor GC,都回收了部分内存,但还是无法满足需求,于是直接向old代进行输入,到old代容量90%的时候,又进行了次CMS的并行GC操作,回收了部分内存,但需求还是继续增长,再次进行CMS的回收,发现几乎没回收多少内存,于是启动了FullGC操作,但是仍旧回收不了度搜好内存,最后直接报错。分析GC日志,可以看到确实有个大对象再不停的进行增加,从一开始清空其他无用对象,到最后所有内存都被同一个对象占用,只能说明此 对象的增长应该是在一个循环内,不排除死循环的可能,再加上只有调用当前函数的时候才发生OOM,其他操作都不会触发,说明90%的可能是由问题代码引起的(因为我们的系统对上传文件的大小做了限制,最大20M)。于是用svn检查与前一个版本的差异:一次简单的线上OOM调试发现杀人的心都有。。。。(此处省略1000字)直接一个死循环,不停的进行append不内存溢出才怪。所以提交代码之前,一定要自己测试测试再测试,谨慎是美德。

问题解决之后,突然想起线上项目启动的时候是有配置OOM发生时生成dump文件的配置,在启动脚本里面看到有针对OOM的指令:-XX:+HeapDumpOnOutOfMemoryError -XX:HeapDumpPath=文件储存路径;一次简单的线上OOM调试果然在logs目录下找到异常时的dunp文件一次简单的线上OOM调试,然后突然想起自己刚刚做了件蠢事,竟然对一个抛完异常,线程已经回收且已经处于正常状态的jvm做dump,dump出的对象分析肯定是正常的。再来看下正真出问题的MAT分析文件:一次简单的线上OOM调试,报告里面已经很清楚的显示出了当时的内存状态,再来看下detail描述:一次简单的线上OOM调试已经很清楚了,连业务代码中的错误行数都已经抛出。

相关文章: