一行代码引发的内存泄露的故事

Posted on 2020-06-17 Edited on 2024-04-16 In Performance Optimization , JVM

我在2019年的7月和8月之间大概花了两个多星期写了一个比较简单的爬虫项目，项目主要的功能是周期性的爬取一些网站的热点信息，然后把数据存在 Redis 缓存中，然后有一个可以切换不同网站和展示信息的页面。

为什么会写这个项目呢？写这个项目的原因是在 V2EX 网站上看到很多人在分享他自己做的热点聚合网站，由于，我当时属于离职状态，好久没写代码了，于是决定也写一个类似的项目练练手。于是就写了 hot-crawler 这个项目，项目的源码放在了 GitHub 上。

写完了之后，就购买了域名和云服务器，然后就部署上去了。但是，我发现网站会偶尔访问不了，无响应。发现是服务器的程序进程挂掉了，于是重新启动项目后，我在服务器的控制面板观察服务器的资源状态，看到系统占用内存会不断的升高，所以，我猜应该是内存不足导致进程挂掉了，可是不知道为什么会导致内存泄漏。由于当时已经在网上推广了自己的网站，事情比较紧急，想着用什么方法来解决呢？于是我先是把应用程序作为 Linux 自启的系统服务，这样程序挂掉之后会自动重新启动，不至于一直访问不了。然后，我又通过加一台服务器使用 Nginx 进行负载均衡。因为程序挂掉是需要经过一段时间的，然后需要十几秒的时间重启，在相同的十几秒时间，两台服务器同时挂掉的机率比较小，通过负载均衡可以错开这十几秒，从而使得网站可以持续访问。

网站挂掉的问题解决掉了，但不是真正意义上的解决。我也想去分析程序为什么会出现泄漏，但我不知从何开始。也许可能需要学习很多 JVM 相关的知识，由于当时我的学习计划是先学习计算机基础（体系结构、操作系统、算法、网络、数据库系统等），然后在深入学习 Java 和 Java Web。所以我只能先把这个问题放着，继续学习计算机基础。然而这个问题一直在我的心中困扰着我，这也是后来促使我这么强烈地想学习 JVM 的原因。

最近一段时间一直在学习 JVM，先看了 JVM 内部的实现原理，主要是 adaptive code generation, adaptive memory management, 以及 threads and synchronization。然后看了 JVM 优化的方法，主要是如何选择 JIT compiler 和 garbage collector，如何看 GC 日志，如何使用可视化工具分析程序的运行时状态，如何调整 JVM 的参数。

经过一段时间的 JVM 的学习，我准备开始分析我之前写的 hot-crawler 这个项目。下面就是我的分析过程。

我先不设置 JVM 的内存大小，直接打印 GC 日志看有什么问题。下面是对应的 JVM options 和 GC log。

-XX:+PrintGCDetails -Xloggc:hotcrawler_jvm.log

Java HotSpot(TM) 64-Bit Server VM (25.171-b11) for windows-amd64 JRE (1.8.0_171-b11), built on Mar 28 2018 16:06:12 by "java_re" with MS VC++ 10.0 (VS2010)
Memory: 4k page, physical 16655468k(11303820k free), swap 19145836k(12290304k free)
CommandLine flags: -XX:InitialHeapSize=266487488 -XX:MaxHeapSize=4263799808 -XX:+PrintGC -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:+UseCompressedClassPointers -XX:+UseCompressedOops -XX:-UseLargePagesIndividualAllocation -XX:+UseParallelGC 
0.809: [GC (Allocation Failure) [PSYoungGen: 65536K->10724K(76288K)] 65536K->10905K(251392K), 0.0073689 secs] [Times: user=0.00 sys=0.00, real=0.01 secs] 
1.603: [GC (Allocation Failure) [PSYoungGen: 76260K->10737K(76288K)] 76441K->12235K(251392K), 0.0107562 secs] [Times: user=0.00 sys=0.00, real=0.01 secs] 
2.292: [GC (Allocation Failure) [PSYoungGen: 76273K->10728K(76288K)] 77771K->18061K(251392K), 0.0105378 secs] [Times: user=0.03 sys=0.00, real=0.01 secs] 
2.669: [GC (Allocation Failure) [PSYoungGen: 76264K->10728K(141824K)] 83597K->23640K(316928K), 0.0166216 secs] [Times: user=0.13 sys=0.00, real=0.02 secs] 
3.431: [GC (Metadata GC Threshold) [PSYoungGen: 94298K->10728K(141824K)] 107211K->30083K(316928K), 0.0206330 secs] [Times: user=0.13 sys=0.00, real=0.02 secs] 
3.452: [Full GC (Metadata GC Threshold) [PSYoungGen: 10728K->0K(141824K)] [ParOldGen: 19355K->26803K(141312K)] 30083K->26803K(283136K), [Metaspace: 20761K->20761K(1069056K)], 0.1067090 secs] [Times: user=0.53 sys=0.02, real=0.11 secs] 
4.969: [GC (Allocation Failure) [PSYoungGen: 131072K->19710K(199168K)] 157875K->46522K(340480K), 0.0136119 secs] [Times: user=0.13 sys=0.00, real=0.01 secs] 
6.407: [GC (Allocation Failure) [PSYoungGen: 198910K->21995K(265728K)] 225722K->54167K(407040K), 0.0228798 secs] [Times: user=0.16 sys=0.00, real=0.02 secs]

