首页 > 编程入门 文章详情

JVM——GC日志实战分析

编程入门 行业动态 更新时间:2024-10-07 18:21:17

JVM——GC日志<a href=https://www.elefans.com/category/jswz/34/1769775.html style=实战分析"/>

JVM——GC日志实战分析

摘要

博文将具体示例来演示如何输出 GC 日志，并对输出的日志信息进行解读分析，从中提取有用的信息。

一、GC环境准备

本次演示的示例代码为了演示需要，我们先来编写一段简单的 Java 代码：

package demo.jvm0204;
import java.util.Random;
import java.util.concurrent.TimeUnit;
import java.util.concurrent.atomic.LongAdder;
/*
演示 GC 日志生成与解读
*/
public class GCLogAnalysis {private static Random random = new Random();public static void main(String[] args) {// 当前毫秒时间戳long startMillis = System.currentTimeMillis();// 持续运行毫秒数; 可根据需要进行修改long timeoutMillis = TimeUnit.SECONDS.toMillis(1);// 结束时间戳long endMillis = startMillis + timeoutMillis;LongAdder counter = new LongAdder();System.out.println("正在执行...");// 缓存一部分对象; 进入老年代int cacheSize = 2000;Object[] cachedGarbage = new Object[cacheSize];// 在此时间范围内,持续循环while (System.currentTimeMillis() < endMillis) {// 生成垃圾对象Object garbage = generateGarbage(100*1024);counter.increment();int randomIndex = random.nextInt(2 * cacheSize);if (randomIndex < cacheSize) {cachedGarbage[randomIndex] = garbage;}}System.out.println("执行结束!共生成对象次数:" + counter.longValue());}// 生成对象private static Object generateGarbage(int max) {int randomSize = random.nextInt(max);int type = randomSize % 4;Object result = null;switch (type) {case 0:result = new int[randomSize];break;case 1:result = new byte[randomSize];break;case 2:result = new double[randomSize];break;default:StringBuilder builder = new StringBuilder();String randomString = "randomString-Anything";while (builder.length() < randomSize) {builder.append(randomString);builder.append(max);builder.append(randomSize);}result = builder.toString();break;}return result;}
}

程序并不复杂，我们指定一个运行时间作为退出条件，时间一到自动退出循环。在generateGarbage 方法中，我们用了随机数来生成各种类型的数组对象并返回。

在 main 方法中，我们用一个数组来随机存放一部分生成的对象，这样可以模拟让部分对象晋升到老年代。具体的持续运行时间和缓存对象个数，各位可以自己进行调整。一般来说，Java 中的大对象主要就是各种各样的数组，比如开发中最常见的字符串，实际上 String 内部就是使用字符数组 char[] 来存储的。

这个示例除了可以用来进行 GC 日志分析之外，稍微修改一下，还可以用作其他用途：

  • 比如让缓存的对象变多，在限制堆内存的情况下，就可以模拟“内存溢出”。
  • 增加运行时长，比如加到 30 分钟或者更长，我们就可以用前面介绍过的 VisualVM 等工具来实时监控和观察。
  • 当然，我们也可以使用全局静态变量来缓存，用来模拟“内存泄漏”，以及进行堆内存 Dump 的试验和分析。
  • 加大每次生成的数组的大小，可以用来模拟“大对象/巨无霸对象”（大对象/巨无霸对象主要是 G1 中的概念，比如超过 1MB 的数组，具体情况在后面的内容中再进行探讨）。

二、常用的GC参数

2.1 输出 GC 日志详情

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

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
HeapPSYoungGen 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 1056768Kclass space used 366K, capacity 386K, committed 512K, reserved 1048576K

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

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

在程序执行完成后、JVM 关闭前，还会输出各个内存池的使用情况，从最后面的输出中可以看到。下面我们来简单解读上面输出的堆内存信息。

2.2 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 1056768Kclass space used 366K, capacity 386K, committed 512K, reserved 1048576KMetaspace，元数据区总计使用了 3449K，容量是 4494K，JVM 保证可用的大小是 4864K，保留空间 1GB 左右。其中 class space 使用了 366K，capacity 386K

2.3 指定 GC 日志文件

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

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

在某些情况下，将每次 JVM 执行的 GC 日志输出到不同的文件可以方便排查问题。如果业务访问量大，导致 GC 日志文件太大，可以开启 GC 日志轮换，分割成多个文件，可以参考：ROTATING GC LOG FILES – GC easy – Universal Java GC Log Analyser

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

2.4 打印GC事件日期和时间

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

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

2.5 指定堆内存的大小

从前面的示例中可以看到 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

2.6 指定垃圾收集器

一般来说，使用 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 中既有年轻代又有老年代，可能某个区块一会是老年代，一会又变成年轻代了。

2.7 其他参数

JVM 里还有一些 GC 日志相关的参数，例如：-XX:+PrintGCApplicationStoppedTime 可以输出每次 GC 的持续时间和程序暂停时间；-XX:+PrintReferenceGC 输出 GC 清理了多少引用类型。

三、GC事件的类型

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

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

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

3.1 Minor 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）。

3.2 Major GC与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 事件，是暂停了所有线程、进而对系统造成了性能影响呢，还是与其他业务线程并发执行、暂停时间几乎可以忽略不计。

四、Serial GC 日志解读

首先，为了打开 GC 日志记录，我们使用下面的 JVM 启动参数如下：

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

让我们看看 Serial GC 的垃圾收集日志，并从中提取信息。启用串行垃圾收集器，程序执行后输出的 GC 日志类似这样（为了方便大家阅读，已手工折行）：

Java HotSpot(TM) 64-Bit Server VM (25.162-b12) ......
Memory: 4k page，physical 16777216k(1551624k free)
CommandLine flags:-XX:InitialHeapSize=536870912 -XX:MaxHeapSize=536870912-XX:+PrintGC -XX:+PrintGCDateStamps-XX:+PrintGCDetails -XX:+PrintGCTimeStamps-XX:+UseCompressedClassPointers -XX:+UseCompressedOops-XX:+UseSerialGC
2019-12-15T15:18:36.592-0800: 0.420:[GC (Allocation Failure)2019-12-15T15:18:36.592-0800: 0.420:[DefNew: 139776K->17472K(157248K)，0.0364555 secs]139776K->47032K(506816K)，0.0365665 secs][Times: user=0.02 sys=0.01，real=0.03 secs]
......
2019-12-15T15:18:37.081-0800: 0.908:[GC (Allocation Failure)2019-12-15T15:18:37.081-0800: 0.908:[DefNew: 156152K->156152K(157248K)，0.0000331 secs]2019-12-15T15:18:37.081-0800: 0.908:[Tenured: 299394K->225431K(349568K)，0.0539242 secs]455546K->225431K(506816K)，[Metaspace: 3431K->3431K(1056768K)]，0.0540948 secs][Times: user=0.05 sys=0.00，real=0.05 secs]

日志的第一行是 JVM 版本信息，第二行往后到第一个时间戳之间的部分，展示了内存分页、物理内存大小，命令行参数等信息，这部分前面介绍过，不在累述。

仔细观察，我们发现在这段日志中发生了两次 GC 事件，其中一次清理的是年轻代，另一次清理的是整个堆内存。让我们先来分析前一次年轻代 GC 事件。

五、Minor GC 日志分析

这次年轻代 GC 事件对应的日志内容：

2019-12-15T15:18:36.592-0800: 0.420:[GC (Allocation Failure)2019-12-15T15:18:36.592-0800: 0.420:[DefNew: 139776K->17472K(157248K)，0.0364555 secs]139776K->47032K(506816K)，0.0365665 secs][Times: user=0.02 sys=0.01，real=0.03 secs]
  1. 2019-12-15T15:18:36.592-0800：GC 事件开始的时间点。其中 -0800 表示当前时区为东八区，这只是一个标识，方便我们直观判断 GC 发生的时间点。后面的 0.420 是 GC 事件相对于 JVM 启动时间的间隔，单位是秒。
  2. GC 用来区分 Minor GC 还是 Full GC 的标志。GC 表明这是一次小型 GC（Minor GC），即年轻代 GC。Allocation Failure 表示触发 GC 的原因。本次 GC 事件，是由于对象分配失败，年轻代中没有空间来存放新生成的对象引起的。
  3. DefNew 表示垃圾收集器的名称。这个名字表示：年轻代使用的单线程、标记—复制、STW 垃圾收集器。139776K->17472K 表示在垃圾收集之前和之后的年轻代使用量。(157248K) 表示年轻代的总空间大小。进一步分析可知：GC 之后年轻代使用率为 11%。
  4. 139776K->47032K(506816K) 表示在垃圾收集之前和之后整个堆内存的使用情况。(506816K) 则表示堆内存可用的总空间大小。进一步分析可知：GC 之后堆内存使用量为 9%。
  5. 0.0365665 secs：GC 事件持续的时间，以秒为单位。
  6. [Times: user=0.02 sys=0.01，real=0.03 secs]：此次 GC 事件的持续时间，通过三个部分来衡量。user 部分表示所有 GC 线程消耗的 CPU 时间；sys 部分表示系统调用和系统等待事件消耗的时间。real 则表示应用程序暂停的时间。因为串行垃圾收集器（Serial Garbage Collector）只使用单个线程，所以这里 real=user+system，0.03 秒也就是 30 毫秒。

凭经验，这个暂停时间对大部分系统来说可以接受，但对某些延迟敏感的系统就不太理想了，比如实时的游戏服务、高频交易业务，30ms 暂停导致的延迟可能会要了亲命。这样解读之后，我们可以分析 JVM 在 GC 事件中的内存使用以及变化情况。在此次垃圾收集之前，堆内存总的使用量为 139776K，其中年轻代使用了 139776K。可以算出，GC 之前老年代空间的使用量为 0。（实际上这是 GC 日志中的第一条记录）

这些数字中蕴含了更重要的信息：

