java8添加并查看GC日志

背景

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

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

直接上个例子，再解释。

1	-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。

名词解释

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。

java8 堆内存结构与 GC 简介

java8 堆内存结构

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

新生代 GC

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

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

老年代 GC

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

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

GC 日志分析

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 是导致应用程序暂停的时间，最后这个是最重要的考察维度。

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 启动参数里加。

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

参数解释：

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