HotSpot JVM就是個龐氏騙局

jopen 11年前發布 | 30K 次閱讀 JVM

　　英文原文：The Hotspot JVM is a Ponzi Scheme [guest post]

　　正好今天是愚人節，就來說點騙子的東西吧~

　　時不時的我就會聽見有人抱怨說，他的 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)
    4. </ol>

    　　我們再進一步的分析下：

    1. 堆的總大小是126912K

    2. 其中新生代的大小是19136K.

    3. 這意味著老生代是107776K.
      4. </ol>

      　　再稍微計算一下我們會發現，老生代是 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。這就能解釋為什么應用程序這么久沒有響應，也讓這個龐氏騙局的受害者們知道，他們現在到底是什么情況。

                          <span id="shareA4" class="fl">                          </span>
       本文由用戶 jopen 自行上傳分享，僅供網友學習交流。所有權歸原作者，若您的權利被侵害，請聯系管理員。
       轉載本站原創文章，請注明出處，并保留原始鏈接、圖片水印。
       本站是一個以用戶分享為主的開源技術平臺，歡迎各類分享！
        本文地址：http://www.baiduhome.net/news/view/a169ce