時不時的我就會聽見有人抱怨說,他的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。這就能解釋為什么應用程序這么久沒有響應,也讓這個龐氏騙局的受害者們知道,他們現在到底是什么情況。
原創文章轉載請注明出處:http://it.deepinmind.com
英文原文鏈接