1. 程式人生 > >JVM之ParNew和CMS日誌分析

JVM之ParNew和CMS日誌分析

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

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

這個階段相應的日誌資訊如下:

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

這個階段對應的日誌資訊如下(這中間又發生了一次 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]

日誌詳情分別如下:

  1. CMS-concurrent-reset:這個階段的開始,目的如前面所述;
  2. 0.044/0.044 secs:這個階段的持續時間與時鐘時間;
  3. [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 收集器興起的原因。

參考: