CMS日志及對(duì)應(yīng)階段
CMS 收集器是老年代經(jīng)常使用的收集器，它采用的是標(biāo)記-清楚算法，應(yīng)用程序在發(fā)生一次 Full GC 時(shí)，典型的 GC 日志信息如下：
// 階段1：Initial Mark
[GC (CMS Initial Mark) [1 CMS-initial-mark: 0K(2097152K)] 620856K(3040896K), 0.1337462 secs] [Times: user=0.36 sys=0.00, real=0.13 secs]
// 階段2：并發(fā)標(biāo)記
2019-06-24T14:26:28.421+0800: 4.344: [CMS-concurrent-mark-start]
2019-06-24T14:26:28.448+0800: 4.370: [CMS-concurrent-mark: 0.026/0.026 secs] [Times: user=0.08 sys=0.01, real=0.03 secs]
// 階段3：Concurrent Preclean
2019-06-24T14:26:28.448+0800: 4.370: [CMS-concurrent-preclean-start]
2019-06-24T14:26:28.452+0800: 4.375: [CMS-concurrent-preclean: 0.004/0.004 secs] [Times: user=0.02 sys=0.00, real=0.00 secs]
// 階段4：Concurrent Abortable Preclean
2019-06-24T14:26:28.452+0800: 4.375: [CMS-concurrent-abortable-preclean-start]
2019-06-24T14:26:28.892+0800: 4.815: [GC (Allocation Failure) 2019-06-24T14:26:28.892+0800: 4.815: [ParNew2019-06-24T14:26:28.946+0800: 4.868: [CMS-concurrent-abortable-preclean: 0.066/0.493 secs] [Times: user=1.79 sys=0.09, real=0.49 secs]
: 838912K->92239K(943744K), 0.1086553 secs] 838912K->92239K(3040896K), 0.1088052 secs] [Times: user=0.31 sys=0.05, real=0.11 secs]
// 階段5：Final Remark
2019-06-24T14:26:29.001+0800: 4.924: [GC (CMS Final Remark) [YG occupancy: 113547 K (943744 K)]2019-06-24T14:26:29.001+0800: 4.924: [Rescan (parallel) , 0.0273029 secs]2019-06-24T14:26:29.029+0800: 4.951: [weak refs processing, 0.0000370 secs]2019-06-24T14:26:29.029+0800: 4.951: [class unloading, 0.0057905 secs]2019-06-24T14:26:29.035+0800: 4.957: [scrub symbol table, 0.0038963 secs]2019-06-24T14:26:29.038+0800: 4.961: [scrub string table, 0.0006268 secs][1 CMS-remark: 0K(2097152K)] 113547K(3040896K), 0.0391238 secs] [Times: user=0.13 sys=0.00, real=0.04 secs]
// 階段6：Concurrent Sweep
2019-06-24T14:26:29.041+0800: 4.963: [CMS-concurrent-sweep-start]
2019-06-24T14:26:29.041+0800: 4.963: [CMS-concurrent-sweep: 0.000/0.000 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
// 階段7：Concurrent Reset.
2019-06-24T14:26:29.041+0800: 4.963: [CMS-concurrent-reset-start]
2019-06-24T14:26:29.049+0800: 4.971: [CMS-concurrent-reset: 0.008/0.008 secs] [Times: user=0.03 sys=0.00, real=0.01 secs]
階段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)的日志信息為：
[GC (CMS Initial Mark) [1 CMS-initial-mark: 0K(2097152K)] 620856K(3040896K), 0.1337462 secs] [Times: user=0.36 sys=0.00, real=0.13 secs]
CMS-initial-mark：初始標(biāo)記階段，它會(huì)收集所有 GC Roots 以及其直接引用的對(duì)象；
0K：當(dāng)前老年代使用的容量，這里是 0G；
(2097152K)：老年代可用的最大容量，這里是 2G；
620856K：整個(gè)堆目前使用的容量，這里是 600M；
(3040896K)：堆可用的容量，這里是 3G；
0.1337462 secs：這個(gè)階段的持續(xù)時(shí)間；
[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)的日志信息如下：
2019-06-24T14:26:28.421+0800: 4.344: [CMS-concurrent-mark-start]
2019-06-24T14:26:28.448+0800: 4.370: [CMS-concurrent-mark: 0.026/0.026 secs] [Times: user=0.08 sys=0.01, real=0.03 secs]
這里詳細(xì)對(duì)上面的日志解釋，如下所示：
CMS-concurrent-mark：并發(fā)收集階段，這個(gè)階段會(huì)遍歷老年代，并標(biāo)記所有存活的對(duì)象；
0.138/0.138 secs：這個(gè)階段的持續(xù)時(shí)間與時(shí)鐘時(shí)間；
[Times: user=1.01 sys=0.21, real=0.14 secs]：如前面所示，但是這部的時(shí)間，其實(shí)意義不大，因?yàn)樗菑牟l(fā)標(biāo)記的開始時(shí)間開始計(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)行的過程中，一些對(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)的日志信息如下：
2019-06-24T14:26:28.448+0800: 4.370: [CMS-concurrent-preclean-start]
2019-06-24T14:26:28.452+0800: 4.375: [CMS-concurrent-preclean: 0.004/0.004 secs] [Times: user=0.02 sys=0.00, real=0.00 secs]
其含義為：
CMS-concurrent-preclean：Concurrent Preclean 階段，對(duì)在前面并發(fā)標(biāo)記階段中引用發(fā)生變化的對(duì)象進(jìn)行標(biāo)記；
0.056/0.057 secs：這個(gè)階段的持續(xù)時(shí)間與時(shí)鐘時(shí)間；
[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è)階段的日志信息如下：
2019-06-24T14:26:28.452+0800: 4.375: [CMS-concurrent-abortable-preclean-start]
2019-06-24T14:26:28.946+0800: 4.868: [CMS-concurrent-abortable-preclean: 0.066/0.493 secs] [Times: user=1.79 sys=0.09, real=0.49 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ì)象過多的話，也會(huì)導(dǎo)致老年代涉及的存活對(duì)象會(huì)很多）。這個(gè)階段會(huì)比前面的幾個(gè)階段更復(fù)雜一些，相關(guān)日志如下：
2019-06-24T14:26:29.001+0800: 4.924: [GC (CMS Final Remark) [YG occupancy: 113547 K (943744 K)]2019-06-24T14:26:29.001+0800: 4.924: [Rescan (parallel) , 0.0273029 secs]2019-06-24T14:26:29.029+0800: 4.951: [weak refs processing, 0.0000370 secs]2019-06-24T14:26:29.029+0800: 4.951: [class unloading, 0.0057905 secs]2019-06-24T14:26:29.035+0800: 4.957: [scrub symbol table, 0.0038963 secs]2019-06-24T14:26:29.038+0800: 4.961: [scrub string table, 0.0006268 secs][1 CMS-remark: 0K(2097152K)] 113547K(3040896K), 0.0391238 secs] [Times: user=0.13 sys=0.00, real=0.04 secs]
對(duì)上面的日志進(jìn)行分析：
YG occupancy: 1805641 K (3774912 K)：年輕代當(dāng)前占用量及容量，這里分別是 1.71G 和 3.6G；
[Rescan (parallel) , 0.0429390 secs]：這個(gè) Rescan 是當(dāng)應(yīng)用暫停的情況下完成對(duì)所有存活對(duì)象的標(biāo)記，這個(gè)階段是并行處理的，這里花費(fèi)了 0.0429390s；
[weak refs processing, 0.0027800 secs]：第一個(gè)子階段，它的工作是處理弱引用；
[class unloading, 0.0033120 secs]：第二個(gè)子階段，它的工作是：unloading the unused classes；
[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í)鐘的暫停也包含在這里；
0K(2097152K)：這個(gè)階段之后，老年代的使用量與總量，這里分別是 0G 和 2G；
113547K(3040896K)：這個(gè)階段之后，堆的使用量與總量（包括年輕代，年輕代在前面發(fā)生過 GC），這里分別是 100M 和 3G；
0391238 secs：這個(gè)階段的持續(xù)時(shí)間；
[Times: user=0.13 sys=0.00, real=0.04 secs]：對(duì)應(yīng)的時(shí)間信息。
經(jīng)歷過這五個(gè)階段之后，老年代所有存活的對(duì)象都被標(biāo)記過了，現(xiàn)在可以通過清除算法去清理那些老年代不再使用的對(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）：
2019-06-24T14:26:29.041+0800: 4.963: [CMS-concurrent-sweep-start]
2019-06-24T14:26:29.041+0800: 4.963: [CMS-concurrent-sweep: 0.000/0.000 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
階段7：Concurrent Reset.
這個(gè)階段也是并發(fā)執(zhí)行的，它會(huì)重設(shè) CMS 內(nèi)部的數(shù)據(jù)結(jié)構(gòu)，為下次的 GC 做準(zhǔn)備，對(duì)應(yīng)的日志信息如下：
2019-06-24T14:26:29.041+0800: 4.963: [CMS-concurrent-reset-start]
2019-06-24T14:26:29.049+0800: 4.971: [CMS-concurrent-reset: 0.008/0.008 secs] [Times: user=0.03 sys=0.00, real=0.01 secs]
