JVM 之 ParNew 和 CMS 日誌分析

ParNew 收集器

ParNew 收集器是年輕代經常使用的垃圾收集器，它採用的是複製算法，youngGC 時一個典型的日誌信息以下所示：

2018-04-12T13:48:26.134+0800: 15578.050: [GC2018-04-12T13:48:26.135+0800: 15578.050: [ParNew: 3412467K->59681K(3774912K), 0.0971990 secs] 9702786K->6354533K(24746432K), 0.0974940 secs] [Times: user=0.95 sys=0.00, real=0.09 secs]

依次分析一下上面日誌信息的含義：

• 2018-04-12T13:48:26.134+0800：Mirror GC 發生的時間；

• 15578.050：GC 開始時，相對 JVM 啓動的相對時間，單位時秒，這裏是4h+；

• ParNew：收集器名稱，這裏是 ParNew 收集器，它使用的是並行的 mark-copy 算法，GC 過程也會 Stop the World；

• 3412467K->59681K：收集先後年輕代的使用狀況，這裏是 3.25G->58.28M；

• 3774912K：整個年輕代的容量，這裏是 3.6G；

• 0.0971990 secs：Duration for the collection w/o final cleanup.

• 9702786K->6354533K：收集先後整個堆的使用狀況，這裏是 9.25G->6.06G;

• 24746432K：整個堆的容量，這裏是 23.6G；

• 0.0974940 secs：ParNew 收集器標記和複製年輕代活着的對象所花費的時間（包括和老年代通訊的開銷、對象晉升到老年代開銷、垃圾收集週期結束一些最後的清理對象等的花銷）；

對於 [Times: user=0.95 sys=0.00, real=0.09 secs]，這裏面涉及到三種時間類型，含義以下：

• user：GC 線程在垃圾收集期間所使用的 CPU 總時間；

• sys：系統調用或者等待系統事件花費的時間；

• real：應用被暫停的時鐘時間，因爲 GC 線程是多線程的，致使了 real 小於 (user+real)，若是是 gc 線程是單線程的話，real 是接近於 (user+real) 時間。

CMS 收集器

CMS 收集器是老年代常用的收集器，它採用的是標記-清楚算法，應用程序在發生一次 Full GC 時，典型的 GC 日誌信息以下：

2018-04-12T13:48:26.233+0800: 15578.148: [GC [1 CMS-initial-mark: 6294851K(20971520K)] 6354687K(24746432K), 0.0466580 secs] [Times: user=0.04 sys=0.00, real=0.04 secs]

2018-04-12T13:48:26.280+0800: 15578.195: [CMS-concurrent-mark-start]

2018-04-12T13:48:26.418+0800: 15578.333: [CMS-concurrent-mark: 0.138/0.138 secs] [Times: user=1.01 sys=0.21, real=0.14 secs]

2018-04-12T13:48:26.418+0800: 15578.334: [CMS-concurrent-preclean-start]

2018-04-12T13:48:26.476+0800: 15578.391: [CMS-concurrent-preclean: 0.056/0.057 secs] [Times: user=0.20 sys=0.12, real=0.06 secs]

2018-04-12T13:48:26.476+0800: 15578.391: [CMS-concurrent-abortable-preclean-start]

2018-04-12T13:48:29.989+0800: 15581.905: [CMS-concurrent-abortable-preclean: 3.506/3.514 secs] [Times: user=11.93 sys=6.77, real=3.51 secs]

2018-04-12T13:48:29.991+0800: 15581.906: [GC[YG occupancy: 1805641 K (3774912 K)]2018-04-12T13:48:29.991+0800: 15581.906: [GC2018-04-12T13:48:29.991+0800: 15581.906: [ParNew: 1805641K->48395K(3774912K), 0.0826620 secs] 8100493K->6348225K(24746432K), 0.0829480 secs] [Times: user=0.81 sys=0.00, real=0.09 secs]2018-04-12T13:48:30.074+0800: 15581.989: [Rescan (parallel) , 0.0429390 secs]2018-04-12T13:48:30.117+0800: 15582.032: [weak refs processing, 0.0027800 secs]2018-04-12T13:48:30.119+0800: 15582.035: [class unloading, 0.0033120 secs]2018-04-12T13:48:30.123+0800: 15582.038: [scrub symbol table, 0.0016780 secs]2018-04-12T13:48:30.124+0800: 15582.040: [scrub string table, 0.0004780 secs] [1 CMS-remark: 6299829K(20971520K)] 6348225K(24746432K), 0.1365130 secs] [Times: user=1.24 sys=0.00, real=0.14 secs]

