G1 GC的日志结构及user、sys 和 real 三者之间有什么不同

LeslieMhb

已于 2024-07-13 18:47:21 修改

阅读量908

点赞数 35

文章标签： jvm 容器 java

于 2024-07-13 18:28:58 首次发布

本文链接：https://blog.csdn.net/qq_40776617/article/details/140401741

版权

前言

G1，Java8可选，Java9已默认的垃圾收集器，G1 垃圾收集器的关键特性之一是能够在不牺牲吞吐量的同时，限制 GC 暂停时间(即可以设置所需的最大停顿时间)。

调优 JVM 大小和排查问题的情况下，须理解 G1 GC 的日志格式。由于 G1 GC 日志中有许多与子任务相关的信息，因此为了更好地理解和利用这些信息，推荐 GC 日志分析工具：http://gceasy.io/。作者在2月份的文章为了记录P98导致系统崩了？_监控数据 p98-CSDN博客中分析了大量的GC日志，也用到了http://gceasy.io/这个工具网站，在几万行的日志中可以更快帮忙分析出关键的几个指标。

如何生成详细的GC log？

需要在TOMCAT_JAVA_OPTS参数中加入：-XX:+PrintGCDetails -XX:+PrintGCDateStamps

Minor GC（YGC）日志

Minor GC时，产生的GC 日志文件内容：

2024-07-10T15:04:37.929+0800: 20197.284

表示 GC 发生时间，其中20197.284 表示 Java 进程启动 20197284ms后发生 GC。

GC pause (G1 Evacuation Pause)

疏散停顿（Evacuation Pause）：将存活对象从一个区域（young or young + old）拷贝到另一个区域的阶段。

(young)

这是个 YGC 事件。

GC Workers: 4

表示 GC 的工作线程是 4 个。

[Eden: 2016.0M(2016.0M)->0.0B(2016.0M) Survivors: 32.0M->32.0M Heap: 2076.8M(4096.0M)->60.0M(4096.0M)]

显示堆的大小变化：

Eden: 2016.0M(2016.0M)->0.0B(2016.0M)

Eden空间是2016.0M，并且2016.0M空间全被占用。在GC后，年轻代（young generation）空间下降到0，Eden空间增长到2016.0M，但是没有提交。因为要求，额外的空间被添加给Eden。

Survivors: 0.0B->64.0M

GC 前，幸存者空间是 0 字节，但GC 后，幸存者空间增长到64.0M，表明对象从年轻代（Young Generation）提升到幸存者空间（Survivor space）。

Heap: 2048.0M(4096.0M)->62.3M(4096.0M)

堆的大小是4096.0M，被占用2048.0M，GC 后，堆占用率降至62.3M，即（2048.0M – 62.3M）的对象被垃圾回收了，堆大小仍是4096.0M。

Times: user=0.12 sys=0.04, real=0.08 secs

real 表示 GC 总共花 0.08s。

这里出现了3个时间参数： user=0.12 sys=0.04, real=0.08 secs，第一次观察gc日志时作者也很疑惑到底有什么区别，前辈告诉我暂时先观察real就行。文章最后会介绍这三个参数的区别以及到底应该关注哪一个参数。

Full GC 日志

Full GC 时，产生的GC日志文件内容：

2015-09-14T12:35:27.263-0700: 183.216

2015-09-14T12:35:27.263-0700 表示 GC 发生的时间
183.216 表示 Java 进程启动 183 秒后发生了 GC.

Full GC (Allocation Failure)

Full GC 事件，触发的原因是因为空间分配失败（allocation failure），当堆中有很多碎片时，在老年代进行直接内存分配也许会失败，即使有许多空闲空间，这通常会导致分配失败。

[Eden: 3072.0K(194.0M)->0.0B(201.0M) Survivors: 0.0B->0.0B Heap: 3727.1M(4022.0M)->3612.0M(4022.0M)], [Metaspace: 2776K->2776K(1056768K)]

堆的大小变化，由于这是 Full GC 事件:

Eden: 3072.0K(194.0M)->0.0B(201.0M)