  • GC 前后对比，年轻代的使用量为 139776K->17472K，减少了 122304K。
  • 但堆内存的总使用量 139776K->47032K，只下降了 92744K。

可以算出，从年轻代提升到老年代的对象占用了“122304K-92744K=29560K”的内存空间。当然，另一组数字也能推算出 GC 之后老年代的使用量：47032K-17472K=29560K。

此次 GC 事件的示意图如下所示：

六、Full GC 日志分析

分析完第一次 GC 事件之后，我们心中应该有个大体的模式了。一起来看看Full GC 事件的日志：

2019-12-15T15:18:37.081-0800: 0.908:[GC (Allocation Failure)2019-12-15T15:18:37.081-0800: 0.908:[DefNew: 156152K->156152K(157248K)，0.0000331 secs]2019-12-15T15:18:37.081-0800: 0.908:[Tenured: 299394K->225431K(349568K)，0.0539242 secs]455546K->225431K(506816K)，[Metaspace: 3431K->3431K(1056768K)]，0.0540948 secs][Times: user=0.05 sys=0.00，real=0.05 secs]
  1. 2019-12-15T15:18:37.081-0800：GC 事件开始的时间。
  2. [DefNew: 156152K->156152K(157248K)，0.0000331 secs]：前面已经解读过了，因为内存分配失败，发生了一次年轻代 GC。此次 GC 同样用的 DefNew 收集器。注意：此次垃圾收集消耗了 0.0000331 秒，基本上确认本次 GC 事件没怎么处理年轻代。
  3. Tenured：用于清理老年代空间的垃圾收集器名称。Tenured 表明使用的是单线程的 STW 垃圾收集器，使用的算法为“标记—清除—整理（mark-sweep-compact）”。 299394K->225431K(349568K) 表示 GC 前后老年代的使用量，以及老年代的空间大小。0.0539242 secs 是清理老年代所花的时间。
  4. 455546K->225431K(506816K)：在 GC 前后整个堆内存部分的使用情况，以及可用的堆空间大小。
  5. [Metaspace: 3431K->3431K(1056768K)]：Metaspace 空间的变化情况。可以看出，此次 GC 过程中 Metaspace 也没有什么变化。
  6. [Times: user=0.05 sys=0.00，real=0.05 secs]：GC 事件的持续时间，分为 user、sys、real 三个部分。因为串行垃圾收集器只使用单个线程，因此“real=user+system”。50 毫秒的暂停时间，比起前面年轻代的 GC 来说增加了一倍左右。这个时间跟什么有关系呢？答案是：GC 时间，与 GC 后存活对象的总数量关系最大。

进一步分析这些数据，GC 之后老年代的使用率为：225431K/349568K=64%，这个比例不算小，但也不能就此说出了什么问题，毕竟 GC 后内存使用量下降了，还需要后续的观察……

和年轻代 GC 相比，比较明显的差别是此次 GC 事件清理了老年代和 Metaspace。FullGC，我们主要关注 GC 之后内存使用量是否下降，其次关注暂停时间。简单估算，GC 后老年代使用量为 220MB 左右，耗时 50ms。如果内存扩大 10 倍，GC 后老年代内存使用量也扩大 10 倍，那耗时可能就是 500ms 甚至更高，就会系统有很明显的影响了。这也是我们说串行 GC 性能弱的一个原因，服务端一般是不会采用串行 GC 的。

七、Parallel GC 日志解读

并行垃圾收集器对年轻代使用“标记—复制（mark-copy）”算法，对老年代使用“标记—清除—整理（mark-sweep-compact）”算法。年轻代和老年代的垃圾回收时都会触发 STW 事件，暂停所有的应用线程，再来执行垃圾收集。在执行“标记”和“复制/整理”阶段时都使用多个线程，因此得名“Parallel”。通过多个 GC 线程并行执行的方式，能使 JVM 在多 CPU 平台上的 GC 时间大幅减少。通过命令行参数 -XX:ParallelGCThreads=NNN 可以指定 GC 线程的数量，其默认值为 CPU 内核数量。下面的三组命令行参数是等价的，都可用来指定并行垃圾收集器：

-XX:+UseParallelGC
-XX:+UseParallelOldGC
-XX:+UseParallelGC -XX:+UseParallelOldGC
# 请注意命令行启动时没有换行
java -XX:+UseParallelGC
-Xms512m -Xmx512m
-Xloggc:gc.demo.log
-XX:+PrintGCDetails
-XX:+PrintGCDateStamps
demo.jvm0204.GCLogAnalysis

并行垃圾收集器适用于多核服务器，其主要目标是增加系统吞吐量（也就是降低 GC 总体消耗的时间）。为了达成这个目标，会使用尽可能多的 CPU 资源：

  • 在 GC 事件执行期间，所有 CPU 内核都在并行地清理垃圾，所以暂停时间相对来说更短；
  • 在两次 GC 事件中间的间隔期，不会启动 GC 线程，所以这段时间内不会消耗任何系统资源。

另一方面，因为并行 GC 的所有阶段都不能中断，所以并行 GC 很可能会出现长时间的卡顿。

长时间卡顿的意思，就是并行 GC 启动后，一次性完成所有的 GC 操作，所以单次暂停的时间较长。假如系统延迟是非常重要的性能指标，那么就应该选择其他垃圾收集器。执行上面的命令行，让我们看看并行垃圾收集器的 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-18T00:37:47.463-0800: 0.690:[GC (Allocation Failure)[PSYoungGen: 104179K->14341K(116736K)]383933K->341556K(466432K)，0.0229343 secs][Times: user=0.04 sys=0.08，real=0.02 secs]
2019-12-18T00:37:47.486-0800: 0.713:[Full GC (Ergonomics)[PSYoungGen: 14341K->0K(116736K)][ParOldGen: 327214K->242340K(349696K)]341556K->242340K(466432K)，[Metaspace: 3322K->3322K(1056768K)]，0.0656553 secs][Times: user=0.30 sys=0.02，real=0.07 secs]
......

