JVM内存GC的骗局——JVM不抛出OOM但内存已经泄露

概述

在平常测试中，咱们会去重点观察java的内存使用状况，好比：进程会抛出OOM异常，再也不接收新的请求；响应时间在固定时间段内变长，超时或者不响应，CPU使用率时常像过山车同样等。有时候JVM还会发生欺骗你的场景， JVM不停的在垃圾回收，但是每次回收完后堆却仍是满的，很明显程序内存被使用完了，已经没法正常工做了，但JVM就是不抛出OutOfMemoryError(OOM)这个异常来告诉程序员内部发出了什么，只是不停的作老好人尝试帮咱们作垃圾回收，把服务器的资源耗光了，可是此时服务器已经没法响应用户的正常请求了，让咱们一块儿来看看这些状况发生时候的现象，体会一下被欺骗的感受。

现状：

       同事在模拟用户不停的发送请求给某系统，在运行一段时间后，忽然，系统上邮件报告测试用例请求失败，登陆测试系统的服务器，首先看下JVM的参数设置，以下：

-server –Xms4g –Xmx4g -XX:MaxPermSize=256m  -verbose:gc -XX:+PrintGCDetails -Xloggc:$CATALINA_BASE/logs/gc.log -XX:+PrintGCTimeStamp，再使用TOP命令看看服务器发生了什么。

观察一段时间后，CPU一直运行在100%，因而想固然的认为多是那段程序里面触发了BUG,有多是正则表达式或者某段代码里面有个死循环的坑跳进去，没有出来。这不是很简单的事吗？直接使用jstack + pid 把堆栈打出来便可，直接操做吧，界面上立刻输出操做日志，因为日志过多而且其余的日志相似，帮只截取部分以下：

从上面的堆栈日志能够看出，全部的线程都被BLOCKED住了，而后堆栈里面也找不到任何业务的相关代码，难道直觉出错了，感受一会儿不太好了，可是至少能够排查到不是上面的二种缘由了，好吧，那再看看应用的GC的状况，部分日志以下。

1403682.561: [GC [PSYoungGen: 1375104K->11376K(1386176K)] 4145665K->2782002K(4182400K), 0.0174410 secs] [Times: user=0.27 sys=0.00, real=0.02 secs]

1407799.743: [GC [PSYoungGen: 1386160K->11632K(1386432K)] 4156786K->2793538K(4182656K), 0.0285330 secs] [Times: user=0.48 sys=0.00, real=0.03 secs]

1409230.024: [GC [PSYoungGen: 1386416K->10688K(1377984K)] 4168322K->2803822K(4174208K), 0.0265000 secs] [Times: user=0.43 sys=0.00, real=0.02 secs]

1409230.051: [Full GC [PSYoungGen: 10688K->7014K(1377984K)] [PSOldGen: 2793134K->2796224K(2796224K)] 2803822K->2803238K(4174208K) [PSPermGen: 48439K->48439K(262144K)], 7.8892780 secs] [Times: user=7.92 sys=0.00, real=7.89 secs]

1410502.582: [Full GC [PSYoungGen: 1366336K->85344K(1377984K)] [PSOldGen: 2796224K->2796224K(2796224K)] 4162560K->2881568K(4174208K) [PSPermGen: 48577K->48577K(262144K)], 8.2720110 secs] [Times: user=8.29 sys=0.00, real=8.27 secs]

 

解释一下：

第一行：
1403682.561: [GC [PSYoungGen: 1375104K->11376K(1386176K)] 4145665K->2782002K(4182400K), 0.0174410 secs] [Times: user=0.27 sys=0.00, real=0.02 secs]

发生的时间点，：JVM运行的时间长度，以度为单位，也能够格式化成固定的时间格式

PSYoungGen：发生了何种类型的GC，此处表明发生了年轻代的GC

1375104K：回收前的大小

11376K：回收后的大小

1386176K：YOUNG代的大小

4145665 K：回收前总的占用大小

2782002K：回收后的占用大小

4182400K：总占用大小

0.27和0.00：表明在用户态(user)和系统状(sys)的CPU运行时间

0.02 secs：表明实际的GC的运行时间

