JVM - 一篇带你读懂 Java GC 日志（附 GC 耗时讲解）

Posted 2022-05-28 放羊的牧码

简介

每一种回收器的日志格式都是由其自身的实现决定的，换而言之，每种回收器的日志格式都可以不一样。但虚拟机设计者为了方便用户阅读，将各个回收器的日志都维持一定的共性。本文简单介绍下这些共性，一目了然，一图胜千言（Java GC 日志可以通过 +PrintGCDetails 开启）

配置

• ParallelGC

详解

• YoungGC 日志解释

• FullGC 日志解释

附加

• 应该上面的解释大家大部分都好理解，但是我第一次看的时候，发现怎么有各种耗时时间，那他们分别的意义又代表什么呢？在我们开始分析 GC 日志的时候，会遇到两个问题

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

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

在 GC 日志文件中，每个 GC 事件有三种类型的时间

• user：进程执行用户态代码（核心之外）所使用的时间。这是执行此进程所使用的实际 CPU 时间，其他进程和此进程阻塞的时间并不包括在内。在垃圾收集的情况下，表示 GC 线程执行所使用的 CPU 总时间；简单粗暴理解就是每个线程耗时的累计总和

• sys：进程在内核态消耗的 CPU 时间，即在内核执行系统调用或等待系统事件所使用的 CPU 时间

• real：程序从开始到结束所用的时钟时间。这个时间包括其他进程使用的时间片和进程阻塞的时间（比如等待 I/O 完成）；简单粗暴理解就是多个线程中，取决于耗时最长的那个线程

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

Ps2：YGC 实际耗时 是 YGC 耗时 的四舍五入后的结果，FGC 同理可得

案例

[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 停顿时间时，可以参考这两个时间