 前面的 GC 事件是发生在年轻代 Minor GC：

2019-12-18T00:37:47.463-0800: 0.690:[GC (Allocation Failure)[PSYoungGen: 104179K->14341K(116736K)]383933K->341556K(466432K)，0.0229343 secs][Times: user=0.04 sys=0.08，real=0.02 secs]
  1. 2019-12-18T00:37:47.463-0800: 0.690：GC 事件开始的时间。
  2. GC：用来区分 Minor GC 还是 Full GC 的标志。这里是一次“小型 GC（Minor GC）”。
  3. PSYoungGen：垃圾收集器的名称。这个名字表示的是在年轻代中使用并行的“标记—复制（mark-copy）”，全线暂停（STW）垃圾收集器。104179K->14341K(116736K) 表示 GC 前后的年轻代使用量，以及年轻代的总大小，简单计算 GC 后的年轻代使用率 14341K/116736K=12%。
  4. 383933K->341556K(466432K) 则是 GC 前后整个堆内存的使用量，以及此时可用堆的总大小，GC 后堆内存使用率为 341556K/466432K=73%，这个比例不低，事实上前面已经发生过 FullGC 了，只是这里没有列出来。
  5. [Times: user=0.04 sys=0.08，real=0.02 secs]：GC 事件的持续时间，通过三个部分来衡量。user 表示 GC 线程所消耗的总 CPU 时间，sys 表示操作系统调用和系统等待事件所消耗的时间； real 则表示应用程序实际暂停的时间。因为并不是所有的操作过程都能全部并行，所以在 Parallel GC 中，real 约等于 user+system/GC 线程数。笔者的机器是 8 个物理线程，所以默认是 8 个 GC 线程。分析这个时间，可以发现，如果使用串行 GC，可能得暂停 120 毫秒，但并行 GC 只暂停了 20 毫秒，实际上性能是大幅度提升了。

通过这部分日志可以简单算出：在 GC 之前，堆内存总使用量为 383933K，其中年轻代为 104179K，那么可以算出老年代使用量为 279754K。

在此次 GC 完成后，年轻代使用量减少了 104179K-14341K=89838K，总的堆内存使用量减少了 383933K-341556K=42377K。

那么我们可以计算出有“89838K-42377K=47461K”的对象从年轻代提升到老年代。老年代的使用量为：341556K-14341K=327215K。

老年代的大小为 466432K-116736K=349696K，使用率为 327215K/349696K=93%，基本上快满了。

总结：年轻代 GC，我们可以关注暂停时间，以及 GC 后的内存使用率是否正常，但不用特别关注 GC 前的使用量，而且只要业务在运行，年轻代的对象分配就少不了，回收量也就不会少。

2019-12-18T00:37:47.486-0800: 0.713:[Full GC (Ergonomics)[PSYoungGen: 14341K->0K(116736K)][ParOldGen: 327214K->242340K(349696K)]341556K->242340K(466432K)，[Metaspace: 3322K->3322K(1056768K)]，0.0656553 secs][Times: user=0.30 sys=0.02，real=0.07 secs]
  1. 2019-12-18T00:37:47.486-0800：GC 事件开始的时间。
  2. Full GC：完全 GC 的标志。Full GC 表明本次 GC 清理年轻代和老年代，Ergonomics 是触发 GC 的原因，表示 JVM 内部环境认为此时可以进行一次垃圾收集。
  3. [PSYoungGen: 14341K->0K(116736K)]：和上面的示例一样，清理年轻代的垃圾收集器是名为“PSYoungGen”的 STW 收集器，采用“标记—复制（mark-copy）”算法。年轻代使用量从 14341K 变为 0，一般 Full GC 中年轻代的结果都是这样。
  4. ParOldGen：用于清理老年代空间的垃圾收集器类型。在这里使用的是名为 ParOldGen 的垃圾收集器，这是一款并行 STW 垃圾收集器，算法为“标记—清除—整理（mark-sweep-compact）”。327214K->242340K(349696K)]：在 GC 前后老年代内存的使用情况以及老年代空间大小。简单计算一下，GC 之前，老年代使用率为 327214K/349696K=93%，GC 后老年代使用率 242340K/349696K=69%，确实回收了不少。那么有多少内存提升到老年代呢？其实在 Full GC 里面不好算，而在 Minor GC 之中比较好算，原因大家自己想一想。
  5. 341556K->242340K(466432K)：在垃圾收集之前和之后堆内存的使用情况，以及可用堆内存的总容量。简单分析可知，GC 之前堆内存使用率为 341556K/466432K=73%，GC 之后堆内存的使用率为：242340K/466432K=52%。
  6. [Metaspace: 3322K->3322K(1056768K)]：前面我们也看到了关于 Metaspace 空间的类似信息。可以看出，在 GC 事件中 Metaspace 里面没有回收任何对象。
  7. 0.0656553secs：GC 事件持续的时间，以秒为单位。
  8. [Times: user=0.30 sys=0.02，real=0.07 secs]：GC 事件的持续时间，含义参见前面。

Full GC 和 Minor GC 的区别是很明显的，此次 GC 事件除了处理年轻代，还清理了老年代和 Metaspace。总结：Full GC 时我们更关注老年代的使用量有没有下降，以及下降了多少。如果 FullGC 之后内存不怎么下降，使用率还很高，那就说明系统有问题了。

 八、CMS 的 GC 日志解读

通过以下选项来指定 CMS 垃圾收集器：

-XX:+UseConcMarkSweepGC

如果 CPU 资源受限，CMS 的吞吐量会比并行 GC 差一些。示例：

# 请注意命令行启动时没有换行，此处是方便大家阅读。
java -XX:+UseConcMarkSweepGC
-Xms512m
-Xmx512m
-Xloggc：gc.demo.log
-XX:+PrintGCDetails
-XX:+PrintGCDateStamps
demo.jvm0204.GCLogAnalysis

和前面分析的串行 GC/并行 GC 一样，我们将程序启动起来，看看 CMS 算法生成的 GC 日志是什么样子：

Java HotSpot(TM) 64-Bit Server VM (25.162-b12) 。。。
Memory： 4k page，physical 16777216k(1168104k free)CommandLine flags：-XX:InitialHeapSize=536870912 -XX:MaxHeapSize=536870912-XX:MaxNewSize=178958336 -XX:MaxTenuringThreshold=6-XX:NewSize=178958336 -XX:OldPLABSize=16 -XX:OldSize=357912576-XX:+PrintGC -XX:+PrintGCDateStamps-XX:+PrintGCDetails -XX:+PrintGCTimeStamps-XX:+UseCompressedClassPointers -XX:+UseCompressedOops-XX:+UseConcMarkSweepGC -XX:+UseParNewGC2019-12-22T00:00:31.865-0800: 1.067：[GC (Allocation Failure)2019-12-22T00:00:31.865-0800: 1.067：[ParNew： 136418K->17311K(157248K)，0.0233955 secs]442378K->360181K(506816K)，0.0234719 secs][Times: user=0.10 sys=0.02，real=0.02 secs]2019-12-22T00:00:31.889-0800: 1.091：[GC (CMS Initial Mark)[1 CMS-initial-mark: 342870K(349568K)]363883K(506816K)，0.0002262 secs][Times: user=0.00 sys=0.00,real=0.00 secs]
2019-12-22T00:00:31.889-0800: 1.091：[CMS-concurrent-mark-start]
2019-12-22T00:00:31.890-0800: 1.092：[CMS-concurrent-mark: 0.001/0.001 secs][Times: user=0.00 sys=0.00,real=0.01 secs]
2019-12-22T00:00:31.891-0800: 1.092：[CMS-concurrent-preclean-start]
2019-12-22T00:00:31.891-0800: 1.093：[CMS-concurrent-preclean: 0.001/0.001 secs][Times: user=0.00 sys=0.00,real=0.00 secs]
2019-12-22T00:00:31.891-0800: 1.093：[CMS-concurrent-abortable-preclean-start]
2019-12-22T00:00:31.891-0800: 1.093：[CMS-concurrent-abortable-preclean: 0.000/0.000 secs][Times: user=0.00 sys=0.00,real=0.00 secs]
2019-12-22T00:00:31.891-0800: 1.093：[GC (CMS Final Remark)[YG occupancy: 26095 K (157248 K)]2019-12-22T00:00:31.891-0800: 1.093：[Rescan (parallel) ，0.0002680 secs]2019-12-22T00:00:31.891-0800: 1.093：[weak refs processing，0.0000230 secs]2019-12-22T00:00:31.891-0800: 1.093：[class unloading，0.0004008 secs]2019-12-22T00:00:31.892-0800: 1.094：[scrub symbol table，0.0006072 secs]2019-12-22T00:00:31.893-0800: 1.095：[scrub string table，0.0001769 secs][1 CMS-remark: 342870K(349568K)]368965K(506816K)，0.0015928 secs][Times: user=0.01 sys=0.00,real=0.00 secs]
2019-12-22T00:00:31.893-0800: 1.095：[CMS-concurrent-sweep-start]
2019-12-22T00:00:31.893-0800: 1.095：[CMS-concurrent-sweep： 0.000/0.000 secs][Times: user=0.00 sys=0.00,real=0.00 secs]
2019-12-22T00:00:31.893-0800: 1.095：[CMS-concurrent-reset-start]
2019-12-22T00:00:31.894-0800: 1.096：[CMS-concurrent-reset: 0.000/0.000 secs][Times: user=0.00 sys=0.00,real=0.00 secs]