注：上面总的运行时间小于用户态和系统态的时间总和，是因为后者仅指CPU的运行时间，包括等待或IO阻塞的时间，并且如今的GC是采用多线程收集的，同时机器也是多个CPU，所以，大部分是两者之和要比前面的值大，若是是采用串形化收集器( serial collector)的话，两者时间几乎相差很少。关于各类收集器的差异，后续有时间再安排详细总结。

接下来的二行，再也不重复说明，第四行有Full字样，表明JVM发生了Full GC，不过多了二个分区的收集，PSOldGen：老生代的回收先后空间大小及总空间；PSPermGen：持久代的回收先后空间大小和总空间。从第三行，能够看出老空间的使用率达到饱和，从而触发了FULL GC，可是很遗憾的是第五行后又接着发生了FULL GC，后面的都是一直在持续进行，可是系统一直不抛出OOM异常或者进程退出，致使这台机器服务进程一直存在，可是基本没法正常工做。

GC，不管Young GC仍是Full GC，每次都会致使JVM STW(STOP WORLD)暂停用户的业务工做，来处理垃圾回收任务，短期内没法响应用户请求，特别是大量的Full GC会致使系统响应速度下降，另外还有OOM的巨大风险。Young GC频繁，就算GC采用多线程回收方式，尽管回收的时候很是短，可是若是GC次数和频率很高，所以对应用的影响是不可忽视的。 Full GC 包括整个分区的垃圾回收，包括新生代、旧生代、持久代等。所以其回收成本高，应用也会暂停更长时间，没法及时响应用户的请求，因此须要特别注意这个种状况，通常来说，排除主动的调用GC操做外，JVM会在如下几种状况发生Full GC。  

1. 旧生代内存不足

2. 持久代内存不足

3. 统计新生代 GC晋升到旧生代的平均大小大于旧生代的剩余空间

  

解决

       知道发生的缘由后，就可使用JMAP -heap直接看一下JVM内存的对像值，或者使用JMAP -dump直接JVM的堆栈DUMP出来，使用MAT打开分析就行。若是这种现像发生以后，DUMP出来的文件会较大，有些会达到十多个G，由于通常不直接在工做机器上进行，须要把文件转发到其余的非线上服务而且内存足够的机器上分析，最后能够用MAT把分析后的文件打开便可，操做结果以下：

第四行里面看不出实际的业务相关的，第五行到六行仍是能够看出来的，那就先看第四行的对象包括什么具体的实例吧。

打开后，首页会给出可疑的建议对象实例，直接跳转到列表中，打开折叠细节便可看到真面目，里面包括了三十多万个对象，找相关的人员对根据业务须要，直接把不须要的实例在使用完后移除，其余几行的问题相似处理就便可。

总结

       从上面GC的发生的状况来看，JVM一次次不停的努力的帮咱们进行GC操做，直接把CPU所有占光，可是就是不直接抛出异常直接告诉咱们内存不够了，感受把咱们带了到一个巨大的庞氏骗局，也许咱们把JVM的内存加大，这个坑还将帮咱们隐藏下去，若是程序设置了定时重启之类的操做，这个坑就永远发现不了。通常产品开发人员很是但愿应用程序能在用户发觉以前发现这个问题，JVM没法判断出这个问题，也就不能帮咱们抛出几乎OOM的异常，不过能够经过调整GCTimeLimit和GCHeapFreeLimit参数来从新定义什么时候抛出OutOfMemoryError错误。GCTimeLimit 的默认值是98%，也就是说若是98%时间都用花在GC上，则会抛出OutOfMemoryError。GCHeapFreeLimit 是回收后可用堆的大小。默认值是2%。固然最好的办法就是开发工程师开始就很清楚如何使用相关的容器类的正确用法，而且在上线前能通过充分的测试或运行。本文只是引用GC方面的一个具体的安全来讲明GC是怎么骗人的，关于GC和JVM内存相关的细节如何及时的发现此类的问题，有机会再经过示例和你们探讨学习。

 

注：以上资料仅以HOTSPOT VM 1.7.65 版本参考。

 

 

本文章为做者原创

🈲禁止🈲

其余公众帐号转载，如有转载，请标明出处