背景

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 的日志如下：

1
[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 日志如下：

1
2
3
4
5
6
7
8
9
10
11
12
[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 采用并行标记的方式降低停顿