通过上面的 GC 日志，可以看出 HotSpot VM 把我电脑的所有可用空间（4G 多）作为了最大的堆内存空间，然后进行了若干次的 Minor GC。然后进行了一次 Full GC，增加了 Metadata 即 Permanent generation 区域的内存空间大小。然后又进行了几次 Minor GC。以上是全部的 GC 日志，后面就没有任何日志了。

通过分析直接打印 GC 日志，好像看不出什么，没什么收获。

我决定设置 JVM 各个区域的内存空间大小（heap, young generation, permanent generation），然后再观察 GC 日志有什么变化。下面是对应的 JVM options 和 GC log。

-XX:+PrintGCDetails -Xloggc:hotcrawler_jvm.log -Xms188m -Xmx188m -XX:NewSize=70m -XX:MaxNewSize=70m -XX:MetaspaceSize=48m -XX:MaxMetaspaceSize=48m

Java HotSpot(TM) 64-Bit Server VM (25.171-b11) for windows-amd64 JRE (1.8.0_171-b11), built on Mar 28 2018 16:06:12 by "java_re" with MS VC++ 10.0 (VS2010)
Memory: 4k page, physical 16655468k(8988472k free), swap 19145836k(9640588k free)
CommandLine flags: -XX:CompressedClassSpaceSize=41943040 -XX:InitialHeapSize=197132288 -XX:MaxHeapSize=197132288 -XX:MaxMetaspaceSize=50331648 -XX:MaxNewSize=73400320 -XX:MetaspaceSize=50331648 -XX:NewSize=73400320 -XX:+PrintGC -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:+UseCompressedClassPointers -XX:+UseCompressedOops -XX:-UseLargePagesIndividualAllocation -XX:+UseParallelGC 
0.662: [GC (Allocation Failure) [PSYoungGen: 54272K->8698K(62976K)] 54272K->8969K(183808K), 0.0063849 secs] [Times: user=0.00 sys=0.00, real=0.01 secs] 
1.212: [GC (Allocation Failure) [PSYoungGen: 62970K->8693K(62976K)] 63241K->11555K(183808K), 0.0120044 secs] [Times: user=0.08 sys=0.03, real=0.01 secs] 
1.519: [GC (Allocation Failure) [PSYoungGen: 62965K->8680K(62976K)] 65827K->16997K(183808K), 0.0102365 secs] [Times: user=0.00 sys=0.00, real=0.01 secs] 
1.822: [GC (Allocation Failure) [PSYoungGen: 62952K->8680K(62976K)] 71269K->21376K(183808K), 0.0082618 secs] [Times: user=0.13 sys=0.00, real=0.01 secs] 
2.123: [GC (Allocation Failure) [PSYoungGen: 62952K->8696K(62976K)] 75648K->26253K(183808K), 0.0090796 secs] [Times: user=0.13 sys=0.00, real=0.01 secs] 
2.519: [GC (Allocation Failure) [PSYoungGen: 62968K->8696K(48640K)] 80525K->30111K(169472K), 0.0105225 secs] [Times: user=0.00 sys=0.00, real=0.01 secs] 
2.890: [GC (Allocation Failure) [PSYoungGen: 48632K->13143K(55808K)] 70047K->37449K(176640K), 0.0127155 secs] [Times: user=0.11 sys=0.02, real=0.01 secs] 
3.187: [GC (Allocation Failure) [PSYoungGen: 53079K->15846K(48640K)] 77385K->45876K(169472K), 0.0092983 secs] [Times: user=0.06 sys=0.00, real=0.01 secs] 
3.740: [GC (Allocation Failure) [PSYoungGen: 48614K->14735K(52224K)] 78644K->47682K(173056K), 0.0079699 secs] [Times: user=0.00 sys=0.00, real=0.01 secs] 
3.907: [GC (Allocation Failure) [PSYoungGen: 47503K->2562K(50176K)] 80450K->48166K(171008K), 0.0091892 secs] [Times: user=0.00 sys=0.00, real=0.01 secs] 
4.044: [GC (Allocation Failure) [PSYoungGen: 33282K->1646K(32768K)] 78886K->49090K(153600K), 0.0036603 secs] [Times: user=0.11 sys=0.00, real=0.00 secs] 
4.195: [GC (Allocation Failure) [PSYoungGen: 32366K->1328K(48128K)] 79810K->50120K(168960K), 0.0050500 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
4.376: [GC (Allocation Failure) [PSYoungGen: 27952K->3178K(49152K)] 76744K->53074K(169984K), 0.0036726 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
4.543: [GC (Allocation Failure) [PSYoungGen: 29802K->2879K(49152K)] 79698K->55308K(169984K), 0.0047447 secs] [Times: user=0.13 sys=0.00, real=0.01 secs] 
4.857: [GC (Allocation Failure) [PSYoungGen: 29503K->4040K(49152K)] 81932K->58848K(169984K), 0.0043435 secs] [Times: user=0.13 sys=0.00, real=0.00 secs] 
5.262: [GC (Allocation Failure) [PSYoungGen: 30664K->1376K(49664K)] 85472K->60099K(170496K), 0.0039789 secs] [Times: user=0.09 sys=0.00, real=0.00 secs] 
5.549: [GC (Allocation Failure) [PSYoungGen: 29024K->2343K(49664K)] 87747K->62299K(170496K), 0.0041532 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
6.053: [GC (Allocation Failure) [PSYoungGen: 29991K->4762K(51200K)] 89947K->66211K(172032K), 0.0036624 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
6.323: [GC (Allocation Failure) [PSYoungGen: 34458K->1177K(50176K)] 95907K->66148K(171008K), 0.0032255 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
6.495: [GC (Allocation Failure) [PSYoungGen: 30873K->2340K(52224K)] 95844K->67544K(173056K), 0.0025049 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
6.826: [GC (Allocation Failure) [PSYoungGen: 34596K->5084K(51712K)] 99800K->71949K(172544K), 0.0051142 secs] [Times: user=0.11 sys=0.02, real=0.01 secs] 
7.002: [GC (Allocation Failure) [PSYoungGen: 37340K->2259K(53760K)] 104205K->73418K(174592K), 0.0056459 secs] [Times: user=0.00 sys=0.00, real=0.01 secs]

通过上面的 GC 日志，可用看出 HotSpot VM 实际分配的各个区域的内存比我们设置的要稍微大一点。然后 JVM 进行了多次的 Minor GC，不断地收集 Young generation 的空间，可能 Young generation 空间设置的小了一点，但也感觉不是小了，因为只有项目刚启动时有 Minor GC，后面一直都没有 Minor GC 了。

然而，重点来了，重点是现在没有了 Full GC，这说明 heap 的 Old generation 和 permanent generation 的内存是够用的。通过 Windows 操作系统的进程管理器会发现程序所占的内存远远超过 JVM 堆的内存，而且程序占用的内存还在不断的上升。通过 GC 日志感觉堆内存没什么问题，那么问题出在哪里呢？

由于 GC 日志找不出问题，于是我决定使用 JConsole 看一下程序的运行时状态。经过一段时间的观察，我似乎找到了问题的根源，那就是 thread 太多了，并且不断的在增加。下图是 thread 的变化曲线。

于是我回想代码中哪里会创建线程或线程池，我想只有一个地方创建了线程池，那就是在爬虫的定时任务中创建线程池进行页面的爬取。这行代码如下所示：

ExecutorService executorService = Executors.newFixedThreadPool(threadPoolNum);

虽然这行创建线程池没什么问题，但是我把创建线程池的代码写在了定时任务执行的方法中，因此，每执行一次任务，就会创建一个线程池和若干的线程。我立刻把线程池定义成了成员变量，然后观察 JVM 的内存和线程，发现一切都稳定、正常了。内存空间和线程数不会一直增加。下图是修复代码后的线程变化图：

通过自己的努力，我终于解决了那个积压已久的问题。在重新部署后的那一刻，我内心是无比的兴奋与激动。

以前自己写代码主要在乎功能的实现，经过这个教训，更让我懂得了软件的性能和稳定性的重要性。