理解CMS GC日志

本文翻译自：
https://blogs.oracle.com/poonam/entry/understanding_cms_gc_logs

准备工作

JVM的GC日志的主要参数包括如下几个：
-XX:+PrintGC 输出GC日志
-XX:+PrintGCDetails 输出GC的详细日志
-XX:+PrintGCTimeStamps 输出GC的时间戳（以基准时间的形式）
-XX:+PrintGCDateStamps 输出GC的时间戳（以日期的形式，如2013-05-04T21:53:59.234+0800）
-XX:+PrintHeapAtGC 在进行GC的前后打印出堆的信息
-Xloggc:../logs/gc.log 日志文件的输出路径

CMS GC知识

CMS，全称Concurrent Mark and Sweep,用于对年老代进行回收，目标是尽量减少应用的暂停时间，减少full gc发生的机率，利用和应用程序线程并发的垃圾回收线程来标记清除年老代。
CMS并非没有暂停，而是用两次短暂停来替代串行标记整理算法的长暂停，内外的设置正常收集周期是这样的：

　　1、CMS-initial-mark 初始标记
　　2、CMS-concurrent-mark 并发标记的
　　3、CMS-concurrent-preclean 执行预清理
　　4、CMS-concurrent-abortable-preclean 执行可中止预清理
　　5、CMS-remark 重新标记
　　6、CMS-concurrent-sweep 并发清除
　　7、CMS-concurrent-reset 并发重设状态等待下次CMS的触发

其中，CMS-initial-mark和CMS-remark会stop-the-world。

具体CMS的原理可以参看这篇文章
了解CMS(Concurrent Mark-Sweep)垃圾回收器

理解CMS GC日志

启动jvm的时候，增加参数-XX:+PrintGCDetails 和 -XX:+PrintGCTimeStamps可以打印出CMS GC的详细日志。读懂log信息有助于应用系统的各种参数调优，同时也有助于使得CMS实现更好的性能。

下面的例子使用了1.8的jvm

2016-12-21T15:05:30.175+0800: 90.439: [GC2016-12-21T15:05:30.175+0800: 90.439: [ParNew: 720896K->49062K(720896K), 0.2289360 secs] 864443K->262770K(1507328K), 0.2292340 secs] [Times: user=0.42 sys=0.00, real=0.23 secs]

Young generation(ParNew)收集。新生代的容量是720896K，在使用量达到了720896K时发生了GC，回收的Young generation容量为49062K。本次GC花费了0.2289360s

2016-12-21T15:05:14.628+0800: 74.892: [GC [1 CMS-initial-mark: 646746K(786432K)] 723228K(1507328K), 0.0456000 secs] [Times: user=0.04 sys=0.00, real=0.04 secs]

CMS开始回收tenured generation collection。这阶段是CMS初始化标记的阶段，从垃圾回收的“根对象”开始，且只扫描直接与“根对象”直接关联的对象，并做标记，在此期间，其他线程都会停止。

tenured generation的空间是786432K，在容量为646746K时开始执行初始标记。

2016-12-21T15:05:14.674+0800: 74.938: [CMS-concurrent-mark-start]

Concurrent marking(并发标记)阶段开始。
本阶段，其他线程重新开始正常执行，在上一步初始对象的基础上继续向下追溯标记

2016-12-21T15:05:15.188+0800: 75.452: [CMS-concurrent-mark: 0.513/0.514 secs] [Times: user=0.95 sys=0.05, real=0.52 secs] 并发标记阶段发费了0.513s cpu time 和0.514s 系统时间（包括其他线程占用cpu导致标记线程挂起的时间） 2016-12-21T15:05:15.188+0800: 75.452: [CMS-concurrent-preclean-start] concurrent-preclean(并发域清理)阶段开始 并发预清理阶段仍然是并发的。在这个阶段，虚拟机查找在执行并发标记阶段新进入老年代的对象(可能会有一些对象从新生代晋升到老年代， 或者有一些对象被分配到老年代)。通过重新扫描，减少下一个阶段"重新标记"的工作，因为下一个阶段会Stop The World。 2016-12-21T15:05:15.192+0800: 75.456: [CMS-concurrent-preclean: 0.004/0.004 secs] [Times: user=0.01 sys=0.00, real=0.00 secs] concurrent-preclean花费了0.004s cpu time 和 0.004s 系统时间 2016-12-21T15:05:20.256+0800: 80.521: [GC[YG occupancy: 377234 K (720896 K)]2016-12-21T15:05:20.256+0800: 80.521: [Rescan (parallel) , 0.3789280 secs]2016-12-21T15:05:20.635+0800: 80.900: [weak refs processing, 0.0017780 secs]2016-12-21T15:05:20.637+0800: 80.901: [class unloading, 0.0141220 secs]2016-12-21T15:05:20.651+0800: 80.916: [scrub symbol table, 0.0259990 secs]2016-12-21T15:05:20.677+0800: 80.942: [scrub string table, 0.0024140 secs] [1 CMS-remark: 646746K(786432K)] 1023980K(1507328K), 0.4268320 secs] [Times: user=0.78 sys=0.01, real=0.42 secs] rescan阶段，会暂停其他线程。重新扫描CMS堆中剩余的对象，重新从“根对象”开始扫描，并且也会处理对象关联。本次扫描花费了 0.3789280s，其中弱引用对象（weak referene objects）处理大约用来0.0017780s，本阶段共计时间0.4268320s 2016-12-21T15:05:20.685+0800: 80.950: [CMS-concurrent-sweep-start] 开始清理没有标记的对象，清理阶段是和其他线程并发进行的。 2016-12-21T15:05:21.340+0800: 81.605: [CMS-concurrent-sweep: 0.640/0.655 secs] [Times: user=1.23 sys=0.03, real=0.66 secs] 时间，不解释了 2016-12-21T15:05:21.341+0800: 81.605: [CMS-concurrent-reset-start] 2016-12-21T15:05:21.402+0800: 81.666: [CMS-concurrent-reset: 0.061/0.061 secs] [Times: user=0.06 sys=0.05, real=0.06 secs] reset 阶段开始，并且输出所用时间。在这个阶段，与CMS相关数据结构被重新初始化，这样下一个周期可以正常进行。

