本文翻譯自：
https://blogs.oracle.com/poonam/entry/understanding_cms_gc_logs

准備工作

JVM的GC日志的主要參數包括如下幾個：
-XX:+PrintGC 輸出GC日志
-XX:+PrintGCDetails 輸出GC的詳細日志
-XX:+PrintGCTimeStamps 輸出GC的時間戳（以基准時間的形式）
-XX:+PrintGCDateStamps 輸出GC的時間戳（以日期的形式，如2013-05-04T21:53:59.234+0800）
-XX:+PrintHeapAtGC 在進行GC的前后打印出堆的信息
-Xloggc:../logs/gc.log 日志文件的輸出路徑

CMS GC知識

CMS，全稱Concurrent Mark and Sweep,用於對年老代進行回收，目標是盡量減少應用的暫停時間，減少full gc發生的機率，利用和應用程序線程並發的垃圾回收線程來標記清除年老代。
CMS並非沒有暫停，而是用兩次短暫停來替代串行標記整理算法的長暫停，內外的設置正常收集周期是這樣的：

　　1、CMS-initial-mark 初始標記
　　2、CMS-concurrent-mark 並發標記的
　　3、CMS-concurrent-preclean 執行預清理
　　4、CMS-concurrent-abortable-preclean 執行可中止預清理
　　5、CMS-remark 重新標記
　　6、CMS-concurrent-sweep 並發清除
　　7、CMS-concurrent-reset 並發重設狀態等待下次CMS的觸發

其中，CMS-initial-mark和CMS-remark會stop-the-world。

具體CMS的原理可以參看這篇文章
了解CMS(Concurrent Mark-Sweep)垃圾回收器

理解CMS GC日志

啟動jvm的時候，增加參數-XX:+PrintGCDetails 和 -XX:+PrintGCTimeStamps可以打印出CMS GC的詳細日志。讀懂log信息有助於應用系統的各種參數調優，同時也有助於使得CMS實現更好的性能。

下面的例子使用了1.8的jvm

2016-12-21T15:05:30.175+0800: 90.439: [GC2016-12-21T15:05:30.175+0800: 90.439: [ParNew: 720896K->49062K(720896K), 0.2289360 secs] 864443K->262770K(1507328K), 0.2292340 secs] [Times: user=0.42 sys=0.00, real=0.23 secs]

Young generation(ParNew)收集。新生代的容量是720896K，在使用量達到了720896K時發生了GC，回收的Young generation容量為49062K。本次GC花費了0.2289360s

2016-12-21T15:05:14.628+0800: 74.892: [GC [1 CMS-initial-mark: 646746K(786432K)] 723228K(1507328K), 0.0456000 secs] [Times: user=0.04 sys=0.00, real=0.04 secs]

CMS開始回收tenured generation collection。這階段是CMS初始化標記的階段，從垃圾回收的“根對象”開始，且只掃描直接與“根對象”直接關聯的對象，並做標記，在此期間，其他線程都會停止。

tenured generation的空間是786432K，在容量為646746K時開始執行初始標記。

2016-12-21T15:05:14.674+0800: 74.938: [CMS-concurrent-mark-start]

Concurrent marking(並發標記)階段開始。
本階段，其他線程重新開始正常執行，在上一步初始對象的基礎上繼續向下追溯標記

2016-12-21T15:05:15.188+0800: 75.452: [CMS-concurrent-mark: 0.513/0.514 secs] [Times: user=0.95 sys=0.05, real=0.52 secs] 並發標記階段發費了0.513s cpu time 和0.514s 系統時間（包括其他線程占用cpu導致標記線程掛起的時間） 2016-12-21T15:05:15.188+0800: 75.452: [CMS-concurrent-preclean-start] concurrent-preclean(並發域清理)階段開始 並發預清理階段仍然是並發的。在這個階段，虛擬機查找在執行並發標記階段新進入老年代的對象(可能會有一些對象從新生代晉升到老年代， 或者有一些對象被分配到老年代)。通過重新掃描，減少下一個階段"重新標記"的工作，因為下一個階段會Stop The World。 2016-12-21T15:05:15.192+0800: 75.456: [CMS-concurrent-preclean: 0.004/0.004 secs] [Times: user=0.01 sys=0.00, real=0.00 secs] concurrent-preclean花費了0.004s cpu time 和 0.004s 系統時間 2016-12-21T15:05:20.256+0800: 80.521: [GC[YG occupancy: 377234 K (720896 K)]2016-12-21T15:05:20.256+0800: 80.521: [Rescan (parallel) , 0.3789280 secs]2016-12-21T15:05:20.635+0800: 80.900: [weak refs processing, 0.0017780 secs]2016-12-21T15:05:20.637+0800: 80.901: [class unloading, 0.0141220 secs]2016-12-21T15:05:20.651+0800: 80.916: [scrub symbol table, 0.0259990 secs]2016-12-21T15:05:20.677+0800: 80.942: [scrub string table, 0.0024140 secs] [1 CMS-remark: 646746K(786432K)] 1023980K(1507328K), 0.4268320 secs] [Times: user=0.78 sys=0.01, real=0.42 secs] rescan階段，會暫停其他線程。重新掃描CMS堆中剩余的對象，重新從“根對象”開始掃描，並且也會處理對象關聯。本次掃描花費了 0.3789280s，其中弱引用對象（weak referene objects）處理大約用來0.0017780s，本階段共計時間0.4268320s 2016-12-21T15:05:20.685+0800: 80.950: [CMS-concurrent-sweep-start] 開始清理沒有標記的對象，清理階段是和其他線程並發進行的。 2016-12-21T15:05:21.340+0800: 81.605: [CMS-concurrent-sweep: 0.640/0.655 secs] [Times: user=1.23 sys=0.03, real=0.66 secs] 時間，不解釋了 2016-12-21T15:05:21.341+0800: 81.605: [CMS-concurrent-reset-start] 2016-12-21T15:05:21.402+0800: 81.666: [CMS-concurrent-reset: 0.061/0.061 secs] [Times: user=0.06 sys=0.05, real=0.06 secs] reset 階段開始，並且輸出所用時間。在這個階段，與CMS相關數據結構被重新初始化，這樣下一個周期可以正常進行。

