OOM分析之问题定位(一)

一.问题描述

最近对系统进行压测时发现Server日志报如下错误:java.lang.OutOfMemoryError: GC overhead limit exceeded。

查看Oracle OOM文档,在文档中找到以下内容:

Exception in thread thread_name: java.lang.OutOfMemoryError:GC Overhead limit exceeded
Cause: The detail message “GC overhead limitexceeded” indicates that the garbage collector is running all the time andJava program is making very slow progress. After a garbage collection, if the Java process is spending more than approximately 98% of its time doing garbage collection and if it is recovering less than 2% of the heap and has been doing so far the last 5 (compile time constant) consecutive garbage collections, then a java.lang.OutOfMemoryError is thrown.This exception is typically thrown because the amount of live data barely fitsinto the Java heap having little free space for new allocations.
Action:Increase the heap size.The java.lang.OutOfMemoryError exception for GC Overhead limit exceeded can be turned off with thecommand line flag -XX:-UseGCOverheadLimit.
原文链接如下:
https://docs.oracle.com/javase/8/docs/technotes/guides/troubleshoot/memleaks002.html
上面一段文字大概意思是JVM用98%的时间回收了不到2%的堆内存,因此预测到内存即将耗尽,抛出OOM异常来提示内存不足,相当于给用户一个警告信息。Oracle给的解决方法是提高堆内存,也可以用-XX:-UseGCOverheadLimit参数来关闭这个异常警告。

这种方式其实只是治标不治本,让用户提高堆内存容量,虽然解决了燃眉之急,但实际上并没有解决内存消耗过大的根本问题。如果堆内存一直增长,最终还会提示“GC overhead limit exceeded”。即使用XX:-UseGCOverheadLimit参数关闭OOM预测提示,当内存占用增长到极限,最后也会直接报 java.lang.OutOfMemoryError: Java heap space,造成进程停止的严重影响。所以Oracle给的解决方案并不靠谱,只能作为参考。

通过以上描述,可以推测进程中要么有任务一直在申请内存,要么发生了内存泄露。具体哪种原因还得对内存使用情况深入分析后判断,以下是分析的整个过程。

二.MAT分析

1.获取dump文件

登上服务器,用 Java自带的jmap生成dump 文件,命令如下:

jmap -dump:live,format=b,file= heap.hprof

2. 饼图分析

将dump文件下载到自己电脑,用 MAT打开。
OOM分析之问题定位(一)

从overview视图看到java.util.concurrent.ThreadPoolExecutor @ 0x744ce0aa 共占用了1.6G内存,比例占到了75%,可以初步判断有一个ThreadPoolExecutor的实例占据了大量内存,导致OOM。

3.Leak Suspects报告

点击overview视图下的Leak Suspects 按钮,查看分析结果。
OOM分析之问题定位(一)
从报告中看到QRCodeBatchTask类中引用的ThreadPoolExecutor的对象共占用了71.43%的内存,java.util.concurrent.LinkedBlockingQueue$Node 对象占用的最多。

4. Histogram图

点击菜单栏的Hitstorgam按钮,生成instances报告,并用Retained Heap进行排序。
OOM分析之问题定位(一)
图中Shallow Heap指对象自身占用内存大小,Retained Heap指对象自身加其引用对象总共占用内存大小。

从图中看出占用内存最多的是BufferedImages对象,QRCodeTask对象排到了第四,这个对象功能后面会提到。

选中BufferedImage右键查show object by classby incoming class,看到确实是QRCodeTask引用了BufferedImage。
OOM分析之问题定位(一)
选中BufferedImage右键查看Merge Shortest Paths to GC Roots ->exclude all phantim/weak/softetc. references,可以得知QRCodeTask中的的backGroundImage,logoImage变量占用内存最大。
OOM分析之问题定位(一)

5. DominatorTree

选中BufferedImage,点击Dominator Tree菜单。从图中可以看到确实是java.util.concurrent.LinkedBlockingQueue$Node引用了BufferImage,与Leak Suspects报告一致。
OOM分析之问题定位(一)
至此,可以基本分析出是QRCodeTask类中的两个BufferImage 对象backGroundImage和logoImage占用了大量内存,大概17M。

MAT分析工作基本到此结束,下一步找到相应代码查看业务逻辑。

三.代码分析

1.当有请求过来时会执行以下函数,把QRCodeBatchTask添加到线程池中。

 public void applyQRcode() {
    exec.execute(new QRCodeBatchTask());
  }

2.QRCodeBatchTask会不断往线程池提交QRCodeTask任务,并把生成的图片赋值给QRCodeTask。

public void run() {
		backImage=ImageIO.read(backGroundImageFile);
		logoImage=ImageIO.read(logoFile);
		for (List list : lists) {
			exec.execute(new QRCodeTask(backImage,logoImage));
)}}

3.QRCodeTask保存backGroundImage,logoImage对象,并在任务执行中用到。

 public class QRCodeTask implements Runnable {
    private BufferedImage backGroundImage, logoImage;
    public QRCodeTask(String backGroundImage, logoImage ) {
        this.backGroundImage = backImage;
        this.logoImage = logoImage;
    }
}

以上业务代码处理逻辑是每次请求过来时都会新建一个QRCodeBatchTask任务并提交到线程池中。QRCodeBatchTask会从磁盘读取两张图片,赋值给新建的QRCodeTask任务,所有新建的任务都会提交到线程池中去执行。

ThreadPoolExecutor原理是把提交的所有任务添加到LinkedBlockingQueue队列中,这也就是图中java.util.concurrent.LinkedBlockingQueue$Node对象引用QRCodeTask对象的原因。实际压测时候随着请求的持续增加,新建的QRCodeBatchTask越来越多,生成的图片也越来越多,最终导致占用的内存持续增长直至OOM发生。

四.问题解决

原因已经知道,解决问题就相对容易了。因为每个任务用到的backGroundImage,logoImage其实是一样的,因此可以用单例模式获取这两个图片,以此来保证进程内只保留一个图片对象,这样就减少了内存的占用。

通过重构代码,再次运行程序并用VisualVM进行监控可以观察到内存占用趋于平稳,没有再发生OOM,问题得到解决。