Java GC CMS 日誌分析

看以前最好對GC的新生代（Young Generation）和老生代（Old Generation）以及晉升過程（Promotion）都有深入理解，本文幫助理解GC CMS日誌，對JVM調優沒有進一步說明。

82551.569:[GC [1 CMS-initial-mark: 2027280K(2516992K)] 2084513K(3088576K), 0.0344000secs] [Times: user=0.03 sys=0.01, real=0.03 secs]

第一階段：初始標記階段（Initial mark）標誌着CMS收集老生代（Old Generation）的開始，全部從根部直接可達的對象會被標記，此時其餘線程被阻斷，這個階段稱爲stop-the-world。此記錄中，老生代的大小是2516992K，CMS在佔用內存達到2027280K時觸發，初始標記引發的pause time是0.0344s。

82551.604:[CMS-concurrent-mark-start]

第二階段：併發標記階段（concurrent mark），全部第一個階段被停掉的線程從新啓動，此階段內，從第一階段標記對象出發全部間接可達的對象將被標記。

82553.887:[CMS-concurrent-mark: 2.272/2.283 secs] [Times: user=5.27 sys=0.14, real=2.29secs]

併發標記消耗2.272s CPU時間和2.283s 實際時間，實際時間包含CPU時間和阻斷其餘線程的時間。

82553.887:[CMS-concurrent-preclean-start]

第三階段：併發預清理階段（concurrent preclean），目的是減輕下一個階段：重標記（remark）的工做量，由於預清理是併發的，而重標記是stop-the-world的，這樣能夠減少對其餘線程的影響。此階段內，收集器查看在併發標記過程當中，CMS堆內獲得晉升（promotion）的對象。

82553.928:[CMS-concurrent-preclean: 0.040/0.041 secs] [Times: user=0.04 sys=0.00,real=0.04 secs]

併發預清理消耗0.040s CPU時間和0.041s實際時間。

82553.929:[CMS-concurrent-abortable-preclean-start]

CMS: abort preclean due to time 82558.942: [CMS-concurrent-abortable-preclean: 1.311/5.014secs] [Times: user=1.41 sys=0.05, real=5.01 secs]

82558.959:[GC[YG occupancy: 338653 K (571584 K)]82558.959: [Rescan (parallel) , 0.3058990secs]82559.265: [weak refs processing, 0.0667480 secs]82559.332: [classunloading, 0.0868270 secs]82559.419: [scrub symbol & string tables,0.1176240 secs] [1 CMS-remark: 
2027283K(2516992K)] 2365936K(3088576K),0.6602340 secs] [Times: user=4.88 sys=0.37, real=0.66 secs]

第四階段：通過了併發預清理階段，可切斷式預清理（abortable preclean）開始了（筆者不肯定這麼翻譯是否合理）。從上面的記錄能夠看出，新生代的容量是571584K，新生代佔有內存達到338653K時此預清理過程就被切斷了，重標記階段開始，因爲重標記是stop-the-world的，因此其餘線程被阻斷。

第五階段：重標記（remark）階段，此階段從新掃描CMS堆中剩餘的且狀態更新過的對象，從新從根部遍歷，而且執行被引用的對象。這裏，重掃描消耗0.3058990s，弱引用對象執行消耗0.667480s，重標記整體消耗了0.6602340s。

須要說明的是：若是新生代中Eden的佔有內存達到了參數XX:CMSScheduleRemarkEdenSizeThreschold=<n>的值，可切斷式預清理就會啓動，直到Eden佔有內存達到參數XX:CMSScheduleRemarkEdenPenetration=<n>纔會結束，因此說它是能夠被打斷的。若是它執行的時間超過了參數XX:CMSMaxAbortablePrecleanTime的值，不管如何也是會當即中止的。以上這些參數是爲了限制預清理執行時間過長，可是預清理減輕了重標記的工做量。

82559.619:[CMS-concurrent-sweep-start]

第六階段：併發清理階段，重標記事後CMS開始清理沒有標記的也就是已經死亡的對象。這一過程不會阻斷其餘進程。所用時間以下一條記錄所示。

82560.976:[CMS-concurrent-sweep: 1.320/1.357 secs] [Times: user=1.76 sys=0.23, real=1.36secs] 

82560.976:[CMS-concurrent-reset-start]

82561.000:[CMS-concurrent-reset: 0.024/0.024 secs] [Times: user=0.02 sys=0.00, real=0.02secs]

第七階段：重置階段，CMS內數據再一次初始化，進入下一個清理循環，重置消耗0.024s。

下面是兩種清理錯誤的狀況：promotion failed和concurrentmode failure。

250169.767:[GC 250169.767: [ParNew (promotion failed): 571584K->571584K(571584K),0.6487910 secs]250170.416: [CMS250173.050: [CMS-concurrent-mark: 2.887/3.777 secs][Times: user=10.86 sys=0.56, real=3.78 secs] 

(concurrentmode failure): 2268975K->2111899K(2516992K), 8.3732150 secs]2766660K->2111899K(3088576K), [CMS Perm : 562899K->562896K(1048576K)],9.0223120 secs] [Times: user=9.78 sys=0.28, real=9.02 secs]

promotion failure表示重新生代晉升到老生代時發生了錯誤，由於老生代內存佔用快滿了，因此放不下晉升上來的對象。

有時promotion failure會引發concurrentmode failure，緣由仍是老生代內存不夠用了，這樣就引發了Full GC，也就是記錄中的CMS Perm，Full GC是一個stop-the-world的過程。

原文：https://blogs.oracle.com/poonam/entry/understanding_cms_gc_logs