當前位置：
首頁 > 知識 > JVM 之 ParNew 和 CMS 日誌分析

JVM 之 ParNew 和 CMS 日誌分析

知識 10-16

（點擊

上方公眾號

，可快速關注）




來源：王蒙 ，


matt33.com/2018/07/28/jvm-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：







在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]




日誌詳情分別如下：






  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各類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收集器；


    //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技能


喜歡這篇文章嗎？立刻分享出去讓更多人知道吧！

本站內容充實豐富，博大精深，小編精選每日熱門資訊，隨時更新，點擊「搶先收到最新資訊」瀏覽吧！


請您繼續閱讀更多來自 ImportNew 的精彩文章:

※SpringBoot | 第二十章：非同步開發之非同步請求
※這個牛逼技術你可千萬別學！

TAG:ImportNew |