轉(zhuǎn)載自： http://ifeve.com/jvm-cms-log/

在CMS GC 時,使用參數(shù)-XX:+PRintGCDetails 和 -XX:+PrintGCTimeStamps 會輸出很多日志信息，了解這些信息可以幫我們更好的調(diào)整參數(shù)，以獲得更高的性能。

我們來看下在JDK1.4.2_10 中CMS GC日志示例：

39.910: [GC 39.910: [ParNew: 261760K->0K(261952K), 0.2314667 secs] 262017K->26386K(1048384K), 0.2318679 secs]新生代使用 (ParNew 并行)回收器。新生代容量為261952K，GC回收后占用從261760K降到0,耗時0.2314667秒。(譯注：262017K->26386K(1048384K), 0.2318679 secs 表示整個堆占用從262017K 降至26386K,費時0.2318679)

40.146: [GC [1 CMS-initial-mark: 26386K(786432K)] 26404K(1048384K), 0.0074495 secs]開始使用CMS回收器進(jìn)行老年代回收。初始標(biāo)記(CMS-initial-mark)階段,這個階段標(biāo)記由根可以直接到達(dá)的對象，標(biāo)記期間整個應(yīng)用線程會暫停。老年代容量為786432K,CMS 回收器在空間占用達(dá)到 26386K 時被觸發(fā)

40.154: [CMS-concurrent-mark-start]開始并發(fā)標(biāo)記(concurrent-mark-start) 階段，在第一個階段被暫停的線程重新開始運行，由前階段標(biāo)記過的對象出發(fā)，所有可到達(dá)的對象都在本階段中標(biāo)記。

40.683: [CMS-concurrent-mark: 0.521/0.529 secs]并發(fā)標(biāo)記階段結(jié)束，占用 0.521秒CPU時間, 0.529秒墻鐘時間(也包含線程讓出CPU給其他線程執(zhí)行的時間)

40.683: [CMS-concurrent-preclean-start]開始預(yù)清理階段預(yù)清理也是一個并發(fā)執(zhí)行的階段。在本階段，會查找前一階段執(zhí)行過程中,從新生代晉升或新分配或被更新的對象。通過并發(fā)地重新掃描這些對象，預(yù)清理階段可以減少下一個stop-the-world 重新標(biāo)記階段的工作量。

40.701: [CMS-concurrent-preclean: 0.017/0.018 secs]預(yù)清理階段費時 0.017秒CPU時間，0.018秒墻鐘時間。

40.704: [GC40.704: [Rescan (parallel) , 0.1790103 secs]40.883: [weak refs processing, 0.0100966 secs] [1 CMS-remark: 26386K(786432K)] 52644K(1048384K), 0.1897792 secs]Stop-the-world 階段,從根及被其引用對象開始，重新掃描 CMS 堆中殘留的更新過的對象。這里重新掃描費時0.1790103秒，處理弱引用對象費時0.0100966秒，本階段費時0.1897792 秒。

40.894: [CMS-concurrent-sweep-start]開始并發(fā)清理階段，在清理階段，應(yīng)用線程還在運行。

41.020: [CMS-concurrent-sweep: 0.126/0.126 secs]并發(fā)清理階段費時0.126秒

41.020: [CMS-concurrent-reset-start]開始并發(fā)重置

41.147: [CMS-concurrent-reset: 0.127/0.127 secs]在本階段，重新初始化CMS內(nèi)部數(shù)據(jù)結(jié)構(gòu)，以備下一輪 GC 使用。本階段費時0.127秒

這是CMS正常運行周期打印的日志，現(xiàn)在讓我們一起看一下其他的CMS日志記錄：

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 收集器被請求進(jìn)行新生代的回收，但收集器并沒有嘗試回收，因為 它 預(yù)計在最糟糕的情況下， CMS 老年代中沒有足夠的空間容納新生代的幸存對象。我們把這個失敗稱之為”完全晉升擔(dān)保失敗”。

因為這樣，并發(fā)模式的 CMS 被中斷同并且在 197.981秒時，F(xiàn)ull GC被啟動。這次Full GC，采用標(biāo)記-清除-整理算法，會發(fā)生stop-the-world，費時2.3733725秒。CMS 老年代占用從 402978K 降到248977K。

避免并發(fā)模式失敗, 通過增加老年代空間大小或者設(shè)置參數(shù) CMSInitiatingOccupancyFraction 同時設(shè)置UseCMSInitiatingOccupancyOnly為true。參數(shù) CMSInitiatingOccupancyFraction 的值必須謹(jǐn)慎選擇，設(shè)置過低會造成頻繁發(fā)生 CMS 回收。

有時我們發(fā)現(xiàn)，當(dāng)日志中出現(xiàn)晉升失敗時，老年代還有足夠的空間。這是因為”碎片”，老年代中的可用空間并不連續(xù)，而從新生代晉升上來的對象，需要一塊連續(xù)的可用空間。CMS 收集器是一種非壓縮收集器，在某種類型的應(yīng)用中會發(fā)生碎片。下面博客中 Jon 詳細(xì)討論了如何處理碎片問題：https://blogs.Oracle.com/jonthecollector/entry/when_the_sum_of_the