这只是摘录的一部分 GC 日志。比起串行 GC/并行 GC 来说，CMS 的日志信息复杂了很多，这一方面是因为 CMS 拥有更加精细的 GC 步骤，另一方面 GC 日志很详细就意味着暴露出来的信息也就更全面细致。

Minor GC 日志分析

最前面的几行日志是清理年轻代的 Minor GC 事件：

2019-12-22T00:00:31.865-0800: 1.067：[GC (Allocation Failure)2019-12-22T00:00:31.865-0800: 1.067：[ParNew： 136418K->17311K(157248K)，0.0233955 secs]442378K->360181K(506816K)，0.0234719 secs][Times: user=0.10 sys=0.02，real=0.02 secs]
  1. 2019-12-22T00:00:31.865-0800: 1.067：GC 事件开始的时间。
  2. GC (Allocation Failure)：用来区分 Minor GC 还是 Full GC 的标志。GC 表明这是一次“小型 GC”；Allocation Failure 表示触发 GC 的原因。本次 GC 事件，是由于年轻代可用空间不足，新对象的内存分配失败引起的。
  3. [ParNew： 136418K->17311K(157248K)，0.0233955 secs]：其中 ParNew 是垃圾收集器的名称，对应的就是前面日志中打印的 -XX:+UseParNewGC 这个命令行标志。表示在年轻代中使用的“并行的标记—复制（mark-copy）”垃圾收集器，专门设计了用来配合 CMS 垃圾收集器，因为 CMS 只负责回收老年代。后面的数字表示 GC 前后的年轻代使用量变化，以及年轻代的总大小。0.0233955 secs 是消耗的时间。
  4. 442378K->360181K(506816K)，0.0234719 secs：表示 GC 前后堆内存的使用量变化，以及堆内存空间的大小。消耗的时间是 0.0234719 secs，和前面的 ParNew 部分的时间基本上一样。
  5. [Times: user=0.10 sys=0.02，real=0.02 secs]：GC 事件的持续时间。user 是 GC 线程所消耗的总 CPU 时间；sys 是操作系统调用和系统等待事件消耗的时间；应用程序实际暂停的时间 real ~= (user + sys)/GC线程数。我的机器是 4 核 8 线程，而这里是 6 倍的比例，因为总有一定比例的处理过程是不能并行执行的。

进一步计算和分析可以得知，在 GC 之前，年轻代使用量为 136418K/157248K=86%。堆内存的使用率为 442378K/506816K=87%。稍微估算一下，老年代的使用率为：(442378K-136418K)/(506816K-157248K)=(305960K /349568K)=87%。这里是凑巧了，GC 之前 3 个比例都在 87% 左右。GC 之后呢？年轻代使用量为 17311K ~= 17%，下降了 119107K。堆内存使用量为 360181K ~= 71%，只下降了 82197K。两个下降值相减，就是年轻代提升到老年代的内存量：119107-82197=36910K。那么老年代空间有多大？老年代使用量是多少？正在阅读的同学，请开动脑筋，用这些数字算一下。此次 GC 的内存变化示意图为：

Full GC 日志分析

实际上这次截取的年轻代 GC 日志和 FullGC 日志是紧连着的，我们从间隔时间也能大致看出来，1.067 + 0.02secs ~ 1.091。CMS 的日志是一种完全不同的格式，并且很长，因为 CMS 对老年代进行垃圾收集时每个阶段都会有自己的日志。为了简洁，我们将对这部分日志按照阶段依次介绍。

019-12-22T00:00:31.889-0800: 1.091:[GC (CMS Initial Mark)[1 CMS-initial-mark: 342870K(349568K)]363883K(506816K)，0.0002262 secs][Times: user=0.00 sys=0.00,real=0.00 secs]
2019-12-22T00:00:31.889-0800: 1.091:[CMS-concurrent-mark-start]
2019-12-22T00:00:31.890-0800: 1.092:[CMS-concurrent-mark: 0.001/0.001 secs][Times: user=0.00 sys=0.00,real=0.01 secs]
2019-12-22T00:00:31.891-0800: 1.092:[CMS-concurrent-preclean-start]
2019-12-22T00:00:31.891-0800: 1.093:[CMS-concurrent-preclean: 0.001/0.001 secs][Times: user=0.00 sys=0.00,real=0.00 secs]
2019-12-22T00:00:31.891-0800: 1.093:[CMS-concurrent-abortable-preclean-start]
2019-12-22T00:00:31.891-0800: 1.093:[CMS-concurrent-abortable-preclean: 0.000/0.000 secs][Times: user=0.00 sys=0.00,real=0.00 secs]
2019-12-22T00:00:31.891-0800: 1.093:[GC (CMS Final Remark)[YG occupancy: 26095 K (157248 K)]2019-12-22T00:00:31.891-0800: 1.093:[Rescan (parallel) ，0.0002680 secs]2019-12-22T00:00:31.891-0800: 1.093:[weak refs processing，0.0000230 secs]2019-12-22T00:00:31.891-0800: 1.093:[class unloading，0.0004008 secs]2019-12-22T00:00:31.892-0800: 1.094:[scrub symbol table，0.0006072 secs]2019-12-22T00:00:31.893-0800: 1.095:[scrub string table，0.0001769 secs][1 CMS-remark: 342870K(349568K)]368965K(506816K)，0.0015928 secs][Times: user=0.01 sys=0.00,real=0.00 secs]
2019-12-22T00:00:31.893-0800: 1.095:[CMS-concurrent-sweep-start]
2019-12-22T00:00:31.893-0800: 1.095:[CMS-concurrent-sweep： 0.000/0.000 secs][Times: user=0.00 sys=0.00,real=0.00 secs]
2019-12-22T00:00:31.893-0800: 1.095:[CMS-concurrent-reset-start]
2019-12-22T00:00:31.894-0800: 1.096:[CMS-concurrent-reset: 0.000/0.000 secs][Times: user=0.00 sys=0.00,real=0.00 secs]

阶段 1：Initial Mark（初始标记）

前面章节提到过，这个阶段伴随着 STW 暂停。初始标记的目标是标记所有的根对象，包括 GC ROOT 直接引用的对象，以及被年轻代中所有存活对象所引用的对象。后面这部分也非常重要，因为老年代是独立进行回收的。先看这个阶段的日志：

