CMS日志

1. GC参数配置

-XX:+PrintGC

输出GC日志。

-verbose:gc

可以认为 -verbose:gc 是 -XX:+PrintGC 的别名。

-Xloggc:log/gc.log

输出GC日志的存储路径。

-XX:+PrintGCDetails

输出GC的详细日志。

-XX:+PrintGCDateStamps

输出GC的时间戳（以日期的形式）。

-XX:+ExplicitGCInvokesConcurrent

无论什么时候调用系统GC，都执行CMS GC，而不是Full GC。

-XX:+PrintHeapAtGC

在进行GC的前后打印出堆的信息。

-Xms512m

设置初始堆的大小。

-Xmx512m

堆分配的最大空间。

-Xmn1024m

设置年轻代大小。

整个JVM内存大小 = 年轻代大小 + 年老代大小 + 持久代大小，持久代一般固定大小为64m，所以增大年轻代后，将会减小年老代大小。此值对系统性能影响较大，Sun官方推荐配置为整个堆的3/8。

-Xss320K

设置每个线程的堆栈大小。

JDK5.0以后每个线程堆栈大小为1M，以前每个线程堆栈大小为256K。根据应用的线程所需内存大小进行调整。在相同物理内存下，减小这个值能生成更多的线程。但是操作系统对一个进程内的线程数还是有限制的，不能无限生成，经验值在3000~5000左右。

-XX:+UseConcMarkSweepGC

使用CMS收集器，其它类似。

-XX:NewRatio=4

设置年轻代（包括Eden和两个Survivor区）与年老代的比值（除去持久代）。设置为4，则年轻代与年老代所占比值为1：4，年轻代占整个堆栈的1/5，默认值是2即老年代是新生代内存的2倍

-XX:SurvivorRatio=4

设置年轻代中Eden区与Survivor区的大小比值。设置为4，则两个Survivor区与一个Eden区的比值为2:4，一个Survivor区占整个年轻代的1/6，默认值为8。

-XX:MaxPermSize=16m

设置持久代大小为16m。

-XX:MaxTenuringThreshold=0

设置垃圾最大年龄。如果设置为0的话，则年轻代对象不经过Survivor区，直接进入年老代。对于年老代比较多的应用，可以提高效率。如果将此值设置为一个较大值，则年轻代对象会在Survivor区进行多次复制，这样可以增加对象再年轻代的存活时间，增加在年轻代即被回收的概论。

GC[Allocation Failure]表示向young generation(eden)给新对象申请空间，但是young generation(eden)剩余的合适空间不够所需的大小导致的minor gc。

2. Minor GC: UseParNewGC 回收日志

2018-12-29T14:39:40.102+0800: 3.856: [GC (Allocation Failure) 2018-12-29T14:39:40.102+0800: 3.856: [ParNew: 681600K->72044K(766784K), 0.0977206 secs] 681600K->72044K(4109120K), 0.0978554 secs] [Times: user=0.39 
sys=0.06, real=0.10 secs]

2018-12-29T14:39:40.102+0800 本次gc触发的时间；

3.856 jvm启动后所经历的秒数；

GC (Allocation Failure) 对象分配在新生代但空间不够导致触发一次新生代gc；

ParNew 表示这是新生代gc类型, 即ParNewGC；

681600K->72044K(766784K), 0.0977206 secs 触发新生代gc时年轻代堆的大小，回收后的年轻代堆的大小，年轻代堆的总大小，该次gc回收所耗费的时间；

681600K->72044K(4109120K) 回收前堆的总大小，回收后堆的总大小，堆的总大小。

3. Major GC: UseConcMarkSweepGC 垃圾收集

CMS垃圾收集器总共分为7个阶段，其中有2个阶段，即是初始标记和最终标记阶段，是需要暂停用户线程的，其余垃圾收集线程均与用户线程并发执行。

CMS垃圾收集器在新版本的 Java 中被标记为弃用，后续的垃圾收集器默认使用G1GC。但目前很大一部分的垃圾收集器依然是CMS，故需要了解一下CMS垃圾收集的一些流程。

3.1 Phase 1: Initial Mark 初始标记

2018-12-29T14:46:45.247+0800: 429.000: [GC (CMS Initial Mark) [1 CMS-initial-mark: 17305K(3342336K)] 607785K(4109120K), 0.0704856 secs] [Times: user=0.32 sys=0.10, real=0.07 secs] 

这是CMS中两次stop-the-world事件中的一次。它有两个目标：一是标记老年代中所有的GC Roots；二是标记被年轻代中活着的对象引用的对象；