表示伊甸园空间（Eden space）是194mb，被占用3072kb。在 GC 发生之后，年轻代（young generation）下降到0。伊甸园空间增长到201mb，但是没有提交。因为要求，额外的空间被添加给伊甸园。

Survivors: 0.0B->0.0B

表示 GC 发生前后，幸存者空间是 0kb。

Heap: 3727.1M(4022.0M)->3612.0M(4022.0M)

表示堆的大小是 4022mb，其中 3727.1mb 空间未被占用。在 GC 发生之后，堆占用率降至 3612mb，115.1mb (即3727.1 – 3612) 的对象被垃圾回收了，堆的大小仍然是 4022mb。

Metaspace: 2776K->2776K(1056768K)

表示在 GC 发生前后，它被占用的空间大小是 2776k。基本上，意味着在这个阶段 metaspace 空间占用率是保持一致的，metaspace 的总大小是 1056768k。

Times: user=19.08, sys=0.01, real=9.74 secs

real 表示 GC 总共花了 9.74 秒，这个停顿时间很长。

`user`、`sys` 和 `real` 三者之间有什么不同？

前面提到了：

Times: user=0.12 sys=0.04, real=0.08 secs

那么在我们开始分析 GC 日志的时候，会遇到两个问题：

1、user、sys 和 real 三者之间有什么不同？

2、我们该使用哪一个时间来分析日志？

linux命令执行时间

在弄清楚 GC 时间之前，我们先花几分钟来看看linux 的 time 命令。以下是使用该命令的一个示例：

注意这里显示出了 real、user 和 sys 三个时间，这些时间与我们在 GC 日志里看到的大致相同。

real —— 程序从开始到结束所用的时钟时间。这个时间包括其他进程使用的时间片和进程阻塞的时间（比如等待 I/O 完成）。
user —— 进程执行用户态代码（核心之外）所使用的时间。这是执行此进程所使用的实际 CPU 时间，其他进程和此进程阻塞的时间并不包括在内。在垃圾收集的情况下，表示 GC 线程执行所使用的 CPU 总时间。
sys —— 进程在内核态消耗的 CPU 时间，即在内核执行系统调用或等待系统事件所使用的 CPU 时间。

user + sys 时间告诉我们程序执行实际使用的 CPU 时间。注意这里指所有的 CPU，因此如果在进程里有多个线程的话，这个时间可能会超过 real 所表示的时钟时间。

Java GC 时间

上面我们解释了三个时间的概念，接下来我们用一些例子来更好地说明这些概念：

例1：

[Times: user=11.53 sys=1.38, real=1.03 secs]

在这个例子中，user + sys 时间的和比 real 时间要大，这主要是因为日志时间是从 JVM 中获得的，而这个 JVM 在多核的处理器上被配置了多个 GC 线程，由于多个线程并行地执行 GC，因此整个 GC 工作被这些线程共享，最终导致实际的时钟时间（real）小于总的 CPU 时间（user + sys）。

[Times: user=0.09 sys=0.00, real=0.09 secs]

上面的例子中的 GC 时间是从 Serial 垃圾收集器（串行垃圾收集器）中获得的。由于 Serial 垃圾收集器是使用单线程进行垃圾收集的，因此 real 时间等于 user 和 sys 时间之和。

在做性能优化时，我们一般采用 real 时间来优化程序。因为最终用户只关心点击页面发出请求到页面上展示出内容所花的时间，也就是响应时间，而不关心你到底使用了多少个 GC 线程或者处理器。但并不是说 sys 和 user 两个时间不重要，当我们想通过增加 GC 线程或者 CPU 数量来减少 GC 停顿时间时，可以参考这两个时间。

总结

本文主要是介绍了G1 GC日志结构，作者在第一次观察gc日志时只能一行一行对着GC过程分析日志，但是能看懂日志也只是初步入门，还是得靠日常工作中的经验积累。本文主要参考了文章末尾的参考文章的一些观点与看法，简单介绍了G1的日志结构以及user、sys 和 real 三者之间区别，感兴趣的可以点开原文阅读。

参考：