以上过程是一个正常的CMS GC循环周期,接下来再分析一些不正常的日志

以下这个情况我没有复现，用的是文章的中数据，TODO之后想想能否打印出来这种情况

197.976: [GC 197.976: [ParNew: 260872K->260872K(261952K), 0.0000688 secs]197.976: [CMS197.981: [CMS-concurrent-sweep: 0.516/0.531 secs] (concurrent mode failure): 402978K->248977K(786432K), 2.3728734 secs] 663850K->248977K(1048384K), 2.3733725 secs] 这显示，ParNew收集请求执行，但是没有成功。因为此时系统估计没有老生代中没有足够的空间去容纳这些对象（预测之后可能会出现老生代的空余空间将会被系统占光），我们称这种情况为 “full promotion guarantee failure”

在这种情况下下，并发式的CMS被阻塞了，full GC执行了，GC算法进入了concurrent mode failure状态，调用一个serail Old GC(阻塞了其他线程)来清理系统的Heap

日志显示，Full GC花费了2.3733725s，老生代空间由402978K降到了248977K

concurrent mode failure可以通过增大老生代的空间或者通过设置CMSInitiatingOccupancyFraction一个小的值使得CMS Collection发生的更频繁（CMSInitiatingOccupancyFraction可以控制CMS执行的时间，假设设置为70，说明老生代在利用率为70%时发生CMS），但是把这个值设置小也会导致CMS发生更加频繁。

某些情况下，promotion failures也会发生，即使是老生代有足够的空间。这个原因是"fragmentation"-老生代的可用空间不是连续的，而将新生代的对象移动到老生代需要连续的可用空间。而CMS是不会对内存进行压缩的算法，因此造成了这种问题。TODO，这篇文章解决了这个问题，我还没读

补充一下：concurrent mode failure产生的原理：CMS并发处理阶段用户线程还在运行中，伴随着程序运行会有新的垃圾产生，CMS无法处理掉它们（没有标记），只能在下一次GC的时候处理。同样的，用户线程运行就需要分配新的内存空间，为此，CMS收集器并不会在老年代全部被填满以后在进行收集，会预留一部分空间提供并发收集时的程序运行使用。即使是这样，还是会存在CMS运行期间预留的内存无法满足程序需求，就会出现"Concurrent Mode Failure"失败，这是，虚拟机将会启动备案操作：临时启动Serial Old 收集器来重新进行老年代的垃圾收集，Serial Old收集器会Stop the world，这样会导致停顿时间过长

同样的，CMS收集结束后会有大量的碎片空间差生，也会给大对象分配带来麻烦，往往会出现老年代还有很大空间剩余，但是无法找到足够多的连续空间来分配当前对象，不得不提前触发一次Full GC

197.976: [GC 197.976: [ParNew: 260872K->260872K(261952K), 0.0000688 secs]197.976: [CMS197.981: [CMS-concurrent-sweep: 0.516/0.531 secs] (concurrent mode failure): 402978K->248977K(786432K), 2.3728734 secs] 663850K->248977K(1048384K), 2.3733725 secs]

这行GC日志显示的是一个请求失败的新生代GC处理。因为没有足够的空间来存储由新生代晋升上来的对象。这种现象称之为full promotioin guarantee failure 就此会在197.981处产生一次FULL GC，花费了 2.3733725秒 ，从而使CMS的空间从 402978K->248977K.