中文字幕在线观看,亚洲а∨天堂久久精品9966,亚洲成a人片在线观看你懂的,亚洲av成人片无码网站,亚洲国产精品无码久久久五月天

JVM之ParNew和CMS日志分析

2018-10-16    來(lái)源：importnew

容器云強(qiáng)勢(shì)上線！快速搭建集群，上萬(wàn)Linux鏡像隨意使用

在兩年前的文章?JVM 學(xué)習(xí)——垃圾收集器與內(nèi)存分配策略中，已經(jīng)對(duì) GC 算法的原理以及常用的垃圾收集器做了相應(yīng)的總結(jié)。今天這篇文章主要是對(duì)生產(chǎn)環(huán)境中（Java7）常用的兩種垃圾收集器（ParNew：年輕代，CMS：老年代）從日志信息上進(jìn)行分析，做一下總結(jié)，這樣當(dāng)我們?cè)谂挪橄鄳?yīng)的問(wèn)題時(shí)，看到 GC 的日志信息，不會(huì)再那么陌生，能清楚地知道這些日志是什么意思，GC 線程當(dāng)前處在哪個(gè)階段，正在做什么事情等。

ParNew 收集器

ParNew 收集器是年輕代常用的垃圾收集器，它采用的是復(fù)制算法，youngGC 時(shí)一個(gè)典型的日志信息如下所示：

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 發(fā)生的時(shí)間；
  • 15578.050：GC 開(kāi)始時(shí)，相對(duì) JVM 啟動(dòng)的相對(duì)時(shí)間，單位時(shí)秒，這里是4h+；
  • ParNew：收集器名稱，這里是 ParNew 收集器，它使用的是并行的 mark-copy 算法，GC 過(guò)程也會(huì) Stop the World；
  • 3412467K->59681K：收集前后年輕代的使用情況，這里是 3.25G->58.28M；
  • 3774912K：整個(gè)年輕代的容量，這里是 3.6G；
  • 0.0971990 secs：Duration for the collection w/o final cleanup.
  • 9702786K->6354533K：收集前后整個(gè)堆的使用情況，這里是 9.25G->6.06G;
  • 24746432K：整個(gè)堆的容量，這里是 23.6G；
  • 0.0974940 secs：ParNew 收集器標(biāo)記和復(fù)制年輕代活著的對(duì)象所花費(fèi)的時(shí)間（包括和老年代通信的開(kāi)銷、對(duì)象晉升到老年代開(kāi)銷、垃圾收集周期結(jié)束一些最后的清理對(duì)象等的花銷）；

對(duì)于?[Times: user=0.95 sys=0.00, real=0.09 secs]，這里面涉及到三種時(shí)間類型，含義如下：

  • user：GC 線程在垃圾收集期間所使用的 CPU 總時(shí)間；
  • sys：系統(tǒng)調(diào)用或者等待系統(tǒng)事件花費(fèi)的時(shí)間；
  • real：應(yīng)用被暫停的時(shí)鐘時(shí)間，由于 GC 線程是多線程的，導(dǎo)致了 real 小于 (user+real)，如果是 gc 線程是單線程的話，real 是接近于 (user+real) 時(shí)間。

CMS 收集器

CMS 收集器是老年代經(jīng)常使用的收集器，它采用的是標(biāo)記-清楚算法，應(yīng)用程序在發(fā)生一次 Full GC 時(shí)，典型的 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 拆分開(kāi)來(lái)，涉及的階段比較多，下面分別來(lái)介紹各個(gè)階段的情況。

階段1：Initial Mark

這個(gè)是 CMS 兩次 stop-the-wolrd 事件的其中一次，這個(gè)階段的目標(biāo)是：標(biāo)記那些直接被 GC root 引用或者被年輕代存活對(duì)象所引用的所有對(duì)象，標(biāo)記后示例如下所示（插圖來(lái)自：GC Algorithms：Implementations —— Concurrent Mark and Sweep —— Full GC）：