2018-04-12T13:48:30.128+0800: 15582.043: [CMS-concurrent-sweep-start]

2018-04-12T13:48:36.638+0800: 15588.553: [GC2018-04-12T13:48:36.638+0800: 15588.554: [ParNew: 3403915K->52142K(3774912K), 0.0874610 secs] 4836483K->1489601K(24746432K), 0.0877490 secs] [Times: user=0.84 sys=0.00, real=0.09 secs]

2018-04-12T13:48:38.412+0800: 15590.327: [CMS-concurrent-sweep: 8.193/8.284 secs] [Times: user=30.34 sys=16.44, real=8.28 secs]

2018-04-12T13:48:38.419+0800: 15590.334: [CMS-concurrent-reset-start]

2018-04-12T13:48:38.462+0800: 15590.377: [CMS-concurrent-reset: 0.044/0.044 secs] [Times: user=0.15 sys=0.10, real=0.04 secs]

CMS Full GC 拆分開來，涉及的階段比較多，下面分別來介紹各個階段的狀況。

階段1：Initial Mark

這個是 CMS 兩次 stop-the-wolrd 事件的其中一次，這個階段的目標是：標記那些直接被 GC root 引用或者被年輕代存活對象所引用的全部對象，標記後示例以下所示（插圖來自：GC Algorithms：Implementations —— Concurrent Mark and Sweep —— Full GC）：

上述例子對應的日誌信息爲：

2018-04-12T13:48:26.233+0800: 15578.148: [GC [1 CMS-initial-mark: 6294851K(20971520K)] 6354687K(24746432K), 0.0466580 secs] [Times: user=0.04 sys=0.00, real=0.04 secs]

逐行介紹上面日誌的含義：

1. 2018-04-12T13:48:26.233+0800: 15578.148：GC 開始的時間，以及相對於 JVM 啓動的相對時間（單位是秒，這裏大概是4.33h），與前面 ParNew 相似，下面的分析中就直接跳過這個了；

2. CMS-initial-mark：初始標記階段，它會收集全部 GC Roots 以及其直接引用的對象；

3. 6294851K：當前老年代使用的容量，這裏是 6G；

4. (20971520K)：老年代可用的最大容量，這裏是 20G；

5. 6354687K：整個堆目前使用的容量，這裏是 6.06G；

6. (24746432K)：堆可用的容量，這裏是 23.6G；

7. 0.0466580 secs：這個階段的持續時間；

8. [Times: user=0.04 sys=0.00, real=0.04 secs]：與前面的相似，這裏是相應 user、system and real 的時間統計。

階段2：併發標記

在這個階段 Garbage Collector 會遍歷老年代，而後標記全部存活的對象，它會根據上個階段找到的 GC Roots 遍歷查找。併發標記階段，它會與用戶的應用程序併發運行。並非老年代全部的存活對象都會被標記，由於在標記期間用戶的程序可能會改變一些引用，以下圖所示（插圖來自：GC Algorithms：Implementations —— Concurrent Mark and Sweep —— Full GC）：

在上面的圖中，與階段1的圖進行對比，就會發現有一個對象的引用已經發生了變化，這個階段相應的日誌信息以下：

2018-04-12T13:48:26.280+0800: 15578.195: [CMS-concurrent-mark-start]

2018-04-12T13:48:26.418+0800: 15578.333: [CMS-concurrent-mark: 0.138/0.138 secs] [Times: user=1.01 sys=0.21, real=0.14 secs]

這裏詳細對上面的日誌解釋，以下所示：

1. CMS-concurrent-mark：併發收集階段，這個階段會遍歷老年代，並標記全部存活的對象；

2. 0.138/0.138 secs：這個階段的持續時間與時鐘時間；

3. [Times: user=1.01 sys=0.21, real=0.14 secs]：如前面所示，可是這部的時間，其實意義不大，由於它是從併發標記的開始時間開始計算，這期間由於是併發進行，不只僅包含 GC 線程的工做。

階段3：Concurrent Preclean

Concurrent Preclean：這也是一個併發階段，與應用的線程併發運行，並不會 stop 應用的線程。在併發運行的過程當中，一些對象的引用可能會發生變化，可是這種狀況發生時，JVM 會將包含這個對象的區域（Card）標記爲 Dirty，這也就是 Card Marking。以下圖所示（插圖來自：GC Algorithms：Implementations —— Concurrent Mark and Sweep —— Full GC：

