歡迎光臨
每天分享高質量文章
當前位置：知識星球 > 後端 > 正文

JVM 之 ParNew 和 CMS 日誌分析

2018-10-17 分類：後端 閱讀(399) 評論(0)

（點選上方公眾號，可快速關註）


來源：王蒙 ，

matt33.com/2018/07/28/jvm-cms/

在兩年前的文章 JVM 學習——垃圾收集器與記憶體分配策略中，已經對 GC 演演算法的原理以及常用的垃圾收集器做了相應的總結。今天這篇文章主要是對生產環境中（Java7）常用的兩種垃圾收集器（ParNew：年輕代，CMS：老年代）從日誌資訊上進行分析，做一下總結，這樣當我們在排查相應的問題時，看到 GC 的日誌資訊，不會再那麼陌生，能清楚地知道這些日誌是什麼意思，GC 執行緒當前處在哪個階段，正在做什麼事情等。

http://matt33.com/2016/09/18/jvm-basic2/

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

【關於投稿】


如果大家有原創好文投稿，請直接給公號傳送留言。


① 留言格式：
【投稿】+《 文章標題》+ 文章連結

② 示例：
【投稿】《不要自稱是程式員，我十多年的 IT 職場總結》：http://blog.jobbole.com/94148/

③ 最後請附上您的個人簡介哈~



看完本文有收穫？請轉發分享給更多人

關註「ImportNew」，提升Java技能

贊(0)
標籤：

相關推薦

熱門標籤

iOS (11238)微軟 (4955)Linux (4274)安全 (4180)Python (4161)效能 (3165)運維 (2774)最佳化 (2419).NET (2262)Google (2136)機器學習 (1795)併發 (1613)分散式 (1559)叢集 (1240)SQL (1174)Mysql (1060)區塊鏈 (1017)Docker (977)微服務 (922)面試 (919)Apache (743)NLP (725)Redis (719)Android (668)Git (640)架構師 (632)Nginx (630)Facebook (599)JVM (595)爬蟲 (476)

熱門文章

分享創造快樂