java8添加并查看GC日志(ParNew+CMS)

一、背景

java8的垃圾回收器一般推荐的是parNew+CMS，分别针对新生代和老年代的垃圾回收器。实际生产上，有时需要分析GC日志，检查GC回收有没有引起过多的系统暂停，特别是full GC。

二、如何添加jvm参数启动GC日志

直接上个例子，再解释。

-verbose:gc -Xloggc:/var/log/xxx/gc-xxx.log -XX:+PrintGCTimeStamps -XX:+PrintGCDateStamps -XX:+PrintGCDetails -XX:+UseGCLogFileRotation -XX:NumberOfGCLogFiles=10 -XX:GCLogFileSize=1024k

参数解释：

• -verbose:gc : 启用GC日志
• -Xloggc: : GC日志文件路径，注意日志路径需要JVM启动用户拥有读写权限。上面的例子中，可以使用chmod或chown命令对/var/log/xxx/进行赋权限或改变所属用户。
• -XX:+PrintGCTimeStamps : 日志格式，打印GC发生的时间戳，这个时间戳表示 JVM 启动后到现在所逝去的时间。
• -XX:+PrintGCDateStamps : 日志格式，打印GC发生的系统时间。
• -XX:+PrintGCDetails : 打印详细的GC日志
• -XX:+UseGCLogFileRotation : 启动GC日志滚动策略
• -XX:NumberOfGCLogFiles : GC日志文件滚动数量
• -XX:GCLogFileSize : GC日志文件大小

三、GC日志解读

简单看一下新生代和老年代发生GC时的日志是什么样子的。
在看具体的日志之前，先来明确一些名词，并回顾一下java8中的堆存结构与GC。

3.1 名词解释

STW : stop-the-world，意思是系统暂停，或者说jvm中GC相关线程以外的所有应用线程全部暂停，所以叫世界暂停。。。
Minor GC : 新生代GC，指发生在新生代的垃圾收集动作，java8中所有的Minor GC都会触发STW，不过这个过程非常短暂，通常在ms的程度。
Major GC/Full GC : 老年代GC，指发生在老年代的垃圾收集，它要比Minor GC慢很多，触发的STW也更长。我们在生产环境中要特别注意Major GC引起的STW。

3.2 java8堆内存结构与GC简介

3.2.1 java8堆内存结构

java8的堆内存分为新生代(young gen，有时翻译为年轻代)和老年代(old gen，又叫年老代)，新生代又分为eden区和存活区，存活区有两个，S1和S2(或者S0和S1)。

3.2.2 新生代GC

JVM启动之后，对象被创建时先放在eden区，当eden快满时，GC会遍历eden中的对象，将失去引用的对象清除，剩下的幸存者放入S1(如果S1放不下就扔到老年代)，同时清空eden；过一会eden又快满了，这时GC会遍历eden+S1中所有对象，幸存者放入S2，同时清空eden和S1；eden再次快满，再往S1倒腾，如此往复。

具体新生代GC有哪些类型，采用的什么算法，以后有机会再学习分享。

3.2.3 老年代GC

上述新生代GC的过程中，总会有一些对象，总能存活下来，他们会被放到老年代，因为总是干不掉；还有一些对象，太大了，新生代放不下或者放下会导致新生代频繁GC，那就创建的时候就扔到老年代去；还有一些是新生代GC时幸存对象太多，S1或S2放不下了，就打发到老年代来。
老年代的对象会越来越多，当达到一个阈值时，也要触发GC，再看看有没有能干掉的对象。

具体老年代GC有哪些类型，采用的什么算法，以后有机会再学习分享。

3.3 GC日志分析

3.3.1 ParNew日志

一个典型的parNew的日志如下：

[GC (Allocation Failure) 2019-12-24T11:57:02.023+0800: 54249.040: [ParNew: 230534K->2665K(256256K), 0.0125008 secs] 259842K->31977K(827648K), 0.0127202 secs] [Times: user=0.05 sys=0.00, real=0.01 secs]

其中，

• GC (Allocation Failure) : 代表这是一个新生代GC，发生的原因是"Allocation Failure"，新生代不能满足创建对象所需申请的空间了；
• 2019-12-24T11:57:02.023+0800 : 本次GC发生的系统时间
• 54249.040 : 本次GC发生的时间戳，自JVM启动之后的秒数
• [ParNew: 230534K->2665K(256256K), 0.0125008 secs] : 本次GC是ParNewGC，230534K->2665K是本次GC前后新生代的实际size，(256256K)是新生代容量，0.0125008 secs大约是本次GC在新生代的耗时，英文原文是"Duration for the collection w/o final cleanup"，不太懂啥意思。。。
• 259842K->31977K(827648K), 0.0127202 secs : 本次GC前后堆内存大小变化，堆内存容量，以及GC整体耗时(实际上是标记和复制年轻代活着的对象所花费的时间，同时包括和老年代通信的开销、对象移动到老年代所花费的时间、本次垃圾收集周期结束后的一些对象清理的开销。)
• [Times: user=0.05 sys=0.00, real=0.01 secs] : GC事件在不同维度的耗时，user是GC实际使用CPU的时间，sys是系统调用或系统事件响应的耗时，real是导致应用程序暂停的时间，最后这个是最重要的考察维度。

3.3.2 CMS日志

一个典型的CMS日志如下：