2019-12-22T00:00:31.889-0800: 1.091:[GC (CMS Initial Mark)[1 CMS-initial-mark: 342870K(349568K)]363883K(506816K), 0.0002262 secs][Times: user=0.00 sys=0.00,real=0.00 secs]
  1. 2019-12-22T00:00:31.889-0800: 1.091:：时间部分就不讲了，参考前面的解读。后面的其他阶段也一样，不再进行重复介绍。
  2. CMS Initial Mark：这个阶段的名称为“Initial Mark”，会标记所有的 GC Root。
  3. [1 CMS-initial-mark: 342870K(349568K)]：这部分数字表示老年代的使用量，以及老年代的空间大小。
  4. 363883K(506816K)，0.0002262 secs：当前堆内存的使用量，以及可用堆的大小、消耗的时间。可以看出这个时间非常短，只有 0.2 毫秒左右，因为要标记的这些 Roo 数量很少。
  5. [Times: user=0.00 sys=0.00,real=0.00 secs]：初始标记事件暂停的时间，可以看到可以忽略不计。

阶段 2：Concurrent Mark（并发标记）

在并发标记阶段，CMS 从前一阶段“Initial Mark”找到的 ROOT 开始算起，遍历老年代并标记所有的存活对象。看看这个阶段的 GC 日志：

2019-12-22T00:00:31.889-0800: 1.091:[CMS-concurrent-mark-start]
2019-12-22T00:00:31.890-0800: 1.092:[CMS-concurrent-mark: 0.001/0.001 secs][Times: user=0.00 sys=0.00,real=0.01 secs]
  1. CMS-concurrent-mark：指明了是 CMS 垃圾收集器所处的阶段为并发标记（“Concurrent Mark”）。
  2. 0.001/0.001 secs：此阶段的持续时间，分别是 GC 线程消耗的时间和实际消耗的时间。
  3. [Times: user=0.00 sys=0.00,real=0.01 secs]：Times 对并发阶段来说这些时间并没多少意义，因为是从并发标记开始时刻计算的，而这段时间应用线程也在执行，所以这个时间只是一个大概的值。

阶段 3：Concurrent Preclean（并发预清理）

此阶段同样是与应用线程并发执行的，不需要停止应用线程。看看并发预清理阶段的 GC 日志：

2019-12-22T00:00:31.891-0800: 1.092:[CMS-concurrent-preclean-start]
2019-12-22T00:00:31.891-0800: 1.093:[CMS-concurrent-preclean: 0.001/0.001 secs][Times: user=0.00 sys=0.00,real=0.00 secs]
  1. CMS-concurrent-preclean：表明这是并发预清理阶段的日志，这个阶段会统计前面的并发标记阶段执行过程中发生了改变的对象。
  2. 0.001/0.001 secs：此阶段的持续时间，分别是 GC 线程运行时间和实际占用的时间。
  3. [Times: user=0.00 sys=0.00,real=0.00 secs]：Times 这部分对并发阶段来说没多少意义，因为是从开始时间计算的，而这段时间内不仅 GC 线程在执行并发预清理，应用线程也在运行。

阶段 4：Concurrent Abortable Preclean（可取消的并发预清理）

此阶段也不停止应用线程，尝试在会触发 STW 的 Final Remark 阶段开始之前，尽可能地多干一些活。本阶段的具体时间取决于多种因素，因为它循环做同样的事情，直到满足某一个退出条件（如迭代次数、有用工作量、消耗的系统时间等等）。看看 GC 日志：

2019-12-22T00:00:31.891-0800: 1.093:[CMS-concurrent-abortable-preclean-start]
2019-12-22T00:00:31.891-0800: 1.093:[CMS-concurrent-abortable-preclean: 0.000/0.000 secs][Times: user=0.00 sys=0.00,real=0.00 secs]
  1. CMS-concurrent-abortable-preclean：指示此阶段的名称：“Concurrent Abortable Preclean”。
  2. 0.000/0.000 secs：此阶段 GC 线程的运行时间和实际占用的时间。从本质上讲，GC 线程试图在执行 STW 暂停之前等待尽可能长的时间。默认条件下，此阶段可以持续最长 5 秒钟的时间。
  3. [Times: user=0.00 sys=0.00,real=0.00 secs]：“Times”这部分对并发阶段来说没多少意义，因为程序在并发阶段中持续运行。

此阶段完成的工作可能对 STW 停顿的时间有较大影响，并且有许多重要的配置选项和失败模式。

阶段 5：Final Remark（最终标记）

最终标记阶段是此次 GC 事件中的第二次（也是最后一次）STW 停顿。本阶段的目标是完成老年代中所有存活对象的标记。因为之前的预清理阶段是并发执行的，有可能 GC 线程跟不上应用程序的修改速度。所以需要一次 STW 暂停来处理各种复杂的情况。通常 CMS 会尝试在年轻代尽可能空的情况下执行 final remark 阶段，以免连续触发多次 STW 事件。

这部分的 GC 日志看起来稍微复杂一些：

2019-12-22T00:00:31.891-0800: 1.093:[GC (CMS Final Remark)[YG occupancy: 26095 K (157248 K)]2019-12-22T00:00:31.891-0800: 1.093:[Rescan (parallel) ，0.0002680 secs]2019-12-22T00:00:31.891-0800: 1.093:[weak refs processing，0.0000230 secs]2019-12-22T00:00:31.891-0800: 1.093:[class unloading，0.0004008 secs]2019-12-22T00:00:31.892-0800: 1.094:[scrub symbol table，0.0006072 secs]2019-12-22T00:00:31.893-0800: 1.095:[scrub string table，0.0001769 secs][1 CMS-remark: 342870K(349568K)]368965K(506816K)，0.0015928 secs][Times: user=0.01 sys=0.00,real=0.00 secs]
  1. CMS Final Remark：这是此阶段的名称，最终标记阶段，会标记老年代中所有的存活对象，包括此前的并发标记过程中创建/修改的引用。
  2. YG occupancy: 26095 K (157248 K)：当前年轻代的使用量和总容量。
  3. [Rescan (parallel) ，0.0002680 secs]：在程序暂停后进行重新扫描（Rescan），以完成存活对象的标记。这部分是并行执行的，消耗的时间为 0.0002680 秒。
  4. weak refs processing，0.0000230 secs：第一个子阶段，处理弱引用的持续时间。
  5. class unloading，0.0004008 secs：第二个子阶段，卸载不使用的类，以及持续时间。
  6. scrub symbol table，0.0006072 secs：第三个子阶段，清理符号表，即持有 class 级别 metadata 的符号表（symbol tables）。
  7. scrub string table，0.0001769 secs：第四个子阶段， 清理内联字符串对应的 string tables。
  8. [1 CMS-remark: 342870K(349568K)]：此阶段完成后老年代的使用量和总容量。
  9. 368965K(506816K)，0.0015928 secs：此阶段完成后，整个堆内存的使用量和总容量。
  10. [Times: user=0.01 sys=0.00,real=0.00 secs]：GC 事件的持续时间。

在这 5 个标记阶段完成后，老年代中的所有存活对象都被标记上了，接下来 JVM 会将所有不使用的对象清除，以回收老年代空间。

阶段 6：Concurrent Sweep（并发清除）

此阶段与应用程序并发执行，不需要 STW 停顿。目的是删除不再使用的对象，并回收他们占用的内存空间。看看这部分的 GC 日志：

2019-12-22T00:00:31.893-0800: 1.095:[CMS-concurrent-sweep-start]
2019-12-22T00:00:31.893-0800: 1.095:[CMS-concurrent-sweep: 0.000/0.000 secs][Times: user=0.00 sys=0.00,real=0.00 secs]
  1. CMS-concurrent-sweep：此阶段的名称，“Concurrent Sweep”，并发清除老年代中所有未被标记的对象、也就是不再使用的对象，以释放内存空间。
  2. 0.000/0.000 secs：此阶段的持续时间和实际占用的时间，这是一个四舍五入值，只精确到小数点后 3 位。
  3. [Times: user=0.00 sys=0.00,real=0.00 secs]：“Times”部分对并发阶段来说没有多少意义，因为是从并发标记开始时计算的，而这段时间内不仅是并发标记线程在执行，程序线程也在运行。

阶段 7：Concurrent Reset（并发重置）

此阶段与应用程序线程并发执行，重置 CMS 算法相关的内部数据结构，下一次触发 GC 时就可以直接使用。对应的日志为：

