HotSpot JVM就是个庞氏骗局

Published: 01 Apr 2014 Category: GC

正好今天是愚人节，就来说点骗子的东西吧~

时不时的我就会听见有人抱怨说，他的HotSpot JVM不停的在垃圾回收，可是每次回收完后堆却还是满的。当他们发现这是因为JVM的内存已经不够了之后，通常会问这么个问题，为什么JVM不抛一个OutOfMemoryError(OOME)呢？毕竟来说，由于内存不足，我的程序都已经没法继续跑了，对吧？

先说重要的，如果你运气好的话，你永远不会发现你的JVM其实在你身上下了个庞氏骗局的套。它会一直告诉你，你的内存是无限的，就只管去用就好了。JVM的垃圾回收器会一直维持这么个错觉，在内存这一亩三分地上，啥事都好着呢。

然而在这个领域里可不止这一个庞氏骗局而已。操作系统处理内存也是这么副德性。你会不停的分配本地内存，直到最后触发了虚拟内存的交换，这下你就惨了——虽然程序没有完全停止，不过也差不多了，因为磁盘的速度跟内存比起来差太多了。

为了维持这个错觉，垃圾回收器会使用一个叫安全点（Safe Point)的咒语来冻结时间，应用程序根本不知道发生了什么。然而你的程序停止的时间长点是无所谓，但对于使用你的应用程序的人来说，时间可不是冻结的。如果你的应用程序的存活数据很多的话，垃圾回收器得费很大劲来维持这个错觉。你的程序可能不知道时间冻结得有多频繁，多久，但你的用户肯定知道！

由于你的程序相信你的JVM，而你的JVM也一直很努力，很英勇地（甚至有点傻）工作，来维持这种错觉，最后演出终于露馅的时候，你会想，为什么我的应用程序没有抛一个OOME出来呢？

使用ParNew新生代回收算法（和CMS配套使用）

我们来看一段GC日志，来看下能不能搞清楚是怎么回事，我们从一段大概10秒的日志的开头看起。

85.578: [GC 85.578: [ParNew: 17024K->2110K(19136K), 0.0352412 secs] 113097K->106307K(126912K), 0.0353280 secs]

这是一个正常完成的新生代并行回收的过程，通常这是由于新生代的eden区内存分配失败触发的。来看下里面的数据：

  1. 所有的存活对象占用的空间是
    106307K
    .
  2. Survivor区的已使用空间是
    2110K
  3. 这说明老生代中的对象占用的空间是
    104197K
    (106307-2110)

我们再进一步的分析下：

  1. 堆的总大小是
    126912K
  2. 其中新生代的大小是
    19136K
    .
  3. 这意味着老生代是
    107776K
    .

再稍微计算一下我们会发现，老生代是104197K/107776K也就是已经使用了97%了，这已经相当危险了！

CMS上场了

下面的一组日志表明，前面的ParNew回收是在一次CMS周期里执行的，而这次CMS已经完成了。不过这次CMS周期结束后紧接着又是一次CMS。为什么呢，因为前面那次CMS只回收了104197K-101397K = 2800K内存，这大概只是老生代的2.5%，于是只能继续GC了，但这暴露出一个严重的问题！

86.306: [CMS-concurrent-abortable-preclean: 0.744/1.546 secs]
86.306: [GC[YG occupancy: 10649 K (19136 K)]86.306: [Rescan (parallel) , 0.0039103 secs]86.310: [weak refs processing, 0.0005278 secs] [1 CMS-remark: 104196K(107776K)] 114846K(126912K), 0.0045393 secs]
86.311: [CMS-concurrent-sweep-start]
86.366: [CMS-concurrent-sweep: 0.055/0.055 secs]
86.366: [CMS-concurrent-reset-start]
86.367: [CMS-concurrent-reset: 0.001/0.001 secs]
86.808: [GC [1 CMS-initial-mark: 101397K(107776K)] 119665K(126912K), 0.0156781 secs]

