一次CMS GC問題排查過程（理解原理+讀懂GC日誌）

轉自 http://itindex.net/detail/47030-cms-gc-%E9%97%AE%E9%A2%98

這個是以前處理過的一個線上問題，處理過程斷斷續續，經歷了兩週多的時間，中間各類嘗試，總結以下。這篇文章分三部分：

一、問題的場景和處理過程；二、GC的一些理論東西；三、看懂GC的日誌

先說一下問題吧

問題場景：線上機器在半夜會推送一個700M左右的數據，這個時候有個數據置換的過程，也就是說有700M*2的數據在heap區域中，線上系統超時比較多，致使了很嚴重（嚴重程度就不說了）的問題。

問題緣由：看日誌，系統接口超時的時候，系統出現了FullGC，這個時候stop-the-world了，也就停機了。分析gc的日誌，發現有promotion failed，根據FullGC觸發的條件，這個時候就會出現FullGC了。日誌以下：

1 2 2013 - 11 -27T03: 00 : 53.638 + 0800 : 35333.562 : [GC 35333.562 : [ParNew (promotion failed): 1877376K->1877376K(1877376K), 15.7989680 secs] 35349.361 : [CMS: 2144171K->2129287K(2146304K), 10.4200280 sec s] 3514052K->2129287K(4023680K), [CMS Perm : 119979K->118652K(190132K)], 26.2193500 secs] [Times: user= 30.35 sys= 5.19 , real= 26.22 secs] 問題解決：中間調整過幾回，先搞了幾臺機器作了驗證，後來逐步推廣的。

一、調大heap區，由原來的4g，調整到5g，young區的大小不變，仍是2g，這時候old區就由2g變爲3g了（這樣保證old區有足夠的空間）；

二、設置-XX：UseCMSInitiatingOccupancyOnly，其實這個不關這個問題，只是發現半夜CMS進行的有點頻繁，就禁止掉了悲觀策略；

三、設置CMS區回收的比例，從80%調整到75%，讓old區儘早的進行，有足夠的空間剩餘；

爲何要有GC（垃圾回收）？

JVM經過GC來回收堆和方法區中的內存，GC的基本原理就是找到程序中再也不被使用的對象，而後回收掉這些對象佔用的內存。

主要的收集器有哪些？

引用計數器和跟蹤計數器兩種。

引用計數器記錄對象是否被引用，當計數器爲零時，說明對象已經再也不被使用，能夠進行回收。java中的對象有複雜的引用關係，不是很適合引用計數器，因此sun jdk中並無實現這種GC方式。

跟蹤收集器，全局記錄數據的引用狀態，基於必定的條件觸發。執行的時候，從根集合開始掃描對象的引用關係，主要有複製（copying）、標記-清除（Mark-Sweep）、標記-壓縮(Mark-Compact)那種算法。

跟蹤計數器的三種算法簡介？

複製：從根集合搜掃描出存活的對象，而後將存活的對象複製到一塊新的未使用的空間中，當要回收的空間中存活的對象較少時，比較高效；

標記清除：從根集合開始掃描，對存活的對象進行標記，比較完畢後，再掃描整個空間中未標記的對象，而後進行回收，不須要對對象進行移動；

標記壓縮：標記形式和「標記清除」同樣，可是回收不存活的對象後，會把全部存活的對象在內存空間中進行移動，好處是減小了內存碎片，缺點是成本比較高；

java內存區域的形式是啥樣的？

這裏就再也不介紹了，以前有一篇文章中專門介紹這個的（ http://iamzhongyong.iteye.com/blog/1333100）。

新生代可用的GC？

新生代中對象存活的時間比較短，所以給予Copying算法實現，Eden區域存放新建立的對象，S0和S1區其中一塊用於存放在Minor GC的時候做爲複製存活對象的目標空間，另一塊清空。

串行GC（Serial GC）比較適合單CPU的狀況，能夠經過-XX：UseSerialGC來強行制定；