[1 CMS-initial-mark 收集阶段，开始收集所有的GC Roots和直接引用到的对象；

17305K(3342336K) 当前老年代的使用情况，老年代可用容量；

607785K(4109120K) 当前整个堆的使用情况，整个堆的容量，即是整个堆 - 老年代 = 新生代(4109120 - 3342336 = 766784)。

3.2 Phase 2: Concurrent Mark 并发标记

2018-12-29T14:46:45.317+0800: 429.071: [CMS-concurrent-mark-start]
2018-12-29T14:46:45.326+0800: 429.080: [CMS-concurrent-mark: 0.009/0.009 secs] [Times: user=0.02 sys=0.00, real=0.01 secs]

这个阶段会遍历整个老年代并且标记所有存活的对象，从“初始化标记”阶段找到的GC Roots开始。并发标记的特点是和应用程序线程同时运行。并不是老年代的所有存活对象都会被标记，因为标记的同时应用程序会改变一些对象的引用等；

CMS-concurrent-mark 并发收集阶段，这个阶段会遍历整个年老代并且标记活着的对象。

0.009/0.009 secs 展示该阶段持续的时间和时钟时间。

3.3 Phase 3: Concurrent Preclean 并发预清除

2018-12-29T14:46:45.326+0800: 429.080: [CMS-concurrent-preclean-start]
2018-12-29T14:46:45.338+0800: 429.092: [CMS-concurrent-preclean: 0.012/0.012 secs] [Times: user=0.02 sys=0.00, real=0.01 secs]

这个阶段又是一个并发阶段，和应用线程并行运行，不会中断他们。前一个阶段在并行运行的时候，一些对象的引用已经发生了变化，当这些引用发生变化的时候，JVM会标记堆的这个区域为Dirty Card(包含被标记但是改变了的对象，被认为"dirty")，这就是 Card Marking；

在pre-clean阶段，那些能够从dirty card对象到达的对象也会被标记，这个标记做完之后，dirty card标记就会被清除了；

一些必要的清扫工作也会做，还会做一些final remark阶段需要的准备工作；

CMS-concurrent-preclean 这个阶段负责前一个阶段标记了又发生改变的对象标记。

3.4 Phase 4: Concurrent Abortable Preclean 可终止的并发预清理

2018-12-29T14:46:45.338+0800: 429.092: [CMS-concurrent-abortable-preclean-start]
CMS: abort preclean due to time 2018-12-29T14:46:50.484+0800: 434.238: [CMS-concurrent-abortable-preclean: 4.232/5.146 secs] [Times: user=5.49 sys=0.10, real=5.15 secs] 

又一个并发阶段不会停止应用程序线程。这个阶段尝试着去承担STW的Final Remark阶段足够多的工作。这个阶段持续的时间依赖好多的因素，由于这个阶段是重复的做相同的事情直到发生aboart的条件（比如：重复的次数、多少量的工作、持续的时间等等）之一才会停止；

CMS-concurrent-abortable-preclean 可终止的并发预清理；

这个阶段很大程度的影响着即将来临的Final Remark的停顿，有相当一部分重要的 configuration options 和 失败的模式。

3.5 Phase 5: Final Remark 最终标记

2018-12-29T14:46:50.485+0800: 434.239: [GC (CMS Final Remark) [YG occupancy: 632074 K (766784 K)]2018-12-29T14:46:50.485+0800: 434.239: [Rescan (parallel) , 0.0791637 secs]2018-12-29T14:46:50.564+0800: 434.318: 
[weak refs processing, 0.0001243 secs]2018-12-29T14:46:50.565+0800: 434.318: [class unloading, 0.0409380 secs]2018-12-29T14:46:50.605+0800: 434.359: [scrub symbol table, 0.0136356 secs]2018-12-29T14:46:50.619+08
00: 434.373: [scrub string table, 0.0015586 secs][1 CMS-remark: 17305K(3342336K)] 649380K(4109120K), 0.1370772 secs] [Times: user=0.46 sys=0.06, real=0.13 secs] 

这个阶段是CMS中第二个并且是最后一个STW的阶段。该阶段的任务是完成标记整个年老代的所有的存活对象。由于之前的预处理是并发的，它可能跟不上应用程序改变的速度，这个时候，STW是非常需要的来完成这个严酷考验的阶段；

通常CMS尽量运行Final Remark阶段在年轻代是足够干净的时候，目的是消除紧接着的连续的几个STW阶段；

CMS Final Remark 收集阶段，这个阶段会标记老年代全部的存活对象，包括那些在并发标记阶段更改的或者新创建的引用对象；

YG occupancy: 632074 K (766784 K) 年轻代当前占用的情况和容量；

Rescan (parallel) 这个阶段在应用停止的阶段完成存活对象的标记工作；

weak refs processing 第一个子阶段，随着这个阶段的进行处理弱引用；

class unloading 第二个子阶段, 类的卸载；

scrub symbol table 最后一个子阶段, 清理字符引用等；

1 CMS-remark: 17305K(3342336K) 在这个阶段之后老年代占有的内存大小和老年代的容量；

649380K(4109120K) 在这个阶段之后整个堆的内存大小和整个堆的容量；

通过以上5个阶段的标记，老年代所有存活的对象已经被标记并且现在要通过Garbage Collector采用清扫的方式回收那些不能用的对象了。

3.6 Phase 6: Concurrent Sweep 并发清除

2018-12-29T14:46:50.622+0800: 434.376: [CMS-concurrent-sweep-start]
2018-12-29T14:46:50.635+0800: 434.388: [CMS-concurrent-sweep: 0.012/0.012 secs] [Times: user=0.02 sys=0.00, real=0.02 secs] 

和应用线程同时进行，不需要STW。这个阶段的目的就是移除那些不用的对象，回收他们占用的空间并且为将来使用；

CMS-concurrent-sweep 这个阶段主要是清除那些没有标记的对象并且回收空间。

3.7 Phase 7: Concurrent Reset 并发重置

2018-12-29T14:46:50.635+0800: 434.388: [CMS-concurrent-reset-start]
2018-12-29T14:46:50.651+0800: 434.405: [CMS-concurrent-reset: 0.016/0.016 secs] [Times: user=0.01 sys=0.00, real=0.01 secs] 

这个阶段并发执行，重新设置CMS算法内部的数据结构，准备下一个CMS生命周期的使用；

CMS-concurrent-reset 这个阶段重新设置CMS算法内部的数据结构，为下一个收集阶段做准备；

可参考JVM调优——之CMS GC日志分析。