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

JVM之ParNew和CMS日誌分析

阿新 • • 發佈：2018-12-14

在兩年前的文章 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 收集器興起的原因。

參考：

相關推薦

JVM 之 ParNew 和 CMS 日誌分析

在兩年前的文章 JVM 學習——垃圾收集器與記憶體分配策略中，已經對 GC 演算法的原理以及常用的垃圾收集器做了相應的總結。今天這篇文章主要是對生產環境中（Java7）常用的兩種垃圾收集器（ParNew：年輕代，CMS：老年代）從日誌資訊上進行分析，做一下總結，這樣當我們在排查相應的問題時，看到 G

JVM之ParNew和CMS日誌分析

在兩年前的文章 JVM 學習——垃圾收集器與記憶體分配策略中，已經對 GC 演算法的原理以及常用的垃圾收集器做了相應的總結。今天這篇文章主要是對生產環境中（Java7）常用的兩種垃圾收集器（ParNew：年輕代，CMS：老年代）從日誌資訊上進行分析，做一下總結，這樣當我們在

JVM之G1和CMS

CMS(Concurrent Mark Sweep) 收集器 CMS 收集器是獲取最短回收停頓時間為目標的收集器。適用於 B/S

apache中部署rotatelogs日誌分割和awstats日誌分析

rotatelogs awsta概述：rotatelogs日誌分割：apache使用自帶的日誌分割模塊rotatelogs分割日誌,rotatelogs 是 Apache中自帶的管道日誌程序。awstats日誌分析：是一款開源日誌分析系統，可用來分析Apache網站服務器的訪問日誌，也可用來分析Samba、V

JVM之棧和棧幀

棧： 1、又名堆疊，它是一種運算受限的線性表。其限制是僅允許在表的一端進行插入和刪除運算。這一端被稱為棧頂，相對地，把  另一端稱為棧底。其特性是先進後出。 2、棧是執行緒私有的，生命週期跟執行緒相同，當建立一個執行緒時，同時會建立一個棧，棧的大小和深度都是固定的。 3、方

深入理解JVM之記憶體溢位問題的分析與解決(二)

繼上一篇文章來說,我們這一次來分析JVM記憶體溢位的原因,也就是對引起錯誤程式碼的定位: 我們根據下圖來進行操作: 右鍵點選含有main函式的主檔案,然後選擇run as--》Run Configuration,到達如下圖所示:  點選Arguments到達如下

深入理解JVM之記憶體溢位問題的分析與解決(一)

今天樓主開始學習深入理解JVM這一套視訊,準備將課程的重點以部落格的形式展現出來,儘量把每一節的知識點縮小,寫的精闢; 今天樓主學習的是:記憶體溢位問題的分析與解決,我們來看一個例子  我們可以發現在迴圈中無限制的在建立HeadSpace這個類的例項,這必然會導致我們記憶

mysql高可用架構之MHA和mysql日誌優化

一、MHA簡介： MHA（Master High Availability）目前在MySQL高可用方面是一個相對成熟的解決方案，它由日本DeNA公司youshimaton（現就職於 Facebook公司）開發，是一套優秀的作為MySQL高可用性環境下故障切換和主從提升的高可用軟體。在M

JVM之棧和堆

棧：存放基本資料型別和物件的引用變數。 堆：存放物件。 堆主要是用來存放物件的，棧主要是用來執行程式的。相較於堆，棧的存取速度更快，但棧的大小和生存期必須是確定的，因此缺乏一定的靈活性。而堆卻可以在執行時動態的分配記憶體，生存期不用提前告訴編譯器，這也導致了其存取速度的緩慢。

Java GC CMS 日誌分析

原文連結： 筆者對其中某幾條記錄又進行了詳細說明，以下是一條完整的CMS日誌記錄的示例，外加一些記憶體分配錯誤的情況。 看之前最好對GC的新生代（Young Generation）和老生代（Old Generation）以及晉升過程（Promotion）都有深刻理解，本文