並行回收GC（Parallel Scavenge），啓動的時候按照設置的參數來劃定Eden/S0/S1區域的大小，可是在運行時，會根據Minor GC的頻率、消耗時間來動態調整三個區域的大小，能夠用過-XX：UseAdaptiveSizePolicy來固定大小，不進行動態調整；

並行GC（ParNew）劃分Eden、S一、S0的區域上和串行GC同樣。並行GC須要配合舊生代使用CMS GC（這是他和並行回收GC的不一樣）（若是配置了CMS GC的方式，那麼新生代默認採起的就是並行GC的方式）；

啥時候會觸發Minor GC？

當Eden區域分配內存時，發現空間不足，JVM就會觸發Minor GC，程序中System.gc()也能夠來觸發。

舊生代可用的GC方式有哪幾種？

串行GC（Serial MSC）、並行GC（Parallel MSC）、併發GC（CMS）；

關於CMS？

採用CMS時候，新生代必須使用Serial GC或者ParNew GC兩種。CMS共有七個步驟，只有Initial Marking和Final Marking兩個階段是stop-the-world的，其餘步驟均和應用並行進行。持久代的GC也採用CMS，經過-XX：CMSPermGenSweepingEnabled -XX：CMSClassUnloadingEnabled來制定。在採用cms gc的狀況下，ygc變慢的緣由一般是因爲old gen出現了大量的碎片。

爲啥CMS會有內存碎片，如何避免？

因爲在CMS的回收步驟中，沒有對內存進行壓縮，因此會有內存碎片出現，CMS提供了一個整理碎片的功能，經過-XX：UseCompactAtFullCollection來啓動此功能，啓動這個功能後，默認每次執行Full GC的時候會進行整理（也能夠經過-XX：CMSFullGCsBeforeCompaction=n來制定多少次Full GC以後來執行整理），整理碎片會stop-the-world.

啥時候會觸發CMS GC？

一、舊生代或者持久代已經使用的空間達到設定的百分比時（ CMSInitiatingOccupancyFraction 這個設置old 區，perm 區也能夠設置）；

二、JVM自動觸發(JVM的動態策略，也就是悲觀策略 )（ 基於以前GC的頻率以及舊生代的增加趨勢來評估決定何時開始執行 ），若是不但願JVM自行決定，能夠經過-XX：UseCMSInitiatingOccupancyOnly=true來制定；

啥時候會觸發Full GC？

1、舊生代空間不足：java.lang.outOfMemoryError：java heap space；

2、Perm空間滿：java.lang.outOfMemoryError：PermGen space；

3、CMS GC時出現promotion failed 和concurrent mode failure（Concurrent mode failure發生的緣由通常是CMS正在進行，可是因爲old區內存不足，須要儘快回收old區裏面的死的java對象，這個時候foreground gc須要被觸發，中止全部的java線程，同時終止CMS，直接進行MSC。）；

4、統計獲得的minor GC晉升到舊生代的平均大小大於舊生代的剩餘空間；

5、主動觸發Full GC（執行jmap -histo:live [pid]）來避免碎片問題；

爲啥heap小於3g不建議使用CMS GC這種方式？

http://hellojava.info/?p=142 畢大師的這篇文章講的很清楚。

一、觸發比例很差設置，設置大了，那麼剩餘的空間就少了不少，設置小了，那old區還沒放置多少東西，就要進行回收了；

二、CMS進行的時候，是並行的，也就意味着若是過於頻繁的話，會和應用的強佔CPU；

三、CMS會有內存 碎片問題；

四、YGC的速率變慢（因爲CMS GC的實現原理，致使對象重新生代晉升到舊生代時，尋找哪裏能放下的這個步驟比ParallelOld GC是慢一些的，所以就致使了YGC速度會有必定程度的降低。）；

JVM的悲觀策略是啥？

所謂的悲觀策略（ http://tmalltesting.com/archives/663 咱們性能測試團隊一個同窗分析的案例），就是JVM不按照JVM指定的參數來進行CMS GC，而是根據內存狀況以及以前回收的方式動態調整，自行進行GC。舊生代剩餘的空間（available）大於新生代中使用的空間（max_promotion_in_bytes），或者大於以前平均晉升的old的大小（av_promo），返回false。cms gc是每隔一個週期（默認2s）就會作一次這個檢查，若是爲false，則不執行YGC，而觸發cms gc。

咱們常用的是啥GC方式？

針對目前線上機器的狀況（8G的物流內存），heap區通常設置在4g或者5g左右，通常是使用CMS GC，這時候：

young區使用ParNew（並行GC），Old+Perm(須要單獨設置)使用CMS，整個堆（young+old+perm）使用MSC（（Mark Sweep Compact）是CMS GC算法的Full GC算法,單線程回收整個堆，回收過程有嚴格的步驟。壓縮，因此回收完理論上任何Generation都不會有內存碎片）壓縮回收的方式。

讀懂GC日誌？

基本上都是這種格式：回收前區域佔用的大小->回收後區域佔用的大小（區域設置的大小），佔用的時間

一、promotion failed的一段日誌

1 2 2013 - 11 -27T03: 00 : 53.638 + 0800 : 35333.562 : [GC 35333.562 : [ParNew (promotion failed): 1877376K->1877376K(1877376K), 15.7989680 secs] 35349.361 : [CMS: 2144171K->2129287K(2146304K), 10.4200280 sec s] 3514052K->2129287K(4023680K), [CMS Perm : 119979K->118652K(190132K)], 26.2193500 secs] [Times: user= 30.35 sys= 5.19 , real= 26.22 secs] 解釋以下：

1 2 3 4 5 1877376K->1877376K(1877376K), 15.7989680 secs young區 2144171K->2129287K(2146304K), 10.4200280 sec old區狀況 3514052K->2129287K(4023680K) heap區狀況 119979K->118652K(190132K)], 26.2193500 secs perm區狀況 [Times: user= 30.35 sys= 5.19 , real= 26.22 secs] 整個過程的時間消耗

二、一段正常的CMS的日誌

1 2 3 4 5 6 7 8 9 10 11 12 13 14 2013 - 11 -27T04: 00 : 12.819 + 0800 : 38892.743 : [GC [ 1 CMS-initial-mark: 1547313K(2146304K)] 1734957K(4023680K), 0.1390860 secs] [Times: user= 0.14 sys= 0.00 , real= 0.14 secs] 2013 - 11 -27T04: 00 : 12.958 + 0800 : 38892.883 : [CMS-concurrent-mark-start] 2013 - 11 -27T04: 00 : 19.231 + 0800 : 38899.155 : [CMS-concurrent-mark: 6.255 / 6.272 secs] [Times: user= 8.49 sys= 1.57 , real= 6.27 secs] 2013 - 11 -27T04: 00 : 19.231 + 0800 : 38899.155 : [CMS-concurrent-preclean-start] 2013 - 11 -27T04: 00 : 19.250 + 0800 : 38899.175 : [CMS-concurrent-preclean: 0.018 / 0.019 secs] [Times: user= 0.02 sys= 0.00 , real= 0.02 secs] 2013 - 11 -27T04: 00 : 19.250 + 0800 : 38899.175 : [CMS-concurrent-abortable-preclean-start] CMS: abort preclean due to time 2013 - 11 -27T04: 00 : 25.252 + 0800 : 38905.176 : [CMS-concurrent-abortable-preclean: 5.993 / 6.002 secs] [Times: user= 6.97 sys= 2.16 , real= 6.00 secs] 2013 - 11 -27T04: 00 : 25.253 + 0800 : 38905.177 : [GC[YG occupancy: 573705 K ( 1877376 K)] 38905.177 : [Rescan (parallel) , 0.3685690 secs] 38905.546 : [weak refs processing, 0.0024100 secs] 38905.548 : [cla ss unloading, 0.0177600 secs] 38905.566 : [scrub symbol & string tables, 0.0154090 secs] [ 1 CMS-remark: 1547313K(2146304K)] 2121018K(4023680K), 0.4229380 secs] [Times: user= 1.41 sys= 0.01 , real= 0.43 secs] 2013 - 11 -27T04: 00 : 25.676 + 0800 : 38905.601 : [CMS-concurrent-sweep-start] 2013 - 11 -27T04: 00 : 26.436 + 0800 : 38906.360 : [CMS-concurrent-sweep: 0.759 / 0.760 secs] [Times: user= 1.06 sys= 0.48 , real= 0.76 secs] 2013 - 11 -27T04: 00 : 26.436 + 0800 : 38906.360 : [CMS-concurrent-reset-start] 2013 - 11 -27T04: 00 : 26.441 + 0800 : 38906.365 : [CMS-concurrent-reset: 0.005 / 0.005 secs] [Times: user= 0.00 sys= 0.00 , real= 0.00 secs] 這個是一個正常的CMS的日誌，共分爲七個步驟，重點關注initial-mark和remark這兩個階段，由於這兩個是停機的。

