JVM CMS垃圾回收日志詳解

2017-02-13T13:08:44.032+0800: 70058.910: [GC (Allocation Failure) 2017-02-13T13:08:44.033+0800: 70058.910: [ParNew: 5565156K->90568K(5662336K), 0.1661369 secs] 8129600K->3164530K(13002368K), 0.1663049 secs] [Times: user=0.61 sys=0.00, real=0.16 secs]

年輕代垃圾回收。年輕代的容量為5662336K，通過本次回收，年輕代使用量從5565156K降到了90568K，共耗時0.1661369秒;整個堆容量為13002368K，堆的使用量從8129600K降到了3164530K，共耗時0.1663049秒

2017-02-13T13:08:44.204+0800: 70059.081: [GC (CMS Initial Mark) [1 CMS-initial-mark: 3073961K(7340032K)] 3178414K(13002368K), 0.0105904 secs] [Times: user=0.02 sys=0.00, real=0.01 secs]

CMS初始化标記階段(需要stop the world),這個階段标記的是由根(root)可直達的對象(也就是root之下第一層對象)，标記期間整個應用線程會停止。老年代容量為7340032K，在使用了3073961K時觸發了該标記操作；整個堆容量為13002368K，在使用了3178414K時觸發了改标記，共耗時0.0105904秒

說明：

2017-02-13T13:08:44.214+0800: 70059.092: [CMS-concurrent-mark-start]

開始并發标記階段，之前被停止的應用線程會重新啟動；從初始化階段标記的所有可達的對象(root之下第一層隊形)出發标記處第一層對象所引用的對象(root之下第二層、三層等等)

2017-02-13T13:08:46.076+0800: 70060.954: [CMS-concurrent-mark: 1.861/1.861 secs] [Times: user=2.45 sys=0.01, real=1.86 secs]

并發标記總共花費1.861秒cpu時間和1.861秒時鐘時間(人可感覺的時間)

說明：

wall time解釋：

又叫wall-clock time， wiki解釋為：Wall-clock time is the time that a clock on the wall (or a stopwatch in hand) would measure as having elapsed between the start of the process and "now".
           

2017-02-13T13:08:46.076+0800: 70060.954: [CMS-concurrent-preclean-start]

并發預清理開始。預清理也屬于并發處理階段。這個階段主要并發查找在做并發标記階段時從年輕代晉升到老年代的對象或老年代新配置設定的對象(大對象直接進入老年代)或發生變化的線程(mutators)更新的對象，來減少重新标記階段的工作量

說明：

關于mutators的概念，參考Advanced Design and Implementation of Virtual Machines解釋如下：

5.5小節中解釋：
In GC community, the application threads are usually called mutators, since they mutate the heap. e threads conducting garbage collection are called collectors, since they recycle the heap. Note mutators and collectors are not necessarily separate threads. One thread can shi its role between mutator and collector.


6.8小節中解釋如下：
With stop-the-world GC, the mutators are suspended for garbage collection, then the collection can be done in the context of the suspended mutators. In this design, collectors and mutators are the same native threads in di erent phases.
           

2017-02-13T13:08:46.098+0800: 70060.976: [CMS-concurrent-preclean: 0.022/0.022 secs] [Times: user=0.02 sys=0.00, real=0.02 secs]

并發預清理階段花費0.022秒cpu時間和0.022秒時鐘時間

2017-02-13T13:08:46.098+0800: 70060.976: [CMS-concurrent-abortable-preclean-start]

CMS: abort preclean due to time 2017-02-13T13:08:51.240+0800: 70066.117: [CMS-concurrent-abortable-preclean: 2.939/5.142 secs] [Times: user=3.27 sys=0.00, real=5.14 secs]

可終止的并發預清理。總共花費2.939秒cpu時間和5.142秒時鐘時間

2017-02-13T13:08:51.240+0800: 70066.118: [GC (CMS Final Remark) [YG occupancy: 213456 K (5662336 K)]2017-02-13T13:08:51.240+0800: 70066.118: [Rescan (parallel) , 0.0255997 secs]2017-02-13T13:08:51.266+0800: 70066.144: [weak refs processing, 0.0004628 secs]2017-02-13T13:08:51.266+0800: 70066.144: [class unloading, 0.0156084 secs]2017-02-13T13:08:51.282+0800: 70066.160: [scrub symbol table, 0.0033741 secs]2017-02-13T13:08:51.285+0800: 70066.163: [scrub string table, 0.0008130 secs][1 CMS-remark: 3073961K(7340032K)] 3287418K(13002368K), 0.0463703 secs] [Times: user=0.08 sys=0.00, real=0.05 secs]

重新标記階段，會發生stop the world。最後标記老年代所有存活對象(包括在并發階段建立或修改的對象)，因為之前的并發标記和并發預清理階段都是和應用線程并發進行的，是以可能有遺漏對象，這個階段會保證标記到所有對象。

[YG occupancy: 213456 K (5662336 K)]：年輕代大小為5662336K,目前使用了213456 K

[Rescan (parallel) , 0.0255997 secs]：在應用暫停後重新并發标記所有存活對象，總共耗時0.0255997秒

[weak refs processing, 0.0004628 secs]：子階段1---處理弱引用，共耗時0.0004628秒

[class unloading, 0.0156084 secs]：子階段2---解除安裝已不使用的類，共耗時0.0156084秒

[scrub symbol table, 0.0033741 secs]：子階段3--清理symbol table

[scrub string table, 0.0008130 secs]：子階段4---清理string table

[1 CMS-remark: 3073961K(7340032K)] 3287418K(13002368K), 0.0463703 secs]：重新标記，老年代占用3073961K，總容量7340032K；整個堆占用3287418K，總容量13002368K。共耗時0.0463703秒

2017-02-13T13:08:51.287+0800: 70066.165: [CMS-concurrent-sweep-start]

開始并發清理所有未标記或已終結的對象

2017-02-13T13:08:51.988+0800: 70066.866: [CMS-concurrent-sweep: 0.702/0.702 secs] [Times: user=0.71 sys=0.00, real=0.70 secs]

并發清理總共耗時0.702秒cpu時間和0.702秒時鐘時間

2017-02-13T13:08:51.989+0800: 70066.866: [CMS-concurrent-reset-start]

開始并發重置CMS算法内部資料，來未下次垃圾回收做準備

2017-02-13T13:08:52.006+0800: 70066.884: [CMS-concurrent-reset: 0.017/0.017 secs] [Times: user=0.02 sys=0.00, real=0.02 secs]

并發重置總共耗時0.017秒cpu時間/0.017秒時鐘時間

參考：

https://blogs.oracle.com/poonam/entry/understanding_cms_gc_logs

https://plumbr.eu/handbook/garbage-collection-algorithms-implementations/concurrent-mark-and-sweep

http://www.oracle.com/technetwork/tutorials/tutorials-1876574.html

http://www.oracle.com/technetwork/articles/java/vmoptions-jsp-140102.html