以上過程是一個正常的CMS GC循環周期,接下來再分析一些不正常的日志

以下這個情況我沒有復現，用的是文章的中數據，TODO之后想想能否打印出來這種情況

197.976: [GC 197.976: [ParNew: 260872K->260872K(261952K), 0.0000688 secs]197.976: [CMS197.981: [CMS-concurrent-sweep: 0.516/0.531 secs] (concurrent mode failure): 402978K->248977K(786432K), 2.3728734 secs] 663850K->248977K(1048384K), 2.3733725 secs] 這顯示，ParNew收集請求執行，但是沒有成功。因為此時系統估計沒有老生代中沒有足夠的空間去容納這些對象（預測之后可能會出現老生代的空余空間將會被系統占光），我們稱這種情況為 “full promotion guarantee failure”

在這種情況下下，並發式的CMS被阻塞了，full GC執行了，GC算法進入了concurrent mode failure狀態，調用一個serail Old GC(阻塞了其他線程)來清理系統的Heap

日志顯示，Full GC花費了2.3733725s，老生代空間由402978K降到了248977K

concurrent mode failure可以通過增大老生代的空間或者通過設置CMSInitiatingOccupancyFraction一個小的值使得CMS Collection發生的更頻繁（CMSInitiatingOccupancyFraction可以控制CMS執行的時間，假設設置為70，說明老生代在利用率為70%時發生CMS），但是把這個值設置小也會導致CMS發生更加頻繁。

某些情況下，promotion failures也會發生，即使是老生代有足夠的空間。這個原因是"fragmentation"-老生代的可用空間不是連續的，而將新生代的對象移動到老生代需要連續的可用空間。而CMS是不會對內存進行壓縮的算法，因此造成了這種問題。TODO，這篇文章解決了這個問題，我還沒讀

補充一下：concurrent mode failure產生的原理：CMS並發處理階段用戶線程還在運行中，伴隨着程序運行會有新的垃圾產生，CMS無法處理掉它們（沒有標記），只能在下一次GC的時候處理。同樣的，用戶線程運行就需要分配新的內存空間，為此，CMS收集器並不會在老年代全部被填滿以后在進行收集，會預留一部分空間提供並發收集時的程序運行使用。即使是這樣，還是會存在CMS運行期間預留的內存無法滿足程序需求，就會出現"Concurrent Mode Failure"失敗，這是，虛擬機將會啟動備案操作：臨時啟動Serial Old 收集器來重新進行老年代的垃圾收集，Serial Old收集器會Stop the world，這樣會導致停頓時間過長

同樣的，CMS收集結束后會有大量的碎片空間差生，也會給大對象分配帶來麻煩，往往會出現老年代還有很大空間剩余，但是無法找到足夠多的連續空間來分配當前對象，不得不提前觸發一次Full GC

197.976: [GC 197.976: [ParNew: 260872K->260872K(261952K), 0.0000688 secs]197.976: [CMS197.981: [CMS-concurrent-sweep: 0.516/0.531 secs] (concurrent mode failure): 402978K->248977K(786432K), 2.3728734 secs] 663850K->248977K(1048384K), 2.3733725 secs]

這行GC日志顯示的是一個請求失敗的新生代GC處理。因為沒有足夠的空間來存儲由新生代晉升上來的對象。這種現象稱之為full promotioin guarantee failure 就此會在197.981處產生一次FULL GC，花費了 2.3733725秒 ，從而使CMS的空間從 402978K->248977K.