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