[GC (CMS Initial Mark) [1 CMS-initial-mark: 4606K(571392K)] 37496K(827648K), 0.0085097 secs] [Times: user=0.03 sys=0.00, real=0.00 secs]
[CMS-concurrent-mark-start]
[CMS-concurrent-mark: 0.005/0.006 secs] [Times: user=0.03 sys=0.00, real=0.01 secs]
[CMS-concurrent-preclean-start]
[CMS-concurrent-preclean: 0.001/0.001 secs] [Times: user=0.01 sys=0.00, real=0.00 secs]
[CMS-concurrent-abortable-preclean-start]
[CMS-concurrent-abortable-preclean: 0.717/2.071 secs] [Times: user=3.23 sys=0.07, real=2.07 secs]
[GC (CMS Final Remark) [YG occupancy: 165546 K (256256 K)]2019-12-23T20:54:05.051+0800: 4.167: [Rescan (parallel) , 0.0076715 secs]2019-12-23T20:54:05.058+0800: 4.175: [weak refs processing, 0.0000297 secs]2019-12-23T20:54:05.058+0800: 4.175: [class unloading, 0.0038254 secs]2019-12-23T20:54:05.062+0800: 4.179: [scrub symbol table, 0.0027044 secs]2019-12-23T20:54:05.065+0800: 4.182: [scrub string table, 0.0005307 secs][1 CMS-remark: 4606K(571392K)] 170152K(827648K), 0.0156110 secs] [Times: user=0.06 sys=0.00, real=0.02 secs]
[CMS-concurrent-sweep-start]
[CMS-concurrent-sweep: 0.002/0.002 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
[CMS-concurrent-reset-start]
[CMS-concurrent-reset: 0.003/0.003 secs] [Times: user=0.01 sys=0.00, real=0.00 secs]

可以看到，CMS包含7个阶段，有两个阶段会STW，需要特别注意。

阶段一、Initial Mark

会有短暂的STW
CMS初始化标记的阶段，从垃圾回收的"根对象"(GC Root)开始，扫描与"根对象"直接关联的对象，并做标记，在此期间，其他线程都会停止，但耗时很短。具体"根对象"是什么东西，我也不晓得。。。

[1 CMS-initial-mark: 4606K(571392K)] 37496K(827648K), 0.0085097 secs]中，前面的4606K(571392K)表示当前老年代的已使用的size和分配的容量，后面的37496K(827648K)是当前堆内存的实际大小和容量。

阶段二、Concurrent Mark

并发标记阶段，与其他应用线程并发执行，过程耗时较长。目的是从"根对象"开始对堆中对象进行可达性分析，找出存活的对象。

阶段三、Concurrent Preclean

并发预清理阶段，也是与应用线程并发执行的。虚拟机查找在上一步"并发标记阶段"(Concurrent Mark)时进入老年代的对象。通过重新扫描，减少后面的阶段五"Final Remark"的工作，因为"Final Remark"会STW。

阶段四、Concurrent Abortable Preclean

并发可中止预清理阶段，运行在阶段三"Concurrent Preclean"和阶段五"Final Remark"之间，会一直运行，直到获得所期望的eden空间占用率。这个阶段是为了避免在阶段五"Final Remark"执行之后紧跟着发生一次minorGC，所以要尽量清空eden区。事实上，JVM会把下个阶段"Final Remark"尽量安排在两次minorGC之间。

阶段五、Final Remark

会有较长的STW
重新标记阶段，会暂停所有的应用线程。该阶段的任务是标记整个年老代的所有的存活对象。

日志分析：

• CMS Final Remark : 收集阶段，这个阶段会标记老年代全部的存活对象，包括那些在并发标记阶段更改的或者新创建的引用对象
• YG occupancy : 年轻代当前占用情况和容量
• Rescan (parallel) : 重新标记所花的时间
• weak refs processing : 处理弱引用所花的时间
• class unloading : 卸载无用的class所花的时间
• scrub symbol table 与 scrub string table : 清理类元数据及内部字符串所花的时间。。。(that is cleaning up symbol and string tables which hold class-level metadata and internalized string respectively)。。。不太明白"internalized string"是什么。。。~~~~
• [Times: user=0.06 sys=0.00, real=0.02 secs] : 参考ParNew日志

阶段六、Concurrent Sweep

并发清理阶段，与应用线程并发执行，这个阶段的目的就是移除那些不用的对象，回收他们占用的空间。

阶段七、Concurrent Reset

开始并发重置。在这个阶段，与CMS相关的对象被重新初始化，这样下一个周期可以正常进行。

四、java8中一般的GC优化参数

顺便记一下生产上的经典的java8的GC组合的参数设置，parnew + cms。java8默认GC不是这套，所以要自己在jvm启动参数里加。

-XX:+UseParNewGC -XX:+UseConcMarkSweepGC -XX:CMSInitiatingOccupancyFraction=70 -XX:+CMSParallelRemarkEnabled

参数解释：

• -XX:+UseParNewGC : 指定新生代使用ParNew垃圾回收器
• -XX:+UseConcMarkSweepGC : 指定老年代使用CMS垃圾回收器
• -XX:CMSInitiatingOccupancyFraction : CMS触发阈值，当老年代内存使用达到这个比例时就触发CMS
• -XX:+CMSParallelRemarkEnabled : 让CMS采用并行标记的方式降低停顿