2019-12-22T00:00:31.893-0800: 1.095:[CMS-concurrent-reset-start]
2019-12-22T00:00:31.894-0800: 1.096:[CMS-concurrent-reset: 0.000/0.000 secs][Times: user=0.00 sys=0.00,real=0.00 secs]
  1. CMS-concurrent-reset：此阶段的名称，“Concurrent Reset”，重置 CMS 算法的内部数据结构，为下一次 GC 循环做准备。
  2. 0.000/0.000 secs：此阶段的持续时间和实际占用的时间
  3. [Times: user=0.00 sys=0.00,real=0.00 secs]：“Times”部分对并发阶段来说没多少意义，因为是从并发标记开始时计算的，而这段时间内不仅 GC 线程在运行，程序也在运行。

那么问题来了，CMS 之后老年代内存使用量是多少呢？很抱歉这里分析不了，只能通过后面的 Minor GC 日志来分析了。例如本次运行，后面的 GC 日志是这样的：

2019-12-22T00:00:31.921-0800: 1.123:[GC (Allocation Failure) 2019-12-22T00:00:31.921-0800: 1.123:[ParNew: 153242K->16777K(157248K), 0.0070050 secs]445134K->335501K(506816K)，0.0070758 secs][Times: user=0.05 sys=0.00,real=0.00 secs]

参照前面年轻代 GC 日志的分析方法，我们推算出来，上面的 CMS Full GC 之后，老年代的使用量应该是：445134K-153242K=291892K，老年代的总容量 506816K-157248K=349568K，所以 Full GC 之后老年代的使用量占比是 291892K/349568K=83%。

这个占比不低。说明什么问题呢？ 一般来说就是分配的内存小了，毕竟我们才指定了 512MB 的最大堆内存。按照惯例，来一张 GC 前后的内存使用情况示意图：

总之，CMS 垃圾收集器在减少停顿时间上做了很多给力的工作，很大一部分 GC 线程是与应用线程并发运行的，不需要暂停应用线程，这样就可以在一般情况下每次暂停的时候较少。当然，CMS 也有一些缺点，其中最大的问题就是老年代的内存碎片问题，在某些情况下 GC 会有不可预测的暂停时间，特别是堆内存较大的情况下。

九、G1日志分析

G1 使用示例：

# 请注意命令行启动时没有换行
java -XX:+UseG1GC
-Xms512m
-Xmx512m
-Xloggc:gc.demo.log
-XX:+PrintGCDetails
-XX:+PrintGCDateStamps
demo.jvm0204.GCLogAnalysis

运行之后，我们看看 G1 的日志长什么样：