高性能網絡編程之IO和NIO阻塞分析

總結 soc io模型 一件事 性能 直接 socket 網絡編程 事情 一、內容 1、阻塞和非阻塞是什麽？ 2、傳統IO模型，他存在哪些阻塞點 3、NIO模型 4、對比總結 1、阻塞和非阻塞是什麽？ 阻塞：做某件事情，直到完成，除非超時，如果沒有完成，繼

React效能優化之PureComponent 和 memo使用分析

前言 關於react效能優化，在react 16這個版本，官方推出fiber，在框架層面優化了react效能上面的問題。由於這個太過於龐大，我們今天圍繞子自元件更新策略，從兩個及其微小的方面來談react效能優化。 其主要目的就是防止不必要的子元件渲染更新。 子元件何時更新？ 首先我們看個例子

探索ParNew和CMS垃圾回收器

  前言 上篇文章我們一起分析了JVM的垃圾回收機制，瞭解了新生代的記憶體模型，老年代的空間分配擔保原則，並簡單的介紹了幾種垃圾回收器。詳細內容小夥伴們可以去看一下我的上篇文章：秒懂JVM的垃圾回收機制。 今天我們就來探索一下，ParNew和CMS垃圾回收器的實現過程。   ParNew垃

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

話題引入 讓我們先簡單的看下整個堆年輕代和年老代的垃圾收集器組合（以下配合java8完美支援，其他版本可能稍有不同），其中標紅線的則是我們今天要著重講的內容： ParNew and CMS "Concurrent Mark and Sweep" 是CMS的全稱，官方給予的名稱是：“Mostly Co

詳解CMS收集過程和日誌分析

讓我們先簡單的看下整個堆年輕代和年老代的垃圾收集器組合（以下配合java8完美支援，其他版本可能稍有不同），其中標紅線的則是我們今天要著重講的內容： ParNew and CMS "Concurrent Mark and Sweep" 是CMS的全稱，官方給予的名稱是：“Mostly

JVM 之 逃逸分析和TLAB

來看一道面試題：所有的new 物件都是分配在堆上的嗎？如果不是，是什麼情況。 在沒看到這道題目的時候，我對所有物件都分配在堆上的想法是沒有一絲懷疑的，但是事實是不一定的。 逃逸分析 逃逸分析的定義 逃逸分析，是一種可以有效減少Java 程式中同步負載

jvm原始碼分析之yield和sleep

概述 由於Thread的yield和sleep有一定的相似性，因此放在一起進行分析。yield會釋放CPU資源，讓優先順序更高（至少是相同）的執行緒獲得執行機會；sleep當傳入引數為0時，和yield相同；當傳入引數大於0時，也是釋放CPU資源，當可以讓其它任何優先

小師妹學JVM之:逃逸分析和TLAB

[toc] # 簡介 逃逸分析我們在JDK14中JVM的效能優化一文中已經講過了，逃逸分析的結果就是JVM會在棧上分配物件，從而提升效率。如果我們在多執行緒的環境中，如何提升記憶體的分配效率呢？快來跟小師妹一起學習TLAB技術吧。 # 逃逸分析和棧上分配 小師妹：F師兄，從前大家都說物件是在堆中分配

Oracle Logminer 分析重做日誌RedoLog和歸檔日誌ArchiveLog

cti data 格式 保存 命令 重啟 msl dba object 在實際開發過程中，有時我們很有可能需要某個表的操作痕跡，或通過記錄的SQL語句進行有目的性的數據恢復（此時POINT-IN-TIME恢復已經滿足不了更細的粒度）、或僅僅是查看；

慢查詢日誌分析工具之pt-query-digest

lan git bash pre 日誌分析 windows images git 所有 curl 簡介 pt-query-digest 是用於分析mysql慢查詢的一個工具，與mysqldumpshow工具相比，py-query_digest 工具的分析結果更