一次CMS GC問題排查過程(理解原理+讀懂GC日誌)
這個是之前處理過的一個線上問題,處理過程斷斷續續,經歷了兩週多的時間,中間各種嘗試,總結如下。這篇文章分三部分:
1、問題的場景和處理過程;2、GC的一些理論東西;3、看懂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]
|
問題解決:中間調整過幾次,先搞了幾臺機器做了驗證,後來逐步推廣的。
1、調大heap區,由原來的4g,調整到5g,young區的大小不變,還是2g,這時候old區就由2g變為3g了(這樣保證old區有足夠的空間);
2、設定-XX:UseCMSInitiatingOccupancyOnly,其實這個不關這個問題,只是發現半夜CMS進行的有點頻繁,就禁止掉了悲觀策略;
3、設定CMS區回收的比例,從80%調整到75%,讓old區儘早的進行,有足夠的空間剩餘;
為什麼要有GC(垃圾回收)?
JVM通過GC來回收堆和方法區中的記憶體,GC的基本原理就是找到程式中不再被使用的物件,然後回收掉這些物件佔用的記憶體。
主要的收集器有哪些?
引用計數器和跟蹤計數器兩種。
引用計數器記錄物件是否被引用,當計數器為零時,說明物件已經不再被使用,可以進行回收。java中的物件有複雜的引用關係,不是很適合引用計數器,所以sun jdk中並沒有實現這種GC方式。
跟蹤收集器,全域性記錄資料的引用狀態,基於一定的條件觸發。執行的時候,從根集合開始掃描物件的引用關係,主要有複製(copying)、標記-清除(Mark-Sweep)、標記-壓縮(Mark-Compact)那種演算法。
跟蹤計數器的三種演算法簡介?
複製:從根集合搜掃描出存活的物件,然後將存活的物件複製到一塊新的未使用的空間中,當要回收的空間中存活的物件較少時,比較高效;
標記清除:從根集合開始掃描,對存活的物件進行標記,比較完畢後,再掃描整個空間中未標記的物件,然後進行回收,不需要對物件進行移動;
標記壓縮:標記形式和“標記清除”一樣,但是回收不存活的物件後,會把所有存活的物件在記憶體空間中進行移動,好處是減少了記憶體碎片,缺點是成本比較高;
java記憶體區域的形式是啥樣的?
新生代可用的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、S1、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?
1、舊生代或者持久代已經使用的空間達到設定的百分比時(CMSInitiatingOccupancyFraction這個設定old區,perm區也可以設定);
2、JVM自動觸發(JVM的動態策略,也就是悲觀策略)(基於之前GC的頻率以及舊生代的增長趨勢來評估決定什麼時候開始執行),如果不希望JVM自行決定,可以通過-XX:UseCMSInitiatingOccupancyOnly=true來制定;
3、設定了 -XX:CMSClassUnloadingE考慮nabled 這個則考慮Perm區;
啥時候會觸發Full GC?
一、舊生代空間不足:java.lang.outOfMemoryError:java heap space;
二、Perm空間滿:java.lang.outOfMemoryError:PermGen space;
三、CMS GC時出現promotion failed 和concurrent mode failure(Concurrent mode failure發生的原因一般是CMS正在進行,但是由於old區記憶體不足,需要儘快回收old區裡面的死的java物件,這個時候foreground gc需要被觸發,停止所有的java執行緒,同時終止CMS,直接進行MSC。);
四、統計得到的minor GC晉升到舊生代的平均大小大於舊生代的剩餘空間;
五、主動觸發Full GC(執行jmap -histo:live [pid])來避免碎片問題;
為啥heap小於3g不建議使用CMS GC這種方式?
1、觸發比例不好設定,設定大了,那麼剩餘的空間就少了很多,設定小了,那old區還沒放置多少東西,就要進行回收了;
2、CMS進行的時候,是並行的,也就意味著如果過於頻繁的話,會和應用的強佔CPU;
3、CMS會有記憶體 碎片問題;
4、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日誌?
基本上都是這種格式:回收前區域佔用的大小->回收後區域佔用的大小(區域設定的大小),佔用的時間
1、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] 整個過程的時間消耗
|
2、一段正常的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消耗的總時間。
3、一段正常的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區的情況;
4、一段通過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。
5、一個特殊的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。