上述例子對(duì)應(yīng)的日志信息為：

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 開(kāi)始的時(shí)間，以及相對(duì)于 JVM 啟動(dòng)的相對(duì)時(shí)間（單位是秒，這里大概是4.33h），與前面 ParNew 類似，下面的分析中就直接跳過(guò)這個(gè)了；
  2. CMS-initial-mark：初始標(biāo)記階段，它會(huì)收集所有 GC Roots 以及其直接引用的對(duì)象；
  3. 6294851K：當(dāng)前老年代使用的容量，這里是 6G；
  4. (20971520K)：老年代可用的最大容量，這里是 20G；
  5. 6354687K：整個(gè)堆目前使用的容量，這里是 6.06G；
  6. (24746432K)：堆可用的容量，這里是 23.6G；
  7. 0.0466580 secs：這個(gè)階段的持續(xù)時(shí)間；
  8. [Times: user=0.04 sys=0.00, real=0.04 secs]：與前面的類似，這里是相應(yīng) user、system and real 的時(shí)間統(tǒng)計(jì)。

階段2：并發(fā)標(biāo)記

在這個(gè)階段 Garbage Collector 會(huì)遍歷老年代，然后標(biāo)記所有存活的對(duì)象，它會(huì)根據(jù)上個(gè)階段找到的 GC Roots 遍歷查找。并發(fā)標(biāo)記階段，它會(huì)與用戶的應(yīng)用程序并發(fā)運(yùn)行。并不是老年代所有的存活對(duì)象都會(huì)被標(biāo)記，因?yàn)樵跇?biāo)記期間用戶的程序可能會(huì)改變一些引用，如下圖所示（插圖來(lái)自：GC Algorithms：Implementations —— Concurrent Mark and Sweep —— Full GC）：

在上面的圖中，與階段1的圖進(jìn)行對(duì)比，就會(huì)發(fā)現(xiàn)有一個(gè)對(duì)象的引用已經(jīng)發(fā)生了變化，這個(gè)階段相應(yīng)的日志信息如下：

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]

這里詳細(xì)對(duì)上面的日志解釋，如下所示：

  1. CMS-concurrent-mark：并發(fā)收集階段，這個(gè)階段會(huì)遍歷老年代，并標(biāo)記所有存活的對(duì)象；
  2. 0.138/0.138 secs：這個(gè)階段的持續(xù)時(shí)間與時(shí)鐘時(shí)間；
  3. [Times: user=1.01 sys=0.21, real=0.14 secs]：如前面所示，但是這部的時(shí)間，其實(shí)意義不大，因?yàn)樗菑牟l(fā)標(biāo)記的開(kāi)始時(shí)間開(kāi)始計(jì)算，這期間因?yàn)槭遣l(fā)進(jìn)行，不僅僅包含 GC 線程的工作。

階段3：Concurrent Preclean

Concurrent Preclean：這也是一個(gè)并發(fā)階段，與應(yīng)用的線程并發(fā)運(yùn)行，并不會(huì) stop 應(yīng)用的線程。在并發(fā)運(yùn)行的過(guò)程中，一些對(duì)象的引用可能會(huì)發(fā)生變化，但是這種情況發(fā)生時(shí)，JVM 會(huì)將包含這個(gè)對(duì)象的區(qū)域（Card）標(biāo)記為 Dirty，這也就是 Card Marking。如下圖所示（插圖來(lái)自：GC Algorithms：Implementations —— Concurrent Mark and Sweep —— Full GC：

在pre-clean階段，那些能夠從 Dirty 對(duì)象到達(dá)的對(duì)象也會(huì)被標(biāo)記，這個(gè)標(biāo)記做完之后，dirty card 標(biāo)記就會(huì)被清除了，如下（插圖來(lái)自：GC Algorithms：Implementations —— Concurrent Mark and Sweep —— Full GC：

這個(gè)階段相應(yīng)的日志信息如下：

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 階段，對(duì)在前面并發(fā)標(biāo)記階段中引用發(fā)生變化的對(duì)象進(jìn)行標(biāo)記；
  2. 0.056/0.057 secs：這個(gè)階段的持續(xù)時(shí)間與時(shí)鐘時(shí)間；
  3. [Times: user=0.20 sys=0.12, real=0.06 secs]：同并發(fā)標(biāo)記階段中的含義。

階段4：Concurrent Abortable Preclean

這也是一個(gè)并發(fā)階段，但是同樣不會(huì)影響影響用戶的應(yīng)用線程，這個(gè)階段是為了盡量承擔(dān) STW（stop-the-world）中最終標(biāo)記階段的工作。這個(gè)階段持續(xù)時(shí)間依賴于很多的因素，由于這個(gè)階段是在重復(fù)做很多相同的工作，直接滿足一些條件（比如：重復(fù)迭代的次數(shù)、完成的工作量或者時(shí)鐘時(shí)間等）。這個(gè)階段的日志信息如下：

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：這個(gè)階段的持續(xù)時(shí)間與時(shí)鐘時(shí)間，本質(zhì)上，這里的 gc 線程會(huì)在 STW 之前做更多的工作，通常會(huì)持續(xù) 5s 左右；
  3. [Times: user=11.93 sys=6.77, real=3.51 secs]：同前面。

階段5：Final Remark

這是第二個(gè) STW 階段，也是 CMS 中的最后一個(gè)，這個(gè)階段的目標(biāo)是標(biāo)記所有老年代所有的存活對(duì)象，由于之前的階段是并發(fā)執(zhí)行的，gc 線程可能跟不上應(yīng)用程序的變化，為了完成標(biāo)記老年代所有存活對(duì)象的目標(biāo)，STW 就非常有必要了。

通常 CMS 的 Final Remark 階段會(huì)在年輕代盡可能干凈的時(shí)候運(yùn)行，目的是為了減少連續(xù) STW 發(fā)生的可能性（年輕代存活對(duì)象過(guò)多的話，也會(huì)導(dǎo)致老年代涉及的存活對(duì)象會(huì)很多）。這個(gè)階段會(huì)比前面的幾個(gè)階段更復(fù)雜一些，相關(guān)日志如下：

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]

對(duì)上面的日志進(jìn)行分析：

  1. YG occupancy: 1805641 K (3774912 K)：年輕代當(dāng)前占用量及容量，這里分別是 1.71G 和 3.6G；
  2. ParNew:...：觸發(fā)了一次 young GC，這里觸發(fā)的原因是為了減少年輕代的存活對(duì)象，盡量使年輕代更干凈一些；
  3. [Rescan (parallel) , 0.0429390 secs]：這個(gè) Rescan 是當(dāng)應(yīng)用暫停的情況下完成對(duì)所有存活對(duì)象的標(biāo)記，這個(gè)階段是并行處理的，這里花費(fèi)了 0.0429390s；
  4. [weak refs processing, 0.0027800 secs]：第一個(gè)子階段，它的工作是處理弱引用；
  5. [class unloading, 0.0033120 secs]：第二個(gè)子階段，它的工作是：unloading the unused classes；
  6. [scrub symbol table, 0.0016780 secs] ... [scrub string table, 0.0004780 secs]：最后一個(gè)子階段，它的目的是：cleaning up symbol and string tables which hold class-level metadata and internalized string respectively，時(shí)鐘的暫停也包含在這里；
  7. 6299829K(20971520K)：這個(gè)階段之后，老年代的使用量與總量，這里分別是 6G 和 20G；
  8. 6348225K(24746432K)：這個(gè)階段之后，堆的使用量與總量（包括年輕代，年輕代在前面發(fā)生過(guò) GC），這里分別是 6.05G 和 23.6G；
  9. 0.1365130 secs：這個(gè)階段的持續(xù)時(shí)間；
  10. [Times: user=1.24 sys=0.00, real=0.14 secs]：對(duì)應(yīng)的時(shí)間信息。

經(jīng)歷過(guò)這五個(gè)階段之后，老年代所有存活的對(duì)象都被標(biāo)記過(guò)了，現(xiàn)在可以通過(guò)清除算法去清理那些老年代不再使用的對(duì)象。

階段6：Concurrent Sweep

這里不需要 STW，它是與用戶的應(yīng)用程序并發(fā)運(yùn)行，這個(gè)階段是：清除那些不再使用的對(duì)象，回收它們的占用空間為將來(lái)使用。如下圖所示（插圖來(lái)自：GC Algorithms：Implementations —— Concurrent Mark and Sweep —— Full GC：
）：

這個(gè)階段對(duì)應(yīng)的日志信息如下（這中間又發(fā)生了一次 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：這個(gè)階段主要是清除那些沒(méi)有被標(biāo)記的對(duì)象，回收它們的占用空間；
  2. 8.193/8.284 secs：這個(gè)階段的持續(xù)時(shí)間與時(shí)鐘時(shí)間；
  3. [Times: user=30.34 sys=16.44, real=8.28 secs]：同前面；

階段7：Concurrent Reset.

這個(gè)階段也是并發(fā)執(zhí)行的，它會(huì)重設(shè) CMS 內(nèi)部的數(shù)據(jù)結(jié)構(gòu)，為下次的 GC 做準(zhǔn)備，對(duì)應(yīng)的日志信息如下：

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：這個(gè)階段的開(kāi)始，目的如前面所述；
  2. 0.044/0.044 secs：這個(gè)階段的持續(xù)時(shí)間與時(shí)鐘時(shí)間；
  3. [Times: user=0.15 sys=0.10, real=0.04 secs]：同前面。

總結(jié)

CMS 通過(guò)將大量工作分散到并發(fā)處理階段來(lái)在減少 STW 時(shí)間，在這塊做得非常優(yōu)秀，但是 CMS 也有一些其他的問(wèn)題：

  1. CMS 收集器無(wú)法處理浮動(dòng)垃圾（ Floating Garbage），可能出現(xiàn) “Concurrnet Mode Failure” 失敗而導(dǎo)致另一次 Full GC 的產(chǎn)生，可能引發(fā)串行 Full GC；
  2. 空間碎片，導(dǎo)致無(wú)法分配大對(duì)象，CMS 收集器提供了一個(gè)?-XX:+UseCMSCompactAtFullCollection?開(kāi)關(guān)參數(shù)（默認(rèn)就是開(kāi)啟的），用于在 CMS 收集器頂不住要進(jìn)行 Full GC 時(shí)開(kāi)啟內(nèi)存碎片的合并整理過(guò)程，內(nèi)存整理的過(guò)程是無(wú)法并發(fā)的，空間碎片問(wèn)題沒(méi)有了，但停頓時(shí)間不得不變長(zhǎng)；
  3. 對(duì)于堆比較大的應(yīng)用上，GC 的時(shí)間難以預(yù)估。

CMS 的一些缺陷也是 G1 收集器興起的原因。

參考：

  • JVM各類GC日志剖析；
  • GC之詳解CMS收集過(guò)程和日志分析；
  • Getting Started with the G1 Garbage Collector；
  • JVM實(shí)用參數(shù)（七）CMS收集器；
  • GC Algorithms：Implementations —— Concurrent Mark and Sweep —— Full GC；

標(biāo)簽： 通信

版權(quán)申明：本站文章部分自網(wǎng)絡(luò)，如有侵權(quán)，請(qǐng)聯(lián)系：west999com@outlook.com
特別注意：本站所有轉(zhuǎn)載文章言論不代表本站觀點(diǎn)！
本站所提供的圖片等素材，版權(quán)歸原作者所有，如需使用，請(qǐng)與原作者聯(lián)系。

上一篇:Kafka Controller Redesign方案

下一篇:說(shuō)說(shuō)MQ之RocketMQ（三）