GC日志分析之配置参数

一、常用的 GC 参数

我们从简单到复杂，一步一步来验证前面学习的知识，学会使用，加深巩固。

启动示例程序

如果是在 IDEA、Eclipse 等集成开发环境中，直接在文件中点击鼠标右键，选择“Run…”即可执行。

如果使用 JDK 命令行，则可以使用 javac 工具来编译，使用 java 命令来执行（还记得吗？JDK 8 以上版本，这两个命令可以合并成一个）：

$ javac demo/jvm0204/*.java
$ java demo.jvm0204.GCLogAnalysis
正在执行...
执行结束!共生成对象次数:1423

程序执行 1 秒钟就自动结束了，因为没有指定任何启动参数，所以输出的日志内容也很简单。

 

我们依次加上这些参数来看看效果。

输出 GC 日志详情

然后加上启动参数 -XX:+PrintGCDetails，打印 GC 日志详情，再次执行示例。

IDEA 等集成开发环境可以在“VM options”中指定启动参数，参考前面的内容。注意不要有多余的空格。

java -XX:+PrintGCDetails demo.jvm0204.GCLogAnalysis

执行结果摘录如下：

正在执行...
[GC (Allocation Failure)
  [PSYoungGen: 65081K->10728K(76288K)]
  65081K->27102K(251392K), 0.0112478 secs]
  [Times: user=0.03 sys=0.02, real=0.01 secs]
......此处省略了多行
[Full GC (Ergonomics)
  [PSYoungGen: 80376K->0K(872960K)]
  [ParOldGen: 360220K->278814K(481280K)]
  440597K->278814K(1354240K),
  [Metaspace: 3443K->3443K(1056768K)],
  0.0406179 secs]
  [Times: user=0.23 sys=0.01, real=0.04 secs]
执行结束!共生成对象次数:746
Heap
 PSYoungGen total 872960K, used 32300K [0x000000076ab00000, 0x00000007b0180000, 0x00000007c0000000)
  eden space 792576K, 4% used [0x000000076ab00000,0x000000076ca8b370,0x000000079b100000)
  from space 80384K, 0% used [0x00000007a3800000,0x00000007a3800000,0x00000007a8680000)
  to space 138240K, 0% used [0x000000079b100000,0x000000079b100000,0x00000007a3800000)
 ParOldGen total 481280K, used 278814K [0x00000006c0000000, 0x00000006dd600000, 0x000000076ab00000)
  object space 481280K, 57% used [0x00000006c0000000,0x00000006d1047b10,0x00000006dd600000)
 Metaspace used 3449K, capacity 4494K, committed 4864K, reserved 1056768K
  class space used 366K, capacity 386K, committed 512K, reserved 1048576K

可以看到，使用启动参数 -XX:+PrintGCDetails，发生 GC 时会输出相关的 GC 日志。

这个参数的格式为: -XX:+，这是一个布尔值开关。

在程序执行完成后、JVM 关闭前，还会输出各个内存池的使用情况，从最后面的输出中可以看到。

下面我们来简单解读上面输出的堆内存信息。

Heap 堆内存使用情况

PSYoungGen total 872960K, used 32300K [0x......)
 eden space 792576K, 4% used [0x......)
 from space 80384K, 0% used [0x......)
 to space 138240K, 0% used [0x......)

PSYoungGen，年轻代总计 872960K，使用量 32300K，后面的方括号中是内存地址信息。

• 其中 eden space 占用了 792576K，其中 4% used
• 其中 from space 占用了 80384K，其中 0% used
• 其中 to space 占用了 138240K，其中 0% used

ParOldGen total 481280K, used 278814K [0x......)
 object space 481280K, 57% used [0x......)

ParOldGen，老年代总计 total 481280K，使用量 278814K。

• 其中 object space 占用了 481280K，其中 57% used

Metaspace used 3449K, capacity 4494K, committed 4864K, reserved 1056768K
 class space used 366K, capacity 386K, committed 512K, reserved 1048576K

Metaspace，元数据区总计使用了 3449K，容量是 4494K，JVM 保证可用的大小是 4864K，保留空间 1GB 左右。

• 其中 class space 使用了 366K，capacity 386K

指定 GC 日志文件

我们在前面的基础上，加上启动参数 -Xloggc:gc.demo.log，再次执行。

# 请注意命令行启动时没有换行，此处是手工排版
java -Xloggc:gc.demo.log -XX:+PrintGCDetails
 demo.jvm0204.GCLogAnalysis

提示：从 JDK 8 开始，支持使用 %p、%t 等占位符来指定 GC 输出文件，分别表示进程 pid 和启动时间戳。

例如：-Xloggc:gc.%p.log、-Xloggc:gc-%t.log。

在某些情况下，将每次 JVM 执行的 GC 日志输出到不同的文件可以方便排查问题。

如果业务访问量大，导致 GC 日志文件太大，可以开启 GC 日志轮换，分割成多个文件，可以参考：

https://blog.gceasy.io/2016/11/15/rotating-gc-log-files

执行后在命令行输出的结果如下：

正在执行...
执行结束!共生成对象次数:1327

GC 日志哪去了？

查看当前工作目录，可以发现多了一个文件 gc.demo.log。 如果是 IDE 开发环境，gc.demo.log 文件可能在项目的根目录下。 当然，我们也可以指定 GC 日志文件存放的绝对路径，比如 -Xloggc:/var/log/gc.demo.log 等形式。

gc.demo.log 文件的内容如下：

Java HotSpot(TM) 64-Bit Server VM (25.162-b12) ......
Memory: 4k page，physical 16777216k(1519448k free)


/proc/meminfo:


CommandLine flags:
  -XX:InitialHeapSize=268435456 -XX:MaxHeapSize=4294967296
  -XX:+PrintGC -XX:+PrintGCDetails -XX:+PrintGCTimeStamps
  -XX:+UseCompressedClassPointers -XX:+UseCompressedOops
  -XX:+UseParallelGC
0.310: [GC (Allocation Failure)
  [PSYoungGen: 61807K->10732K(76288K)]
  61807K->22061K(251392K), 0.0094195 secs]
  [Times: user=0.02 sys=0.02, real=0.01 secs]
0.979: [Full GC (Ergonomics)
  [PSYoungGen: 89055K->0K(572928K)]
  [ParOldGen: 280799K->254491K(434176K)]
  369855K->254491K(1007104K),
  [Metaspace: 3445K->3445K(1056768K)],
  0.0362652 secs]
  [Times: user=0.20 sys=0.01, real=0.03 secs]
...... 此处省略部分内容
Heap
...... 堆内存信息格式请参考前面的日志

我们可以发现，加上 -Xloggc: 参数之后，GC 日志信息输出到日志文件中。

文件里最前面是 JVM 相关信息，比如内存页面大小、物理内存大小、剩余内存等信息。

然后是 CommandLine flags 这部分内容。在分析 GC 日志文件时，命令行参数也是一项重要的参考。因为可能你拿到了日志文件，却不知道线上的配置，日志文件中打印了这个信息，能有效减少分析排查时间。

指定 -Xloggc: 参数，自动加上了 -XX:+PrintGCTimeStamps 配置。观察 GC 日志文件可以看到，每一行前面多了一个时间戳（如 0.310:），表示 JVM 启动后经过的时间（单位秒）。

细心的同学还可以发现，JDK 8 默认使用的垃圾收集器参数：-XX:+UseParallelGC。

打印 GC 事件发生的日期和时间

我们在前面的基础上，加上启动参数 -XX:+PrintGCDateStamps，再次执行。

java -Xloggc:gc.demo.log -XX:+PrintGCDetails
 -XX:+PrintGCDateStamps demo.jvm0204.GCLogAnalysis

执行完成后，GC 日志文件中的内容摘录如下：

...... 省略多行
CommandLine flags:
  -XX:InitialHeapSize=268435456 -XX:MaxHeapSize=4294967296
  -XX:+PrintGC -XX:+PrintGCDateStamps
  -XX:+PrintGCDetails -XX:+PrintGCTimeStamps
  -XX:+UseCompressedClassPointers -XX:+UseCompressedOops
  -XX:+UseParallelGC
2019-12-15T15:09:59.235-0800: 0.296:
  [GC (Allocation Failure)
    [PSYoungGen: 63844K->10323K(76288K)]
    63844K->20481K(251392K),
    0.0087896 secs]
  [Times: user=0.02 sys=0.02, real=0.01 secs]
2019-12-15T15:09:59.889-0800: 0.951:
  [Full GC (Ergonomics)
    [PSYoungGen: 81402K->0K(577536K)]
    [ParOldGen: 270176K->261230K(445952K)]
    351579K->261230K(1023488K),
    [Metaspace: 3445K->3445K(1056768K)],
    0.0369622 secs]
  [Times: user=0.19 sys=0.00, real=0.04 secs]
Heap
  .......省略内容参考前面的格式

可以看到，加上 -XX:+PrintGCDateStamps 参数之后，GC 日志每一行前面，都打印了 GC 发生时的具体时间。如 2019-12-15T15:09:59.235-0800 表示的是“东 8 区时间 2019 年 12 月 15 日 15:09:59 秒.235 毫秒”。

指定堆内存的大小

从前面的示例中可以看到 GC 日志文件中输出的 CommandLine flags 信息。

即使我们没有指定堆内存，JVM在启动时也会自动算出一个默认值出来。例如：-XX:InitialHeapSize=268435456 -XX:MaxHeapSize=4294967296 是笔者机器上的默认值，等价于 -Xms256m -Xmx4g 配置。

我们现在继续增加参数，这次加上启动参数 -Xms512m -Xmx512m，再次执行。

java -Xms512m -Xmx512m
 -Xloggc:gc.demo.log -XX:+PrintGCDetails
 -XX:+PrintGCDateStamps demo.jvm0204.GCLogAnalysis

此时输出的 GC 日志文件内容摘录如下：

......
CommandLine flags:
  -XX:InitialHeapSize=536870912 -XX:MaxHeapSize=536870912
  -XX:+PrintGC -XX:+PrintGCDateStamps
  -XX:+PrintGCDetails -XX:+PrintGCTimeStamps
  -XX:+UseCompressedClassPointers -XX:+UseCompressedOops
  -XX:+UseParallelGC
2019-12-15T15:15:09.677-0800: 0.358:
  [GC (Allocation Failure)
    [PSYoungGen: 129204K->21481K(153088K)]
    129204K->37020K(502784K), 0.0121865 secs]
  [Times: user=0.03 sys=0.03, real=0.01 secs]
2019-12-15T15:15:10.058-0800: 0.739:
  [Full GC (Ergonomics)
    [PSYoungGen: 20742K->0K(116736K)]
    [ParOldGen: 304175K->247922K(349696K)]
    324918K->247922K(466432K),
    [Metaspace: 3444K->3444K(1056768K)],
    0.0319225 secs]
  [Times: user=0.18 sys=0.01, real=0.04 secs]

此时堆内存的初始值和最大值都是 512MB。具体的参数可根据实际需要配置，我们为了演示，使用了一个较小的堆内存配置。

指定垃圾收集器

一般来说，使用 JDK 8 时我们可以使用以下几种垃圾收集器：

-XX:+UseSerialGC
-XX:+UseParallelGC
-XX:+UseParallelGC -XX:+UseParallelOldGC
-XX:+UseConcMarkSweepGC
-XX:+UseConcMarkSweepGC -XX:+UseParNewGC
-XX:+UseG1GC

它们都是什么意思呢，我们再简单回顾一下：

• 使用串行垃圾收集器：-XX:+UseSerialGC
• 使用并行垃圾收集器：-XX:+UseParallelGC 和 -XX:+UseParallelGC -XX:+UseParallelOldGC 是等价的，可以通过 GC 日志文件中的 flags 看出来。
• 使用 CMS 垃圾收集器：-XX:+UseConcMarkSweepGC 和 -XX:+UseParNewGC -XX:+UseConcMarkSweepGC 是等价的。但如果只指定 -XX:+UseParNewGC 参数则老年代 GC 会使用 SerialGC。使用CMS时，命令行参数中会自动计算出年轻代、老年代的初始值和最大值，以及最大晋升阈值等信息（例如 -XX:MaxNewSize=178958336 -XX:NewSize=178958336 -XX:OldSize=357912576）。
• 使用 G1 垃圾收集器：-XX:+UseG1GC。原则上不能指定 G1 垃圾收集器的年轻代大小，否则不仅是画蛇添足，更是自废武功了。因为 G1 的回收方式是小批量划定区块（region）进行，可能一次普通 GC 中既有年轻代又有老年代，可能某个区块一会是老年代，一会又变成年轻代了。

如果使用不支持的 GC 组合，会怎么样呢？答案是会启动失败，报 fatal 错误，有兴趣的同学可以试一下。

下一节会依次演示各种垃圾收集器的使用，并采集和分析他们产生的日志。它们的格式差距并不大，学会分析一种 GC 日志之后，就可以举一反三，对于其他类型的 GC 日志，基本上也能看懂各项信息的大概意思。

其他参数

JVM 里还有一些 GC 日志相关的参数，例如：

• -XX:+PrintGCApplicationStoppedTime 可以输出每次 GC 的持续时间和程序暂停时间；
• -XX:+PrintReferenceGC 输出 GC 清理了多少引用类型。

这里就不再赘述，想了解配置详情的，可以回头复习前面的章节。

说明：大部分情况下，配置 GC 参数并不是越多越好。原则上只配置最重要的几个参数即可，其他的都保持默认值，除非你对系统的业务特征有了深入的分析和了解，才需要进行某些细微参数的调整。毕竟，古语有云：“过早优化是万恶之源”。

二、GC 事件的类型简介

一般来说，垃圾收集事件（Garbage Collection events）可以分为三种类型：

• Minor GC（小型 GC）
• Major GC（大型 GC）
• Full GC（完全 GC）

虽然 Minor GC，Major GC 和 Full GC 这几个词汇到处都在用，但官方并没有给出标准的定义。这些术语出现在官方的各种分析工具和垃圾收集日志中，并不是很统一。官方的文档和工具之间也常常混淆，这些混淆甚至根植于标准的 JVM 工具中。

MinorGC 称为“小型 GC”，还是“次要GC”更合理呢？

辨析：在大部分情况下，发生在年轻代的 Minor GC 次数更多，有些文章将次数更多的 GC 称为“次要 GC”明显是不太合理的。

在这里，我们将 Minor GC 翻译为“小型 GC”，而不是“次要 GC”；将 Major GC 翻译为“大型GC”而不是“主要 GC”；Full GC 翻译为完全 GC；有时候也直接称为 Full GC。

其实这也是因为专有名词在中英文翻译的时候，可能会有多个英语词汇对应一个中文词语，也会有一个英文词汇对应多个中文词语，要看具体情况而定。

比如一个类似的情况：Major Version 和 Minor Version，这两个名词一般翻译为“主要版本”和“次要版本”。这当然没问题，大家都能理解，一看就知道什么意思。甚至直接翻译为“大版本号”和“小版本号”也是能讲得通的。

本节简单介绍了这几种事件类型及其区别，下面我们来看看这些事件类型的具体细节。

Minor GC（小型 GC）

收集年轻代内存的 GC 事件称为 Minor GC。关于 Minor GC 事件，我们需要了解一些相关的内容：

1. 当 JVM 无法为新对象分配内存空间时就会触发 Minor GC（ 一般就是 Eden 区用满了）。如果对象的分配速率很快，那么 Minor GC 的次数也就会很多，频率也就会很快。
2. Minor GC 事件不处理老年代，所以会把所有从老年代指向年轻代的引用都当做 GC Root。从年轻代指向老年代的引用则在标记阶段被忽略。
3. 与我们一般的认知相反，Minor GC 每次都会引起 STW 停顿（stop-the-world），挂起所有的应用线程。对大部分应用程序来说，Minor GC 的暂停时间可以忽略不计，因为 Eden 区里面的对象大部分都是垃圾，也不怎么复制到存活区/老年代。但如果不符合这种情况，那么很多新创建的对象就不能被 GC 清理，Minor GC 的停顿时间就会增大，就会产生比较明显的 GC 性能影响。

简单定义：Minor GC 清理的是年轻代，又或者说 Minor GC 就是“年轻代 GC”（Young GC，简称 YGC）。

Major GC vs. Full GC

值得一提的是，这几个术语都没有正式的定义--无论是在 JVM 规范中还是在 GC 论文中。

我们知道，除了 Minor GC 外，另外两种 GC 事件则是：

• Major GC（大型 GC）：清理老年代空间（Old Space）的 GC 事件。
• Full GC（完全 GC）：清理整个堆内存空间的 GC 事件，包括年轻代空间和老年代空间。

 

其实 Major GC 和 Full GC 有时候并不能很好地区分。更复杂的情况是，很多 Major GC 是由 Minor GC 触发的，所以很多情况下这两者是不可分离的。

另外，像 G1 这种垃圾收集算法，是每次找一小部分区域来进行清理，这部分区域中可能有一部分是年轻代，另一部分区域属于老年代。

 

所以我们不要太纠结具体是叫 Major GC 呢还是叫 Full GC，它们一般都会造成单次较长时间的 STW 暂停。所以我们需要关注的是：某次 GC 事件，是暂停了所有线程、进而对系统造成了性能影响呢，还是与其他业务线程并发执行、暂停时间几乎可以忽略不计。