從JDK 1.5 開始，CMS 收集器中的晉升擔(dān)保檢查策略有些變化。原來的策略是考慮最壞情況，即新生代所有對象都晉升到老年代 , 新的晉升擔(dān)保檢查策略基于最近晉升歷史情況，這種預(yù)計晉升對象比最壞情況下晉升對象要少很多，因此需要的空間也會少點。如果晉升失敗，新生代處于一致狀態(tài)。觸發(fā)一次 stop-the-world 的標(biāo)記-壓縮收集. 如果想在 UseSerialGC 中獲得這種功能，需要設(shè)置參數(shù) -XX:+HandlePromotionFailure.

283.736: [Full GC 283.736: [ParNew: 261599K->261599K(261952K), 0.0000615 secs] 826554K->826554K(1048384K), 0.0003259 secs]GC locker: Trying a full collection because scavenge failed283.736: [Full GC 283.736: [ParNew: 261599K->261599K(261952K), 0.0000288 secs]

當(dāng)一個JNI 關(guān)鍵區(qū)被釋放時會發(fā)生 Stop-the-world GC。新生代因為晉升擔(dān)保失敗回收失敗，觸發(fā)一次 Full GC.

CMS 可以運行在增量模式下(i-cms), 使用參數(shù) -XX:+CMSIncrementalMode. 在增量模式下，CMS 收集器在并發(fā)階段，不會獨占整個周期，而會周期性的暫停，喚醒應(yīng)用線程。收集器把并發(fā)階段工作，劃分為片段，安排在次級(minor) 回收之間運行。這對需要低延遲，運行在少量CPU服務(wù)器上的應(yīng)用很有用。

以下是增量模式 CMS的日志.2803.125: [GC 2803.125: [ParNew: 408832K->0K(409216K), 0.5371950 secs] 611130K->206985K(1048192K) icms_dc=4 , 0.5373720 secs]2824.209: [GC 2824.209: [ParNew: 408832K->0K(409216K), 0.6755540 secs] 615806K->211897K(1048192K) icms_dc=4 , 0.6757740 secs]

新生代花費 537 毫秒 和 675 毫秒. 在2次收集之間 iCMS 短暫運行期間由icms_dc 表示，icms_dc 表示運行的占空比。這里占空比為4% .簡單計算下, iCMS 增量階段費時 4/100 * (2824.209 – 2803.125 – 0.537) = 821 毫秒, 即 2次 GC 間隔時間的 4% .

在JDK 1.5 中, CMS 增加一個并發(fā)可中止預(yù)清理(concurrent abortable preclean)階段. 可中止預(yù)清理階段，運行在并行預(yù)清理和重新標(biāo)記之間，直到獲得所期望的eden空間占用率。增加這個階段是為了避免在重新標(biāo)記階段后緊跟著發(fā)生一次垃圾清除。為了盡可能區(qū)分開垃圾清除和重新標(biāo)記 ，我們盡量安排在兩次垃圾清除之間運行重新標(biāo)記階段。

There is a second reason why we do this. Immediately following a scavenge there are likely a large number of grey objects that need rescanning. The abortable preclean phase tries to deal with such newly grey objects thus reducing a subsequent CMS remark pause.

可以通過JVM參數(shù)CMSScheduleRemarkEdenSizeThreshold 和 CMSScheduleRemarkEdenPenetration 控制 重新標(biāo)記階段。默認(rèn)值是2m和50%. CMSScheduleRemarkEdenSizeThreshold 設(shè)置Eden區(qū)大小,低于此值時不啟動重新標(biāo)記階段，因為回報預(yù)期為微不足道 CMSScheduleRemarkEdenPenetration 設(shè)置啟動重新標(biāo)記階段時Eden區(qū)的空間占用率。(譯注：根據(jù)下面描述 Eden 應(yīng)該是指整個新生代)

預(yù)清理階段后，如果Eden 空間占用大于 CMSScheduleRemarkEdenSizeThreshold 設(shè)置的值, 會啟動可中止預(yù)清理，直到占用率達(dá)到 CMSScheduleRemarkEdenPenetration 設(shè)置的值, 否則，我們立即安排重新標(biāo)記階段.(譯注：與上面說的正好相反，不知是不是我翻譯有誤)

7688.150: [CMS-concurrent-preclean-start]7688.186: [CMS-concurrent-preclean: 0.034/0.035 secs]7688.186: [CMS-concurrent-abortable-preclean-start]7688.465: [GC 7688.465: [ParNew: 1040940K->1464K(1044544K), 0.0165840 secs] 1343593K->304365K(2093120K), 0.0167509 secs]7690.093: [CMS-concurrent-abortable-preclean: 1.012/1.907 secs]7690.095: [GC[YG occupancy: 522484 K (1044544 K)]7690.095: [Rescan (parallel) , 0.3665541 secs]7690.462: [weak refs processing, 0.0003850 secs] [1 CMS-remark: 302901K(1048576K)] 825385K(2093120K), 0.3670690 secs]

上面日志中,在預(yù)清理之后, 啟動可中止預(yù)清理, 之后發(fā)生年輕代垃圾回收,年輕代占用從 1040940K 下降到 1464K. 當(dāng)年輕代占用率達(dá)到 522484K 即堆的50%時,發(fā)生重新標(biāo)記

注意在JDK1.5中，年輕代的垃圾回收日志輸出在后面的重新標(biāo)記階段