内存泄露分析与解决

一次内存泄露排查与解决案例全分享!

一、案例背景

我们的项目中有一个通过不同的安卓应用商店网站根据关键词搜索不同 APP 的功能。我们将 “一个关键词 + 一个应用商店网站” 称之为一个搜索任务 SearchTask。其中每个搜索任务默认会搜索网站的前 3 页,假设每一页包含 10 个 APP 的链接,那么我们每个搜索任务会产生 30 个 APP 链接,我们将这每一个 APP 链接称之为一个 Job。

Job 的任务就是负责请求这个链接,并抓取这个页面的 APP 信息。SearchTask 的任务就是产生多个 Job。每一个 SearchTask 的产生和这个 SearchTask 相关联的 Job 都是异步产生的。即 SearchTask 一次产生 10 个链接,然后进行下一页 (下 10 个) 链接的抓取,与此同时,这 10 个链接所对应的 10 个 Job 也会相应的立即进行爬取工作。

现在我们想要做一个关键词搜索 APP 功能的任务进度指示功能。我们为每一个 Job 定义了相关联的 JobStatus 任务状态回调类。为每一个 SearchTask 定义了相关联的 StatusReportSupportSearchListener 状态回调类。同时我们会将每个 SearchTask 对应的所有 Job 都放在一个 List 中,数据结构如下所示:

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
public class SearchStatusReport {

/**
* 一个搜索任务关联了很多个搜索具体APP的Job
*/
protected Map<SearchTask, List<Job>> searchTaskJobListMap;

/**
* 一个搜索任务本身关联一个搜索任务状态
*/
protected Map<SearchTask, StatusReportSupportSearchListener> searchTaskStatusMap;

/**
* 一个爬虫任务对应一个任务状态
*/
protected Map<Job, JobStatus> jobStatusMap;

// ...

}

如上所示,我们通过设置这三个最基本的数据结构,来达到统计搜索进度的目的。当添加一个 SearchTask 的时候,我们会对应的往 searchTaskJobListMap 中添加这个 SearchTask。当这个 SearchTask 对应的所有的 List<Job> 都完成的时候,我们便标记一个搜索任务完成了,如下所示:

SearchStatusReport DataStructure

我们现在有大致 300 个应用商店网站,大概有 300 个关键词,如此我们会产生 90000 个搜索任务。然而当我们实际对这 90000 个任务进行搜索,并尝试记录任务进度的时候,我们发现内存一直在飙升,由此我们猜想可能出现了内存泄漏…

二、内存泄露简介

默认情况下,我们使用的 Java 自带的垃圾收集器是 HotSpot VM 垃圾收集器。这个垃圾收集器使用的是分代垃圾收集器算法,即它会将可用堆内存切割为不同的区域 (代),如图所示,HostSpot VM 将堆分为了 Young Generation、 Old Generation、Permanaent Generation 三个区域:

Hotspot Heap Sructure

注意: G1 垃圾收集器的堆布局与其它垃圾收集器的堆布局有显著不同,我们在这里并不会讨论它。而且在此次案例中,我们也并未采用 G1 垃圾收集器算法来进行垃圾收集。

HotSpot VM 使用分代垃圾收集器的原因主要基于如下两个观察事实:

  • 大多数分配对象的存活时间很短
  • 存活时间久的对象很少引用存活时间短的对象

分代垃圾收集的一大优点是,每个分代都可以依据其特性使用最适当的垃圾收集算法。每次垃圾收集器运行时,一个对象或者是存活下来,继续占用堆内存,或者是被移除,其内存也被释放。当启动一个程序的时候,一开始需要分配大量对象的阶段称之为初始化阶段。当程序运行一段时间后,变回进入到稳定态阶段,为了确定程序有没有发生内存泄露,我们需要知道在多次 Full GC 之后 Java 堆的占用空间大小的变化情况,这可以借助 JVisualVM 工具来帮我们做到。

三、收集 GC 日志

首先在应用程序启动的时候,为 JVM 加上如下参数:

1
-XX:+PrintGCDateStamps -XX:+PrintGCDetails -Xloggc:log/gc.log

这三个参数能够确保程序运行期间发生的 GC 事件日志打印到 log/gc.log 文件中。下面这幅图是使用 JVisualVM 工具记录的程序运行前 15 分钟的 Java 堆的内存占用情况:

GC_Memory_Leak

我们通过执行命令:

1
cat gc.log | grep "Full GC"

找到发生 Full GC 的日志记录:

1
2
3
4
2018-01-23T19:36:22.597+0800: 1.843: [Full GC (Ergonomics) [PSYoungGen: 5098K->0K(132096K)] [ParOldGen: 70828K->73188K(174080K)] 75927K->73188K(306176K), [Metaspace: 20711K->20711K(1069056K)], 0.2491951 secs] [Times: user=1.47 sys=0.01, real=0.25 secs] 
2018-01-23T19:41:07.594+0800: 286.841: [Full GC (Ergonomics) [PSYoungGen: 79940K->61322K(406016K)] [ParOldGen: 159719K->173599K(280576K)] 239660K->234921K(686592K), [Metaspace: 30532K->30532K(1077248K)], 0.5822331 secs] [Times: user=3.60 sys=0.03, real=0.58 secs]
2018-01-23T19:45:41.140+0800: 560.386: [Full GC (Ergonomics) [PSYoungGen: 136534K->125504K(480768K)] [ParOldGen: 273643K->280145K(431616K)] 410178K->405649K(912384K), [Metaspace: 31111K->31111K(1077248K)], 0.7289075 secs] [Times: user=4.87 sys=0.01, real=0.73 secs]
2018-01-23T19:49:59.074+0800: 818.320: [Full GC (Ergonomics) [PSYoungGen: 128704K->110415K(509440K)] [ParOldGen: 416744K->431469K(659456K)] 545449K->541884K(1168896K), [Metaspace: 33989K->33989K(1081344K)], 1.0789386 secs] [Times: user=7.27 sys=0.03, real=1.08 secs]

从而知道在 15 分钟之内,这个应用程序总共发生了 4 次 Full GC,上图中红色方格就是对应着 Full GC 记录的时刻在图上标出来的效果。

正常情况下,程序运行了 15 分钟,应该早已经进入到了一个稳定态阶段,将上述几个红色的点连接起来,看上去也应该是一条趋近于水平的线才对。而我们观察到的却是应用程序占用内存不断飙升的一副图,因此我们断定发生了内存泄露。

四、MAT 分析堆转储

在程序运行到 15 分钟左右的时候,使用 JVisualVM 执行了 Dump Heap 将整个堆 Dump 到了一个文件中,大小约 900 MB。而从 MAT Overview 的顶部面板中,我们获知信息,当前应用程序占用了 618.7 MB 的堆内存:

Total Heap Size

然后使用 Eclipse MAT 工具分析这个文件,得到一份内存泄露报告,如下所示:

Memory Leak Report
Memory Leak Problem Suspect

MAT 告诉我们 SearchStatusReport 这个类维系了大约 538.8 MB 的内存,而 ThreadPoolExecutor 这个类维系了大约 62.9 MB 的内存。

维系一词在这个地方的意思是指这个对象的 Retained Size,即当前对象大小加上当前对象可直接或者间接引用到的对象的大小总和。下图是 Retained Size 和 Shallow Size 的区别:

Retained Size And Shallow Size

我们先点击 SearchStatusReport 的 Details 链接来查看这个类持有了哪些对象:

SearchStatusReport Hold Objects

我们发现单单这一个类便持有了这么多的类:

  • 1563 个 Job
  • 1563 个 JobStatus
  • 630 个 SearchTask
  • 630 个 StatusReportSupportSearchListener

我们这个类的目的是为了定时统计当前完成任务数量,而有些任务已经完成的话,我们就不需要再继续持有这些已经完成的类的引用了。应该尽快释放掉才对。这里其实也已经违背了 HotSpot VM 分代回收器的两个假设之一:

  • 存活时间久的对象很少引用存活时间短的对象

SearchStatusReport 对象是要一直存活于这整个应用程序运行期间的,属于存活时间久的对象。而这一个又一个的不断创建出来的 Job 搜索任务等其实只是存活时间短的对象,我们一直持有这些对象的话,必然会导致内存的不断攀升。

再来看 ThreadPoolExecutor 的 Details 链接显示的类持有对象有哪些:

ThreadPoolExecutor Hold Objects
ThreadPoolExecutor Hold Objects Numbers

我们发现这个类持有了一个类 LinkedBlockingQueue,但是就这个一个类的大小就是 62.8 MB,回顾线程池的实现原理,阻塞队列是用来存放待运行任务的地方,那这说明我们当前给这个队列一下子塞了太多的任务了,它一下子又运行不完,所以只能一直持有这些任务。

五、解决方案

针对 SearchStatusReport 采取的方案是:

  • 每次发现有完成的搜索任务并进行统计之后,便将这些搜索任务即时地从 Map 中 remove 掉。
  • 每次发现有完成的 Job 之后,变将这些从 List 中 remove 掉。

针对 ThreadPoolExecutor 采取的方案是:

  • 在内存中始终维护一个大小为 10 的搜索任务队列,如果有新的搜索任务完成,便从这个队列里面删除掉,添加一个新的搜索任务。否则一直阻塞。

六、效果

这是应用程序在做了上述步骤之后运行 15 分钟后的一个堆内存占用图,我们可以看到堆占用空间不再像之前出现陡坡上涨的势头,因此可以说明内存泄漏问题基本解决。

Fix Memory Leak Effect

只是,Full GC 的次数从之前的 4 次上升到了 21 次 … 那么就留作下次继续优化吧 ~

七、参考

推荐文章