看来在这样的情况下，一个并发模式失败（Concurrent Mode Failure）的错误是必不可少的。

接下来是Concurrent Mode Failure

下面这段日志说明，对于垃圾回收器来说，糟糕的事情发生了，CMS concurrent-mark刚准备开始工作，而讨厌的ParNew又想把一堆数据提升到老生代来，但是现在空间已经不够了。

86.824: [CMS-concurrent-mark-start]
86.875: [GC 86.875: [ParNew: 19134K->19134K(19136K), 0.0000167 secs]86.875: [CMS87.090: [CMS-concurrent-mark: 0.265/0.265 secs]
 (concurrent mode failure): 101397K->107775K(107776K), 0.7588176 secs] 120531K->108870K(126912K), [CMS Perm : 15590K->15589K(28412K)], 0.7589328 secs]

更糟糕的是，ParNew试图分配内存，于是CMS回收只能失败了（concurrent mode failure），为了不让程序知道发生了什么，以便让这个游戏继续下去，GC决定使用它的杀手锏，Full GC。不过尽管用了这个大招，结果也并不妙，因为Full GC回收完后老生代还有107775K在使用而总的大小才只有107776K！内存几乎是100%用完了。当然现在还能继续运行，因为新生代占用的1095K(108870K-107775k)已经全塞到survivor区里了。这已经是千钧一发的时刻了，GC为了维持这个庞氏骗局，只能继续垂死挣扎。

再来一次Full GC

为了解决内存不足的问题，第二个Full GC现在上场了。这次发生在JVM启动后的87.734秒。前面一次暂停的时间是0.7589328秒。加上上次Full GC开始的时间86.875结果是87.634秒，也就是说应用程序只执行了100ms又开始被中断了。

这个英勇的行为为GC又赢取到了一次宝贵的时间，在下一次CMS开始之前，ParNew的一次失败直接唤起了 Full GC,它还一直欺骗应用程序说现在一切都很好，其实不然。

87.734: [Full GC 87.734: [CMS: 107775K->107775K(107776K), 0.5109214 secs] 111054K->109938K(126912K), [CMS Perm : 15589K->15589K(28412K)], 0.5110117 secs]

悲剧仍在继续

一轮又一轮的CMS以及伴随着的concurrent mode failures都表明了，虽然垃圾回收器还在力图维持局面，但说实话你得考虑下这个代价是不是有点太大了，这个时候是不是抛一个什么警告或者错误更好一些。

88.246: [GC [1 CMS-initial-mark: 107775K(107776K)] 109938K(126912K), 0.0040875 secs]
88.250: [CMS-concurrent-mark-start]
88.640: [CMS-concurrent-mark: 0.390/0.390 secs] 
88.640: [CMS-concurrent-preclean-start]
88.844: [CMS-concurrent-preclean: 0.204/0.204 secs]
88.844: [CMS-concurrent-abortable-preclean-start]
88.844: [CMS-concurrent-abortable-preclean: 0.000/0.000 secs]
88.844: [GC[YG occupancy: 11380 K (19136 K)]88.844: [Rescan (parallel) , 0.0109385 secs]88.855: [weak refs processing, 0.0002293 secs] [1 CMS-remark: 107775K(107776K)] 119156K(126912K), 0.0112696 secs]
88.855: [CMS-concurrent-sweep-start]
88.914: [CMS-concurrent-sweep: 0.059/0.059 secs]
88.914: [CMS-concurrent-reset-start]
88.915: [CMS-concurrent-reset: 0.001/0.001 secs]
89.260: [GC 89.260: [ParNew: 19135K->19135K(19136K), 0.0000156 secs]89.260: [CMS: 105875K->107775K(107776K), 0.5703972 secs] 125011K->116886K(126912K), [CMS Perm : 15589K->15584K(28412K)], 0.5705219 secs]
89.831: [GC [1 CMS-initial-mark: 107775K(107776K)] 117010K(126912K), 0.0090772 secs]
89.840: [CMS-concurrent-mark-start]
90.192: [CMS-concurrent-mark: 0.351/0.352 secs]
90.192: [CMS-concurrent-preclean-start]
90.343: [Full GC 90.343: [CMS90.379: [CMS-concurrent-preclean: 0.187/0.187 secs]
 (concurrent mode failure): 107775K->104076K(107776K), 0.5815666 secs] 126911K->104076K(126912K), [CMS Perm : 15586K->15585K(28412K)], 0.5816572 secs]
