垃圾回收器的可用組合:

準備工作

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 日誌檔案的輸出路徑

ParNew and CMS GC日誌初體驗

首先對整個GC日誌有一個大概的認知

2016-08-23T02:23:07.219-0200: 64.322: [GC (Allocation Failure) 64.322: [ParNew: 613404K->68068K(613440K), 0.1020465 secs] 10885349K->10880154K(12514816K), 0.1021309 secs] [Times: user=0.78 sys=0.01, real=0.11 secs]2016-08-23T02:23:07.321-0200: 64.425: [GC (CMS Initial Mark) [1 CMS-initial-mark: 10812086K(11901376K)] 10887844K(12514816K), 0.0001997 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
2016-08-23T02:23:07.321-0200: 64.425: [CMS-concurrent-mark-start]
2016-08-23T02:23:07.357-0200: 64.460: [CMS-concurrent-mark: 0.035/0.035 secs] [Times: user=0.07 sys=0.00, real=0.03 secs]
2016-08-23T02:23:07.357-0200: 64.460: [CMS-concurrent-preclean-start]
2016-08-23T02:23:07.373-0200: 64.476: [CMS-concurrent-preclean: 0.016/0.016 secs] [Times: user=0.02 sys=0.00, real=0.02 secs]
2016-08-23T02:23:07.373-0200: 64.476: [CMS-concurrent-abortable-preclean-start]
2016-08-23T02:23:08.446-0200: 65.550: [CMS-concurrent-abortable-preclean: 0.167/1.074 secs] [Times: user=0.20 sys=0.00, real=1.07 secs]
2016-08-23T02:23:08.447-0200: 65.550: [GC (CMS Final Remark) [YG occupancy: 387920 K (613440 K)]65.550: [Rescan (parallel) , 0.0085125 secs]65.559: [weak refs processing, 0.0000243 secs]65.559: [class unloading, 0.0013120 secs]65.560: [scrub symbol table, 0.0008345 secs]65.561: [scrub string table, 0.0001759 secs][1 CMS-remark: 10812086K(11901376K)] 11200006K(12514816K), 0.0110730 secs] [Times: user=0.06 sys=0.00, real=0.01 secs]
2016-08-23T02:23:08.458-0200: 65.561: [CMS-concurrent-sweep-start]
2016-08-23T02:23:08.485-0200: 65.588: [CMS-concurrent-sweep: 0.027/0.027 secs] [Times: user=0.03 sys=0.00, real=0.03 secs]
2016-08-23T02:23:08.485-0200: 65.589: [CMS-concurrent-reset-start]
2016-08-23T02:23:08.497-0200: 65.601: [CMS-concurrent-reset: 0.012/0.012 secs] [Times: user=0.01 sys=0.00, real=0.01 secs]

Minor GC

2016-08-23T02:23:07.219-02001: 64.3222:[GC3(Allocation Failure4) 64.322: [ParNew5: 613404K->68068K6(613440K)7, 0.1020465 secs8] 10885349K->10880154K9(12514816K)10, 0.1021309 secs11][Times: user=0.78 sys=0.01, real=0.11 secs]12

1. 1. 2016-08-23T02:23:07.219-0200 – GC發生的時間；

   2. 64.322 – GC開始，相對JVM啟動的相對時間，單位是秒；

   3. GC – 區別MinorGC和FullGC的標識，這次代表的是MinorGC；

   4. Allocation Failure – MinorGC的原因，在這個case裡邊，由於年輕代不滿足申請的空間，因此觸發了MinorGC；

   5. ParNew – 收集器的名稱，它預示了年輕代使用一個並行的 mark-copy stop-the-world 垃圾收集器；

   6. 613404K->68068K – 收集前後年輕代的使用情況；

   7. (613440K) – 整個年輕代的容量；

   8. 0.1020465 secs – 這個解釋用原滋原味的解釋：Duration for the collection w/o final cleanup.

   9. 10885349K->10880154K – 收集前後整個堆的使用情況；

   10. (12514816K) – 整個堆的容量；

   11. 0.1021309 secs – ParNew收集器標記和複製年輕代活著的物件所花費的時間（包括和老年代通訊的開銷、物件晉升到老年代時間、垃圾收集週期結束一些最後的清理物件等的花銷）；

   12. [Times: user=0.78 sys=0.01, real=0.11 secs] – GC事件在不同維度的耗時，具體的用英文解釋起來更加合理:

   • • user – Total CPU time that was consumed by Garbage Collector threads during this collection

     • sys – Time spent in OS calls or waiting for system event

     • real – Clock time for which your application was stopped. With Parallel GC this number should be close to (user time + system time) divided by the number of threads used by the Garbage Collector. In this particular case 8 threads were used. Note that due to some activities not being parallelizable, it always exceeds the ratio by a certain amount.

我們來分析下物件晉升問題（原文中的計算方式有問題）：

開始的時候：整個堆的大小是 10885349K，年輕代大小是613404K，這說明老年代大小是 10885349-613404=10271945K，

收集完成之後：整個堆的大小是 10880154K，年輕代大小是68068K，這說明老年代大小是 10880154-68068=10812086K，

老年代的大小增加了：10812086-10271945=608209K，也就是說 年輕代到年老代promot了608209K的資料；

圖形分析：

Full/Major GC 

2016-08-23T11:23:07.321-0200: 64.425: [GC (CMS Initial Mark)1 [1 CMS-initial-mark: 10812086K(11901376K)] 10887844K(12514816K), 0.0001997 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
2016-08-23T11:23:07.321-0200: 64.425: [CMS-concurrent-mark-start]
2016-08-23T11:23:07.357-0200: 64.460: [: 0.035/0.035 secs] [Times: user=0.07 sys=0.00, real=0.03 secs]
2016-08-23T11:23:07.357-0200: 64.460: [CMS-concurrent-preclean-start]
2016-08-23T11:23:07.373-0200: 64.476: [CMS-concurrent-preclean3: 0.016/0.016 secs] [Times: user=0.02 sys=0.00, real=0.02 secs]
2016-08-23T11:23:07.373-0200: 64.476: [CMS-concurrent-abortable-preclean-start]
2016-08-23T11:23:08.446-0200: 65.550: [CMS-concurrent-abortable-preclean4: 0.167/1.074 secs] [Times: user=0.20 sys=0.00, real=1.07 secs]
2016-08-23T11:23:08.447-0200: 65.550: [GC (CMS Final Remark5)
[YG occupancy: 387920 K (613440 K)]65.550: [Rescan (parallel) , 0.0085125 secs]65.559: 
[weak refs processing, 0.0000243 secs]65.559: [class unloading, 0.0013120 secs]65.560: 
[scrub symbol table, 0.0008345 secs]65.561: [scrub string table, 0.0001759 secs][1 CMS-remark: 10812086K(11901376K)] 11200006K(12514816K), 0.0110730 secs] 
[Times: user=0.06 sys=0.00, real=0.01 secs]
2016-08-23T11:23:08.458-0200: 65.561: [CMS-concurrent-sweep-start]
2016-08-23T11:23:08.485-0200: 65.588: [CMS-concurrent-sweep6: 0.027/0.027 secs] [Times: user=0.03 sys=0.00, real=0.03 secs]
2016-08-23T11:23:08.485-0200: 65.589: [CMS-concurrent-reset-start]
2016-08-23T11:23:08.497-0200: 65.601: [CMS-concurrent-reset7: 0.012/0.012 secs] [Times: user=0.01 sys=0.00, real=0.01 secs]

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。

Phase 1: Initial Mark

這是CMS中兩次stop-the-world事件中的一次。它有兩個目標：一是標記老年代中所有的GC Roots；二是標記被年輕代中活著的物件引用的物件。

標記結果如下：

分析：

2016-08-23T11:23:07.321-0200: 64.421: [GC (CMS Initial Mark2[1 CMS-initial-mark: 10812086K3(11901376K)4] 10887844K5(12514816K)6, 0.0001997 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]7

1. 1. 016-08-23T11:23:07.321-0200: 64.42 – GC事件開始，包括時鐘時間和相對JVM啟動時候的相對時間，下邊所有的階段改時間的含義相同；
   2. CMS Initial Mark – 收集階段，開始收集所有的GC Roots和直接引用到的物件；
   3. 10812086K – 當前老年代使用情況；
   4. (11901376K) – 老年代可用容量；
   5. 10887844K – 當前整個堆的使用情況；
   6. (12514816K) – 整個堆的容量；
   7. 0.0001997 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] – 時間計量；

Phase 2: Concurrent Mark

這個階段會遍歷整個老年代並且標記所有存活的物件，從“初始化標記”階段找到的GC Roots開始。併發標記的特點是和應用程式執行緒同時執行。並不是老年代的所有存活物件都會被標記，因為標記的同時應用程式會改變一些物件的引用等。

標記結果如下：

在上邊的圖中，一個引用的箭頭已經遠離了當前物件（current obj）

分析：

2016-08-23T11:23:07.321-0200: 64.425: [CMS-concurrent-mark-start]
2016-08-23T11:23:07.357-0200: 64.460: [CMS-concurrent-mark1: 035/0.035 secs2] [Times: user=0.07 sys=0.00, real=0.03 secs]3

1. 1. CMS-concurrent-mark – 併發收集階段，這個階段會遍歷整個年老代並且標記活著的物件；
   2. 035/0.035 secs – 展示該階段持續的時間和時鐘時間；
   3. [Times: user=0.07 sys=0.00, real=0.03 secs] – 同上

Phase 3: Concurrent Preclean

這個階段又是一個併發階段，和應用執行緒並行執行，不會中斷他們。前一個階段在並行執行的時候，一些物件的引用已經發生了變化，當這些引用發生變化的時候，JVM會標記堆的這個區域為Dirty Card(包含被標記但是改變了的物件，被認為"dirty")，這就是 Card Marking。

在pre-clean階段，那些能夠從dirty card物件到達的物件也會被標記，這個標記做完之後，dirty card標記就會被清除了，如下：

另外，一些必要的清掃工作也會做，還會做一些final remark階段需要的準備工作；

分析

2016-08-23T11:23:07.357-0200: 64.460: [CMS-concurrent-preclean-start]
2016-08-23T11:23:07.373-0200: 64.476: [CMS-concurrent-preclean1: 0.016/0.016 secs2] [Times: user=0.02 sys=0.00, real=0.02 secs]3

1. 1. CMS-concurrent-preclean – 這個階段負責前一個階段標記了又發生改變的物件標記；
   2. 0.016/0.016 secs – 展示該階段持續的時間和時鐘時間；
   3. [Times: user=0.02 sys=0.00, real=0.02 secs] – 同上

Phase 4: Concurrent Abortable Preclean

又一個併發階段不會停止應用程式執行緒。這個階段嘗試著去承擔STW的Final Remark階段足夠多的工作。這個階段持續的時間依賴好多的因素，由於這個階段是重複的做相同的事情直到發生aboart的條件（比如：重複的次數、多少量的工作、持續的時間等等）之一才會停止。

2016-08-23T11:23:07.373-0200: 64.476: [CMS-concurrent-abortable-preclean-start]
2016-08-23T11:23:08.446-0200: 65.550: [CMS-concurrent-abortable-preclean1: 0.167/1.074 secs2] [Times: user=0.20 sys=0.00, real=1.07 secs]3

1. 1. CMS-concurrent-abortable-preclean – 可終止的併發預清理；
   2. 0.167/1.074 secs – 展示該階段持續的時間和時鐘時間（It is interesting to note that the user time reported is a lot smaller than clock time. Usually we have seen that real time is less than user time, meaning that some work was done in parallel and so elapsed clock time is less than used CPU time. Here we have a little amount of work – for 0.167 seconds of CPU time, and garbage collector threads were doing a lot of waiting. Essentially, they were trying to stave off for as long as possible before having to do an STW pause. By default, this phase may last for up to 5 seconds）；
   3. [Times: user=0.20 sys=0.00, real=1.07 secs] – 同上

這個階段很大程度的影響著即將來臨的Final Remark的停頓，有相當一部分重要的 configuration options 和 失敗的模式；

Phase 5: Final Remark

這個階段是CMS中第二個並且是最後一個STW的階段。該階段的任務是完成標記整個年老代的所有的存活物件。由於之前的預處理是併發的，它可能跟不上應用程式改變的速度，這個時候，STW是非常需要的來完成這個嚴酷考驗的階段。

通常CMS儘量執行Final Remark階段在年輕代是足夠乾淨的時候，目的是消除緊接著的連續的幾個STW階段。

分析：

2016-08-23T11:23:08.447-0200: 65.5501: [GC (CMS Final Remark2) [YG occupancy: 387920 K (613440 K)3]65.550: [Rescan (parallel) , 0.0085125 secs]465.559: [weak refs processing, 0.0000243 secs]65.5595: [class unloading, 0.0013120 secs]65.5606: [scrub string table, 0.0001759 secs7][1 CMS-remark: 10812086K(11901376K)8] 11200006K(12514816K) 9, 0.0110730 secs10] [[Times: user=0.06 sys=0.00, real=0.01 secs]11

1. 1. 2016-08-23T11:23:08.447-0200: 65.550 – 同上；

   2. CMS Final Remark – 收集階段，這個階段會標記老年代全部的存活物件，包括那些在併發標記階段更改的或者新建立的引用物件；

   3. YG occupancy: 387920 K (613440 K) – 年輕代當前佔用情況和容量；

   4. [Rescan (parallel) , 0.0085125 secs] – 這個階段在應用停止的階段完成存活物件的標記工作；

   5. weak refs processing, 0.0000243 secs]65.559 – 第一個子階段，隨著這個階段的進行處理弱引用；

   6. class unloading, 0.0013120 secs]65.560 – 第二個子階段(that is unloading the unused classes, with the duration and timestamp of the phase)；

   7. scrub string table, 0.0001759 secs – 最後一個子階段（that is cleaning up symbol and string tables which hold class-level metadata and internalized string respectively）

   8. 10812086K(11901376K) – 在這個階段之後老年代佔有的記憶體大小和老年代的容量；

   9. 11200006K(12514816K) – 在這個階段之後整個堆的記憶體大小和整個堆的容量；

   10. 0.0110730 secs – 這個階段的持續時間；

   11. [Times: user=0.06 sys=0.00, real=0.01 secs] – 同上；

通過以上5個階段的標記，老年代所有存活的物件已經被標記並且現在要通過Garbage Collector採用清掃的方式回收那些不能用的物件了。

Phase 6: Concurrent Sweep

和應用執行緒同時進行，不需要STW。這個階段的目的就是移除那些不用的物件，回收他們佔用的空間並且為將來使用。

如圖：

分析：

2016-08-23T11:23:08.458-0200: 65.561: [CMS-concurrent-sweep-start] 2016-08-23T11:23:08.485-0200: 65.588: [CMS-concurrent-sweep1: 0.027/0.027 secs2] [[Times: user=0.03 sys=0.00, real=0.03 secs] 3

1. 1. CMS-concurrent-sweep – 這個階段主要是清除那些沒有標記的物件並且回收空間；

   2. 0.027/0.027 secs – 展示該階段持續的時間和時鐘時間；

   3. [Times: user=0.03 sys=0.00, real=0.03 secs] – 同上

Phase 7: Concurrent Reset

這個階段併發執行，重新設定CMS演算法內部的資料結構，準備下一個CMS生命週期的使用。

2016-08-23T11:23:08.485-0200: 65.589: [CMS-concurrent-reset-start] 2016-08-23T11:23:08.497-0200: 65.601: [CMS-concurrent-reset1: 0.012/0.012 secs2] [[Times: user=0.01 sys=0.00, real=0.01 secs]3

1. 1. 1. CMS-concurrent-reset – 這個階段重新設定CMS演算法內部的資料結構，為下一個收集階段做準備；

      2. 0.012/0.012 secs – 展示該階段持續的時間和時鐘時間；

      3. [Times: user=0.01 sys=0.00, real=0.01 secs] – 同上