Java HotSpot(TM) 64-Bit Server VM (25.162-b12) ......
Memory: 4k page，physical 16777216k(709304k free)CommandLine flags: -XX:InitialHeapSize=536870912-XX:MaxHeapSize=536870912-XX:+PrintGC -XX:+PrintGCDateStamps-XX:+PrintGCDetails -XX:+PrintGCTimeStamps-XX:+UseCompressedClassPointers -XX:+UseCompressedOops-XX:+UseG1GC2019-12-23T01:45:40.605-0800: 0.181:[GC pause (G1 Evacuation Pause) (young)，0.0038577 secs][Parallel Time: 3.1 ms，GC Workers: 8]...... 此处省略多行[Code Root Fixup: 0.0 ms][Code Root Purge: 0.0 ms][Clear CT: 0.2 ms][Other: 0.6 ms]...... 此处省略多行[Eden: 25.0M(25.0M)->0.0B(25.0M)Survivors: 0.0B->4096.0K Heap: 28.2M(512.0M)->9162.7K(512.0M)][Times: user=0.01 sys=0.01，real=0.00 secs]2019-12-23T01:45:40.881-0800: 0.456:[GC pause (G1 Evacuation Pause) (young) (to-space exhausted)，0.0147955 secs][Parallel Time: 12.3 ms，GC Workers: 8]...... 此处省略多行[Eden: 298.0M(298.0M)->0.0B(63.0M)Survivors: 9216.0K->26.0MHeap: 434.1M(512.0M)->344.2M(512.0M)][Times: user=0.02 sys=0.05，real=0.02 secs]2019-12-23T01:45:41.563-0800: 1.139:[GC pause (G1 Evacuation Pause) (mixed)，0.0042371 secs][Parallel Time: 3.7 ms，GC Workers: 8]...... 此处省略多行[Eden: 20.0M(20.0M)->0.0B(34.0M) Survivors: 5120.0K->4096.0K Heap: 393.7M(512.0M)->358.5M(512.0M)][Times: user=0.02 sys=0.00，real=0.00 secs]2019-12-23T01:45:41.568-0800: 1.144: [GC pause (G1 Humongous Allocation) (young) (initial-mark)，0.0012116 secs][Parallel Time: 0.7 ms，GC Workers: 8]...... 此处省略多行[Other: 0.4 ms][Humongous Register: 0.1 ms][Humongous Reclaim: 0.0 ms][Eden: 2048.0K(34.0M)->0.0B(33.0M)Survivors: 4096.0K->1024.0KHeap: 359.5M(512.0M)->359.0M(512.0M)][Times: user=0.01 sys=0.00，real=0.00 secs]
2019-12-23T01:45:41.569-0800: 1.145: [GC concurrent-root-region-scan-start]
2019-12-23T01:45:41.569-0800: 1.145: [GC concurrent-root-region-scan-end，0.0000360 secs]
2019-12-23T01:45:41.569-0800: 1.145: [GC concurrent-mark-start]
2019-12-23T01:45:41.571-0800: 1.146: [GC concurrent-mark-end，0.0015209 secs]
2019-12-23T01:45:41.571-0800: 1.146: [GC remark2019-12-23T01:45:41.571-0800: 1.147: [Finalize Marking，0.0002456 secs]2019-12-23T01:45:41.571-0800: 1.147: [GC ref-proc，0.0000504 secs]2019-12-23T01:45:41.571-0800: 1.147: [Unloading，0.0007297 secs]，0.0021658 secs][Times: user=0.01 sys=0.00，real=0.00 secs]
2019-12-23T01:45:41.573-0800: 1.149: [GC cleanup 366M->366M(512M)，0.0006795 secs][Times: user=0.00 sys=0.00，real=0.00 secs]Heapgarbage-first heap total 524288K，used 381470K [......region size 1024K，12 young (12288K)，1 survivors (1024K)Metaspace used 3331K，capacity 4494K，committed 4864K，reserved 1056768Kclass space used 364K，capacity 386K，committed 512K，reserved 1048576K

以上是摘录的一部分 GC 日志信息。实际运行我们的示例程序1秒钟，可能会生成上千行的 GC 日志。

Evacuation Pause：young（纯年轻代模式转移暂停）

当年轻代空间用满后，应用线程会被暂停，年轻代内存块中的存活对象被拷贝到存活区。如果还没有存活区，则任意选择一部分空闲的内存块作为存活区。拷贝的过程称为转移（Evacuation），这和前面介绍的其他年轻代收集器是一样的工作原理。转移暂停的日志信息很长，为简单起见，我们去除了一些不重要的信息。在并发阶段之后我们会进行详细的讲解。此外，由于日志记录很多，所以并行阶段和“其他”阶段的日志将拆分为多个部分来进行讲解。我们从 GC 日志中抽取部分关键信息：

2019-12-23T01:45:40.605-0800: 0.181:[GC pause (G1 Evacuation Pause) (young)，0.0038577 secs][Parallel Time: 3.1 ms，GC Workers: 8]...... worker 线程的详情，下面单独讲解[Code Root Fixup: 0.0 ms][Code Root Purge: 0.0 ms][Clear CT: 0.2 ms][Other: 0.6 ms]...... 其他琐碎任务，下面单独讲解[Eden: 25.0M(25.0M)->0.0B(25.0M)Survivors: 0.0B->4096.0K Heap: 28.2M(512.0M)->9162.7K(512.0M)][Times: user=0.01 sys=0.01，real=0.00 secs]
  1. [GC pause (G1 Evacuation Pause) (young)，0.0038577 secs]：G1 转移暂停，纯年轻代模式；只清理年轻代空间。这次暂停在 JVM 启动之后 181ms 开始，持续的系统时间为 0.0038577 秒，也就是 3.8ms。
  2. [Parallel Time: 3.1 ms，GC Workers: 8]：表明后面的活动由 8 个 Worker 线程并行执行，消耗时间为 3.1 毫秒（real time）；worker 是一种模式，类似于一个老板指挥多个工人干活。
  3. …...：为阅读方便，省略了部分内容，可以参考前面的日志，下面紧接着也会讲解。
  4. [Code Root Fixup: 0.0 ms]：释放用于管理并行活动的内部数据，一般都接近于零。这个过程是串行执行的。
  5. [Code Root Purge: 0.0 ms]：清理其他部分数据，也是非常快的，如非必要基本上等于零。也是串行执行的过程。
  6. [Other: 0.6 ms]：其他活动消耗的时间，其中大部分是并行执行的。
  7. …：请参考后文。
  8. [Eden: 25.0M(25.0M)->0.0B(25.0M)：暂停之前和暂停之后，Eden 区的使用量/总容量。
  9. Survivors: 0.0B->4096.0K：GC 暂停前后，存活区的使用量。Heap: 28.2M(512.0M)->9162.7K(512.0M)]：暂停前后，整个堆内存的使用量与总容量。
  10. [Times: user=0.01 sys=0.01，real=0.00 secs]：GC 事件的持续时间。

说明：系统时间（wall clock time/elapsed time），是指一段程序从运行到终止，系统时钟走过的时间。一般系统时间都要比 CPU 时间略微长一点。

最繁重的 GC 任务由多个专用的 worker 线程来执行，下面的日志描述了它们的行为：

[Parallel Time: 3.1 ms，GC Workers: 8][GC Worker Start (ms): Min: 180.6，Avg: 180.6，Max: 180.7，Diff: 0.1][Ext Root Scanning (ms): Min: 0.1，Avg: 0.3，Max: 0.6，Diff: 0.4，Sum: 2.1][Update RS (ms): Min: 0.0，Avg: 0.0，Max: 0.0，Diff: 0.0，Sum: 0.0][Processed Buffers: Min: 0，Avg: 0.0，Max: 0，Diff: 0，Sum: 0][Scan RS (ms): Min: 0.0，Avg: 0.0，Max: 0.0，Diff: 0.0，Sum: 0.0][Code Root Scanning (ms): Min: 0.0，Avg: 0.0，Max: 0.1，Diff: 0.1，Sum: 0.1][Object Copy (ms): Min: 2.2，Avg: 2.5，Max: 2.7，Diff: 0.4，Sum: 19.8][Termination (ms): Min: 0.0，Avg: 0.2，Max: 0.4，Diff: 0.4，Sum: 1.5][Termination Attempts: Min: 1，Avg: 1.0，Max: 1，Diff: 0，Sum: 8][GC Worker Other (ms): Min: 0.0，Avg: 0.0，Max: 0.0，Diff: 0.0，Sum: 0.1][GC Worker Total (ms): Min: 2.9，Avg: 3.0，Max: 3.0，Diff: 0.1，Sum: 23.7][GC Worker End (ms): Min: 183.6，Avg: 183.6，Max: 183.6，Diff: 0.0]
  1. [Parallel Time: 3.1 ms，GC Workers: 8]：前面介绍过，这表明下列活动由 8 个线程并行执行，消耗的时间为 3.1 毫秒（real time）。
  2. GC Worker Start (ms)：GC 的 worker 线程开始启动时，相对于 pause 开始时间的毫秒间隔。如果 Min 和 Max 差别很大，则表明本机其他进程所使用的线程数量过多，挤占了 GC 的可用 CPU 时间。
  3. Ext Root Scanning (ms)：用了多长时间来扫描堆外内存（non-heap）的 GC ROOT，如 classloaders、JNI 引用、JVM 系统 ROOT 等。后面显示了运行时间，“Sum”指的是 CPU 时间。
  4. Update RS、Processed Buffers、Scan RS 这三部分也是类似的，RS 是 Remembered Set 的缩写，可以参考前面章节。
  5. Code Root Scanning (ms)：扫描实际代码中的 root 用了多长时间：例如线程栈中的局部变量。
  6. Object Copy (ms)：用了多长时间来拷贝回收集中的存活对象。
  7. Termination (ms)：GC 的 worker 线程用了多长时间来确保自身可以安全地停止，在这段时间内什么也不做，完成后 GC 线程就终止运行了，所以叫终止等待时间。
  8. Termination Attempts：GC 的 worker 线程尝试多少次 try 和 teminate。如果 worker 发现还有一些任务没处理完，则这一次尝试就是失败的，暂时还不能终止。
  9. GC Worker Other (ms)：其他的小任务， 因为时间很短，在 GC 日志将他们归结在一起。
  10. GC Worker Total (ms)：GC 的 worker 线程工作时间总计。
  11. [GC Worker End (ms)：GC 的 worker 线程完成作业时刻，相对于此次 GC 暂停开始时间的毫秒数。通常来说这部分数字应该大致相等，否则就说明有太多的线程被挂起，很可能是因为“[坏邻居效应（noisy neighbor）]( _performance.md)”所导致的。
[Other: 0.6 ms][Choose CSet: 0.0 ms][Ref Proc: 0.3 ms][Ref Enq: 0.0 ms][Redirty Cards: 0.1 ms][Humongous Register: 0.0 ms][Humongous Reclaim: 0.0 ms][Free CSet: 0.0 ms]
  1. [Other: 0.6 ms]：其他活动消耗的时间，其中很多是并行执行的。
  2. Choose CSet：选择 CSet 消耗的时间，CSet 是 Collection Set 的缩写。
  3. [Ref Proc: 0.3 ms]：处理非强引用（non-strong）的时间，进行清理或者决定是否需要清理。
  4. [Ref Enq: 0.0 ms]：用来将剩下的 non-strong 引用排列到合适的 ReferenceQueue 中。
  5. Humongous Register、Humongous Reclaim 大对象相关的部分，后面进行介绍。
  6. [Free CSet: 0.0 ms]：将回收集中被释放的小堆归还所消耗的时间，以便他们能用来分配新的对象。

此次 Young GC 对应的示意图如下所示：

Concurrent Marking（并发标记）

当堆内存的总体使用比例达到一定数值时，就会触发并发标记。这个默认比例是 45%，但也可以通过 JVM 参数 InitiatingHeapOccupancyPercent 来设置。和 CMS 一样，G1 的并发标记也是由多个阶段组成，其中一些阶段是完全并发的，还有一些阶段则会暂停应用线程。

阶段 1：Initial Mark（初始标记）

可以在 Evacuation Pause 日志中的第一行看到（initial-mark）暂停，类似这样：

2019-12-23T01:45:41.568-0800: 1.144:[GC pause (G1 Humongous Allocation) (young) (initial-mark)，0.0012116 secs]

当然，这里引发 GC 的原因是大对象分配，也可能是其他原因，例如：to-space exhausted，或者默认 GC 原因等等。

阶段 2：Root Region Scan（Root 区扫描）

此阶段标记所有从“根区域”可达的存活对象。根区域包括：非空的区域，以及在标记过程中不得不收集的区域。对应的日志：

2019-12-23T01:45:41.569-0800: 1.145:[GC concurrent-root-region-scan-start]
2019-12-23T01:45:41.569-0800: 1.145:[GC concurrent-root-region-scan-end，0.0000360 secs]

阶段 3：Concurrent Mark（并发标记）

对应的日志：

2019-12-23T01:45:41.569-0800: 1.145:[GC concurrent-mark-start]
2019-12-23T01:45:41.571-0800: 1.146:[GC concurrent-mark-end，0.0015209 secs]

阶段 4：Remark（再次标记）

对应的日志：

2019-12-23T01:45:41.571-0800: 1.146:[GC remark2019-12-23T01:45:41.571-0800: 1.147:[Finalize Marking，0.0002456 secs]2019-12-23T01:45:41.571-0800: 1.147:[GC ref-proc，0.0000504 secs]2019-12-23T01:45:41.571-0800: 1.147:[Unloading，0.0007297 secs]，0.0021658 secs][Times: user=0.01 sys=0.00，real=0.00 secs]

阶段 5：Cleanup（清理）

最后这个清理阶段为即将到来的转移阶段做准备，统计小堆块中所有存活的对象，并将小堆块进行排序，以提升 GC 的效率。此阶段也为下一次标记执行必需的所有整理工作（house-keeping activities）——维护并发标记的内部状态。

要提醒的是，所有不包含存活对象的小堆块在此阶段都被回收了。有一部分任务是并发的：例如空堆区的回收，还有大部分的存活率计算，此阶段也需要一个短暂的 STW 暂停，才能不受应用线程的影响并完成作业。

这种 STW 停顿的对应的日志如下：

2019-12-23T01:45:41.573-0800: 1.149:[GC cleanup 366M->366M(512M)，0.0006795 secs][Times: user=0.00 sys=0.00，real=0.00 secs]

如果发现某些小堆块中只包含垃圾，则日志格式可能会有点不同，如：

2019-12-23T21:26:42.411-0800: 0.689:[GC cleanup 247M->242M(512M)，0.0005349 secs][Times: user=0.00 sys=0.00，real=0.00 secs]
2019-12-23T21:26:42.412-0800: 0.689:[GC concurrent-cleanup-start]
2019-12-23T21:26:42.412-0800: 0.689:[GC concurrent-cleanup-end，0.0000134 secs]

如果你在执行示例程序之后没有看到对应的 GC 日志，可以多跑几遍试试。毕竟 GC 和内存分配属于运行时动态的，每次运行都可能有些不同。

标记周期一般只在碰到 region 中一个存活对象都没有的时候，才会顺手处理一把，大多数情况下都不释放内存。示意图如下所示：

Evacuation Pause（mixed）（转移暂停：混合模式）

并发标记完成之后，G1 将执行一次混合收集（mixed collection），不只清理年轻代，还将一部分老年代区域也加入到 collection set 中。混合模式的转移暂停（Evacuation Pause）不一定紧跟并发标记阶段。在并发标记与混合转移暂停之间，很可能会存在多次 Young 模式的转移暂停。

“混合模式”就是指这次 GC 事件混合着处理年轻代和老年代的 region。这也是 G1 等增量垃圾收集器的特色。

而 ZGC 等最新的垃圾收集器则不使用分代算法。当然，以后可能还是会实现分代的，毕竟分代之后性能还会有提升。

混合模式下的日志，和纯年轻代模式相比，可以发现一些有趣的地方：

2019-12-23T21:26:42.383-0800: 0.661:[GC pause (G1 Evacuation Pause) (mixed)，0.0029192 secs][Parallel Time: 2.2 ms，GC Workers: 8]......[Update RS (ms): Min: 0.1，Avg: 0.2，Max: 0.3，Diff: 0.2，Sum: 1.4][Processed Buffers: Min: 0，Avg: 1.8，Max: 3，Diff: 3，Sum: 14][Scan RS (ms): Min: 0.0，Avg: 0.0，Max: 0.0，Diff: 0.0，Sum: 0.1]......[Clear CT: 0.4 ms][Other: 0.4 ms][Choose CSet: 0.0 ms][Ref Proc: 0.1 ms][Ref Enq: 0.0 ms][Redirty Cards: 0.1 ms][Free CSet: 0.1 ms][Eden: 21.0M(21.0M)->0.0B(21.0M)Survivors: 4096.0K->4096.0KHeap: 337.7M(512.0M)->274.3M(512.0M)][Times: user=0.01 sys=0.00，real=0.00 secs]
  1. [Update RS (ms)：因为 Remembered Sets 是并发处理的，必须确保在实际的垃圾收集之前，缓冲区中的 card 得到处理。如果 card 数量很多，则 GC 并发线程的负载可能就会很高。可能的原因是修改的字段过多，或者 CPU 资源受限。
  2. Processed Buffers：各个 worker 线程处理了多少个本地缓冲区（local buffer）。
  3. Scan RS (ms)：用了多长时间扫描来自 RSet 的引用。
  4. [Clear CT: 0.4 ms]：清理 card table 中 cards 的时间。清理工作只是简单地删除“脏”状态，此状态用来标识一个字段是否被更新的，供 Remembered Sets 使用。
  5. [Redirty Cards: 0.1 ms]：将 card table 中适当的位置标记为 dirty 所花费的时间。“适当的位置”是由 GC 本身执行的堆内存改变所决定的，例如引用排队等。

Full GC（Allocation Failure）

G1 是一款自适应的增量垃圾收集器。一般来说，只有在内存严重不足的情况下才会发生 Full GC。比如堆空间不足或者 to-space 空间不足。在前面的示例程序基础上，增加缓存对象的数量，即可模拟 Full GC。示例日志如下：

2020-03-02T18:44:17.814-0800: 2.826:[Full GC (Allocation Failure) 403M->401M(512M)，0.0046647 secs][Eden: 0.0B(25.0M)->0.0B(25.0M)Survivors: 0.0B->0.0BHeap: 403.6M(512.0M)->401.5M(512.0M)]，[Metaspace: 2789K->2789K(1056768K)][Times: user=0.00 sys=0.00，real=0.00 secs]

因为我们的堆内存空间很小，存活对象的数量也不多，所以这里看到的 Full GC 暂停时间很短。

此次 Full GC 的示意图如下所示：

在堆内存较大的情况下（8G+），如果 G1 发生了 Full GC，暂停时间可能会退化，达到几十秒甚至更多。如下面这张图片所示：

从其中的 OldGen 部分可以看到，118 次 Full GC 消耗了 31 分钟，平均每次达到 20 秒，按图像比例可粗略得知，吞吐率不足 30%。

这张图片所表示的场景是在压测 Flink 按时间窗口进行聚合计算时发生的，主要原因是对象太多，堆内存空间不足而导致的，修改对象类型为原生数据类型之后问题得到缓解，加大堆内存空间，满足批处理/流计算的需求之后 GC 问题不再复现。

发生持续时间很长的 Full GC 暂停时，就需要我们进行排查和分析，确定是否需要修改 GC 配置，或者增加内存，还是需要修改程序的业务逻辑。关于 G1 的调优，我们在后面的调优部分再进行介绍。

十、GCEasy 工具

我们发现 GC 日志量很大，人工分析太消耗精力了。由于各种 GC 算法的复杂性，它们的日志格式互相之间不太兼容。有没有什么工具来减少我们的重复劳动呢? 这种轮子肯定是有现成的。

GCEasy 工具由 Tier1app 公司 开发和支持，这家公司主要提供3款分析工具：

  • GCEasy，访问地址：Universal JVM GC analyzer - Java Garbage collection log analysis made easy，是一款在线的 GC 日志分析工具，支持各种版本的 GC 日志格式。
  • FastThread，官网地址：Smart Java thread dump analyzer - thread dump analysis in seconds，线程分析工具，后面我们专门有一节课程会进行介绍。
  • HeapHero，官网地址：Brilliant Graphs, metrics and heap dump analysisanti-patterns reported，顾名思义，这是一款 Heap Dump 分析工具。

博文参考

更多推荐

JVM——GC日志实战分析

本文发布于:2024-02-28 11:46:39，感谢您对本站的认可！
本文链接:https://www.elefans.com/category/jswz/34/1769241.html
版权声明:本站内容均来自互联网，仅供演示用，请勿用于商业和其他非法用途。如果侵犯了您的权益请与我们联系，我们将在24小时内删除。
本文标签：实战   日志   JVM   GC

发布评论

评论列表 （有 0 条评论）

最近发表

草根站长

>www.elefans.com

编程频道|电子爱好者 - 技术资讯及电子产品介绍！

热门文章

标签列表