在pre-clean階段，那些可以從 Dirty 對象到達的對象也會被標記，這個標記作完以後，dirty card 標記就會被清除了，以下（插圖來自：GC Algorithms：Implementations —— Concurrent Mark and Sweep —— Full GC：

這個階段相應的日誌信息以下：

2018-04-12T13:48:26.418+0800: 15578.334: [CMS-concurrent-preclean-start]

2018-04-12T13:48:26.476+0800: 15578.391: [CMS-concurrent-preclean: 0.056/0.057 secs] [Times: user=0.20 sys=0.12, real=0.06 secs]

其含義爲：

1. CMS-concurrent-preclean：Concurrent Preclean 階段，對在前面併發標記階段中引用發生變化的對象進行標記；

2. 0.056/0.057 secs：這個階段的持續時間與時鐘時間；

3. [Times: user=0.20 sys=0.12, real=0.06 secs]：同併發標記階段中的含義。

階段4：Concurrent Abortable Preclean

這也是一個併發階段，可是一樣不會影響影響用戶的應用線程，這個階段是爲了儘可能承擔 STW（stop-the-world）中最終標記階段的工做。這個階段持續時間依賴於不少的因素，因爲這個階段是在重複作不少相同的工做，直接知足一些條件（好比：重複迭代的次數、完成的工做量或者時鐘時間等）。這個階段的日誌信息以下：

2018-04-12T13:48:26.476+0800: 15578.391: [CMS-concurrent-abortable-preclean-start]

2018-04-12T13:48:29.989+0800: 15581.905: [CMS-concurrent-abortable-preclean: 3.506/3.514 secs] [Times: user=11.93 sys=6.77, real=3.51 secs]

1. CMS-concurrent-abortable-preclean：Concurrent Abortable Preclean 階段；

2. 3.506/3.514 secs：這個階段的持續時間與時鐘時間，本質上，這裏的 gc 線程會在 STW 以前作更多的工做，一般會持續 5s 左右；

3. [Times: user=11.93 sys=6.77, real=3.51 secs]：同前面。

階段5：Final Remark

這是第二個 STW 階段，也是 CMS 中的最後一個，這個階段的目標是標記全部老年代全部的存活對象，因爲以前的階段是併發執行的，gc 線程可能跟不上應用程序的變化，爲了完成標記老年代全部存活對象的目標，STW 就很是有必要了。

一般 CMS 的 Final Remark 階段會在年輕代儘量乾淨的時候運行，目的是爲了減小連續 STW 發生的可能性（年輕代存活對象過多的話，也會致使老年代涉及的存活對象會不少）。這個階段會比前面的幾個階段更復雜一些，相關日誌以下：

2018-04-12T13:48:29.991+0800: 15581.906: [GC[YG occupancy: 1805641 K (3774912 K)]2018-04-12T13:48:29.991+0800: 15581.906: [GC2018-04-12T13:48:29.991+0800: 15581.906: [ParNew: 1805641K->48395K(3774912K), 0.0826620 secs] 8100493K->6348225K(24746432K), 0.0829480 secs] [Times: user=0.81 sys=0.00, real=0.09 secs]2018-04-12T13:48:30.074+0800: 15581.989: [Rescan (parallel) , 0.0429390 secs]2018-04-12T13:48:30.117+0800: 15582.032: [weak refs processing, 0.0027800 secs]2018-04-12T13:48:30.119+0800: 15582.035: [class unloading, 0.0033120 secs]2018-04-12T13:48:30.123+0800: 15582.038: [scrub symbol table, 0.0016780 secs]2018-04-12T13:48:30.124+0800: 15582.040: [scrub string table, 0.0004780 secs] [1 CMS-remark: 6299829K(20971520K)] 6348225K(24746432K), 0.1365130 secs] [Times: user=1.24 sys=0.00, real=0.14 secs]

對上面的日誌進行分析：

1. YG occupancy: 1805641 K (3774912 K)：年輕代當前佔用量及容量，這裏分別是 1.71G 和 3.6G；

2. ParNew:...：觸發了一次 young GC，這裏觸發的緣由是爲了減小年輕代的存活對象，儘可能使年輕代更乾淨一些；

3. [Rescan (parallel) , 0.0429390 secs]：這個 Rescan 是當應用暫停的狀況下完成對全部存活對象的標記，這個階段是並行處理的，這裏花費了 0.0429390s；

4. [weak refs processing, 0.0027800 secs]：第一個子階段，它的工做是處理弱引用；

5. [class unloading, 0.0033120 secs]：第二個子階段，它的工做是：unloading the unused classes；