A、[GC [1 CMS-initial-mark: 1547313K(2146304K)] 1734957K(4023680K), 0.1390860 secs] [Times: user=0.14 sys=0.00, real=0.14 secs]

各個數據依次表示標記先後old區的全部對象佔內存大小和old的capacity，整個JavaHeap（不包括perm）全部對象佔內存總的大小和JavaHeap的capacity。

B、2013-11-27T04:00:25.253+0800: 38905.177: [GC[YG occupancy: 573705 K (1877376 K)]38905.177: [Rescan (parallel) , 0.3685690 secs]38905.546: [weak refs processing, 0.0024100 secs]38905.548: [class unloading, 0.0177600 secs]38905.566: [scrub symbol & string tables, 0.0154090 secs] [1 CMS-remark: 1547313K(2146304K)] 2121018K(4023680K), 0.4229380 secs] [Times: user=1.41 sys=0.01, real=0.43 secs]

Rescan (parallel)表示的是多線程處理young區和多線程掃描old+perm的卡表的總時間， parallel 表示多GC線程並行。

weak refs processing 處理old區的弱引用的總時間，用於回收native memory。

class unloading 回收SystemDictionary消耗的總時間。

三、一段正常的Young GC的日誌

1 2 2013 - 11 -27T04: 00 : 07.345 + 0800 : 38887.270 : [GC 38887.270 : [ParNew: 1791076K->170624K(1877376K), 0.2324440 secs] 2988366K->1413629K(4023680K), 0.2326470 secs] [Times: user= 0.80 sys= 0.00 , real= 0 . 23 secs] ParNew這個代表是並行的回收方式，具體的分別是young區、整個heap區的狀況；

四、一段經過system.gc產生的FullGC日誌

1 2013 - 07 -21T17: 44 : 01.554 + 0800 : 50.568 : [Full GC (System) 50.568 : [CMS: 943772K->220K(2596864K), 2.3424070 secs] 1477000K->220K(4061184K), [CMS Perm : 3361K->3361K(98304K)], 2.3425410 secs] [Times: user= 2.33 sys= 0.01 , real= 2.34 secs] 解釋以下：

Full GC (System)意味着這是個system.gc調用產生的MSC。

「943772K->220K(2596864K), 2.3424070 secs」表示：此次MSC先後old區內總對象大小，old的capacity及此次MSC耗時。

「1477000K->220K(4061184K)」表示：此次MSC先後JavaHeap內總對象大小，JavaHeap的capacity。

「3361K->3361K(98304K)], 2.3425410 secs」表示：此次MSC先後Perm區內總對象大小，Perm區的capacity。

五、一個特殊的GC日誌，根據動態計算直接進行的FullGC（MSC的方式）

1 2013 - 03 -13T13: 48 : 06.349 + 0800 : 7.092 : [GC 7.092 : [ParNew: 471872K->471872K(471872K), 0.0000420 secs] 7.092 : [CMS: 366666K->524287K(524288K), 27.0023450 secs] 838538K->829914K(996160K), [CMS Perm : 3196K->3195K(131072K)], 27.0025170 secs] ParNew的時間特別短，jvm在minor gc前會首先確認old是否是足夠大，若是不夠大，此次young gc直接返回，進行MSC。