90.973: [GC [1 CMS-initial-mark: 104076K(107776K)] 104883K(126912K), 0.0025093 secs]
90.976: [CMS-concurrent-mark-start]
91.335: [CMS-concurrent-mark: 0.359/0.359 secs]
91.335: [CMS-concurrent-preclean-start]
91.367: [CMS-concurrent-preclean: 0.031/0.032 secs]
91.367: [CMS-concurrent-abortable-preclean-start]
92.136: [GC 92.136: [ParNew: 17024K->17024K(19136K), 0.0000167 secs]92.136: [CMS92.136: [CMS-concurrent-abortable-preclean: 0.054/0.769 secs]
 (concurrent mode failure): 104076K->107775K(107776K), 0.5377208 secs] 121100K->110436K(126912K), [CMS Perm : 15588K->15586K(28412K)], 0.5378416 secs]
92.838: [GC [1 CMS-initial-mark: 107775K(107776K)] 112679K(126912K), 0.0050877 secs]
92.843: [CMS-concurrent-mark-start]
93.209: [CMS-concurrent-mark: 0.366/0.366 secs]
93.209: [CMS-concurrent-preclean-start]
93.425: [CMS-concurrent-preclean: 0.215/0.215 secs]
93.425: [CMS-concurrent-abortable-preclean-start]
93.425: [CMS-concurrent-abortable-preclean: 0.000/0.000 secs]
93.425: [GC[YG occupancy: 13921 K (19136 K)]93.425: [Rescan (parallel) , 0.0130859 secs]93.438: [weak refs processing, 0.0002302 secs] [1 CMS-remark: 107775K(107776K)] 121697K(126912K), 0.0134232 secs]
93.439: [CMS-concurrent-sweep-start]
93.505: [CMS-concurrent-sweep: 0.067/0.067 secs]
93.506: [CMS-concurrent-reset-start]
93.506: [CMS-concurrent-reset: 0.001/0.001 secs]

那么对JVM来说到底什么才是内存不足？

定义内存不足

显而易见，Java堆的内存太小了，不足以维持应用程序的运行。大点的堆能让GC把这个庞氏骗局一直持续下去。不过应用程序并没有意味到问题的出现，但终端用户肯定是知道的。我们非常希望应用程序能在用户发觉之前发现这个问题。不幸的是我们没有一个AlmostOutOfMemoryError的异常，不过我们可以通过调整GCTimeLimit和GCHeapFreeLimit参数来重新定义何时抛出OutOfMemoryError错误。

GCTimeLimit 的默认值是98%，也就是说如果98%时间都用花在GC上，则会抛出OutOfMemoryError。GCHeapFreeLimit 是回收后可用堆的大小。默认值是2%。

如果我们分析下GC日志里面的数据可以发现，GC刚刚好没有超出这两个参数的阈值。因此GC会一直维持这个庞氏骗局。但是这两个值又设置的有点太武断了，你可以重新定义下它们，来告诉GC，如果你这么努力工作就是为了维持这个错觉的话，或者你还是认输好一点，让应用程序能够知道它的内存已经用得差不多了。在这里把GCHeapFreeLimit设置成5%，GCTimeLimit设置成90%，来触发一个OutOfMemoryError。这就能解释为什么应用程序这么久没有响应，也让这个庞氏骗局的受害者们知道，他们现在到底是什么情况。

原创文章转载请注明出处：HotSpot JVM就是个庞氏骗局

英文原文链接