6. [scrub symbol table, 0.0016780 secs] ... [scrub string table, 0.0004780 secs]：最後一個子階段，它的目的是：cleaning up symbol and string tables which hold class-level metadata and internalized string respectively，時鐘的暫停也包含在這裏；

7. 6299829K(20971520K)：這個階段以後，老年代的使用量與總量，這裏分別是 6G 和 20G；

8. 6348225K(24746432K)：這個階段以後，堆的使用量與總量（包括年輕代，年輕代在前面發生過 GC），這裏分別是 6.05G 和 23.6G；

9. 0.1365130 secs：這個階段的持續時間；

10. [Times: user=1.24 sys=0.00, real=0.14 secs]：對應的時間信息。

經歷過這五個階段以後，老年代全部存活的對象都被標記過了，如今能夠經過清除算法去清理那些老年代再也不使用的對象。

階段6：Concurrent Sweep

這裏不須要 STW，它是與用戶的應用程序併發運行，這個階段是：清除那些再也不使用的對象，回收它們的佔用空間爲未來使用。以下圖所示（插圖來自：GC Algorithms：Implementations —— Concurrent Mark and Sweep —— Full GC：

）：

這個階段對應的日誌信息以下（這中間又發生了一次 Young GC）：

2018-04-12T13:48:30.128+0800: 15582.043: [CMS-concurrent-sweep-start]

2018-04-12T13:48:36.638+0800: 15588.553: [GC2018-04-12T13:48:36.638+0800: 15588.554: [ParNew: 3403915K->52142K(3774912K), 0.0874610 secs] 4836483K->1489601K(24746432K), 0.0877490 secs] [Times: user=0.84 sys=0.00, real=0.09 secs]

2018-04-12T13:48:38.412+0800: 15590.327: [CMS-concurrent-sweep: 8.193/8.284 secs] [Times: user=30.34 sys=16.44, real=8.28 secs]

分別介紹一下：

1. CMS-concurrent-sweep：這個階段主要是清除那些沒有被標記的對象，回收它們的佔用空間；

2. 8.193/8.284 secs：這個階段的持續時間與時鐘時間；

3. [Times: user=30.34 sys=16.44, real=8.28 secs]：同前面；

階段7：Concurrent Reset.

這個階段也是併發執行的，它會重設 CMS 內部的數據結構，爲下次的 GC 作準備，對應的日誌信息以下：

2018-04-12T13:48:38.419+0800: 15590.334: [CMS-concurrent-reset-start]

2018-04-12T13:48:38.462+0800: 15590.377: [CMS-concurrent-reset: 0.044/0.044 secs] [Times: user=0.15 sys=0.10, real=0.04 secs]

日誌詳情分別以下：

CMS-concurrent-reset：這個階段的開始，目的如前面所述；

0.044/0.044 secs：這個階段的持續時間與時鐘時間；

[Times: user=0.15 sys=0.10, real=0.04 secs]：同前面。

總結

CMS 經過將大量工做分散到併發處理階段來在減小 STW 時間，在這塊作得很是優秀，可是 CMS 也有一些其餘的問題：

1. CMS 收集器沒法處理浮動垃圾（ Floating Garbage），可能出現 「Concurrnet Mode Failure」 失敗而致使另外一次 Full GC 的產生，可能引起串行 Full GC；

2. 空間碎片，致使沒法分配大對象，CMS 收集器提供了一個 -XX:+UseCMSCompactAtFullCollection 開關參數（默認就是開啓的），用於在 CMS 收集器頂不住要進行 Full GC 時開啓內存碎片的合併整理過程，內存整理的過程是沒法併發的，空間碎片問題沒有了，但停頓時間不得不變長；

3. 對於堆比較大的應用上，GC 的時間難以預估。

CMS 的一些缺陷也是 G1 收集器興起的緣由。

參考：

• JVM各種GC日誌剖析；

  https://t.hao0.me/jvm/2016/03/15/jvm-gc-log.html

• GC之詳解CMS收集過程和日誌分析；

  http://www.cnblogs.com/zhangxiaoguang/p/5792468.html

• Getting Started with the G1 Garbage Collector；

  http://www.oracle.com/technetwork/tutorials/tutorials-1876574.html

• JVM實用參數（七）CMS收集器；

  http://ifeve.com/useful-jvm-flags-part-7-cms-collector/

• GC Algorithms：Implementations —— Concurrent Mark and Sweep —— Full GC；

  https://plumbr.io/handbook/garbage-collection-algorithms-implementations#concurrent-mark-and-sweep