vlambda博客
学习文章列表

手撕 JVM 垃圾收集日志（长文一篇）

下图是本篇的写作大纲，将从以下四个方面介绍怎么样处理 JVM 日志。

有准备才能不慌

想要分析日志，首先你得有日志呀，对不对。凡是未雨绸蒙总是没错的。所谓有日志的意思，你要把 JVM 参数配置好，日志格式、日志存储位置等参数，当然了，除了日志相关参数外，其他的一些必要参数最好也配置上，比如 HeapDump 。

我相信大部分成熟的项目都会配置 JVM 参数。但是还是有一些小项目真的会忽略。以至于 JVM 崩溃的时候不方便查找问题原因而追悔莫及。比如下面这位同学（纯属虚构），虽然对话是虚构，但是是真的有不配置参数的。

手撕 JVM 垃圾收集日志（长文一篇）

要配置，有防备，不后悔；不配置，不准备，会追悔。

以上可以说是配置 JVM 日志以及 dump 现场最基本的配置了。这里只介绍关于日志的参数，其他的参数可以读一下 

加了以上配置的 JVM 就像是一台装有黑匣子的飞机。

一个重要概念

并发(Concurrent)和并行(Parallel)在 JVM 垃圾收集过程中的定义有很多同学搞不清楚。所以每次读到这两个概念的时候都一头雾水。 并发(Concurrent)：指垃圾收集线程和用户线程可以同时进行。也就是说 JVM 在进行垃圾收集的时候，用户还是可以正常的使用应用系统提供的服务。(当然了，并没有一种完全并发的垃圾收集器，只是说在垃圾收集的大部分阶段是并发的) 并行(Parallel)：指垃圾收集器是多线程工作的，比方说有4个线程同时进行垃圾收集的工作，但是在收集的过程中，用户线程是被挂起的。也就是在进行并行收集的时候，用户无法正常使用应用系统提供的服务。

分析背景

本篇的全部内容都基于 JDK 8 Hotspot JVM，分别从 ParallelGC 、CMS、G1 三种常用的垃圾收集器来分析。可以通过下图查看三种垃圾收集器的对应关系，分别对应图中标示的 1、2、3。

手撕 JVM 垃圾收集日志（长文一篇）

为了方便日志分析，我设置了一下简单的 JVM 作为基础参数，其中年轻代 10M，老年代 10M，堆大小 20M。

简单日志格式

通过参数 -verbose:gc 或者 -XX:+PrintGC 可以让 JVM 开启简单日志格式，对于这几种垃圾收集期，简单日志的格式都是一致的。简单日志内容很少，只有GC类型(标示是 Minor GC 还是 Full GC)、GC 原因、堆收集前和收集后大小、堆的总大小以及收集耗时。

下面是简单日志配置下的几条收集日志，包括正常的空间分配失败引起的收集、System.gc() 触发的垃圾收集、以及执行 jmap -histo:live pid 命令执行的垃圾收集。

下图说明了一条简单格式的垃圾收集日志各个字段的含义。

手撕 JVM 垃圾收集日志（长文一篇）

在实际的生产环境中，只用简单格式的 JVM 日志意义不大，得到的有用信息不多，也就是知道垃圾收集次数、收集耗时以及堆的使用量，对于排查分析问题的帮助不是很大，所以，一般都会配置更加详细的日志格式。

详细日志格式

使用 -XX:+PrintGCDetails和-XX:+PrintGCDateStamps 这两个参数可以打印详细的垃圾收集日志和垃圾收集的时间戳。当然了，除了这两个之外，还有一些更具体的参数，比如收集前后打印堆使用信息的 -XX:+PrintHeapAtGC参数等等。

当然了，参数配置的越多，打印的信息越是详细，对于排查问题越有帮助，就是内容就会变得很多，肉眼看起来会比较抓狂。

Parallel Scavenge 收集器

在 JDK 8 中，如果不指定垃圾收集器，默认是使用参数 -XX:+UseParallelGC 的，也就是新生代使用 Parallel Scavenge，老年代配合使用的是 Serial Old。

Parallel Scavenge是一款并行的、高吞吐量的垃圾收集器，采用复制算法。适用于追求高效率的、对即时响应要求不高的系统。

要了解清楚 GC 日志各部分的含义，就要了解 JVM 内存模型以及垃圾收集器对于内存的规划和管理情况，老样子，还是通过图来看一下比较清楚。JDK 8 支持的除 G1 外的垃圾收集器，都适用此图，包括下面要介绍的 CMS。

手撕 JVM 垃圾收集日志（长文一篇）

垃圾收集的部分即是上图中的「方法区」和 「堆」两部分。收集日志也基本上是描述这两部分的大小和变化情况。

在上面的背景介绍中给出了本次测试所用的参数。年轻代 10M ，老年代 10M，Metaspace 区 6M。下图是堆空间内存分布图，年轻代分为 Eden区和 S0、S1 两个区，SurvivorRatio为8，这也是默认值，表示新生代 Eden 占年轻代总大小的 80%，也就是 10*80%=8M，而 S0、S1 各占10%，也就是 1M。

手撕 JVM 垃圾收集日志（长文一篇）

好了，基于上面的基础认识。开始分析垃圾收集日志，以下是两条日志，第一条是一次 Minor GC，第二条是 Full GC。

为了更清楚的说明各个部分的含义，我居然又画了一张图（PS:画个图真是不容易），看一下各部分代表的含义。

上图标注的是一条 Full GC 日志，Full GC 同时收集了年轻代、老年代以及 metaspace 区。Full GC 日志包含了 Minor GC 的内容，那我们就直接分析 Full GC 了。

时间戳：日志以时间戳作为开端，表示此次垃圾收集发生的时间，由 -XX:+PrintGCDateStamps 参数决定是否开启。

收集内容主体：

沿着日志顺序往后看，Full GC (System.gc())，收集类型(是 Full GC 还是 Minor GC) ，括号里跟着发生此次垃圾收集的原因。

再后面是年轻代、老年代、Metaspace 区详细的收集情况。

[PSYoungGen: 656K->0K(9216K)]，翻译为 「年轻代：年轻代收集前内存使用量->年轻代垃圾收集后内存使用量（年轻代可用内存总大小）」，垃圾收集前年轻代已使用 656K，垃圾收集后已使用 0K，说明被回收了 656K，总可用大小为 9216K(9M)。诶，不对呀？怎么是 9M 呢，年轻代不是分了 10 M 吗。因为可用内存和总内存不能划等号，S0 和 S1 只能有一块被算进可用内存，所以可用内存为 Eden + S0/S1=9M。

[ParOldGen: 16K->570K(10240K)] 672K->570K(19456K)，翻译为 「[老年代：老年代收集前内存使用量->老年代垃圾收集后内存使用量（老年代可用内存总大小）] 堆空间（包括年轻代和老年代）垃圾收集前内存使用量->堆空间垃圾收集后内存使用量（堆空间总可用大小）」。

垃圾收集前老年使用 16K，收集后呢，竟然变大了，确定没有看错吗。是的，没有。这是因为年轻代的对象有一些进入了老年代导致的。老年代 16K 变成了 570K，说明有 554K 是年轻代晋升而来的。而内存总大小由 672K 减少到了 570K，说明有102K的内存真正的被清理了。

[Metaspace: 3910K->3910K(1056768K)]翻译为元空间回收前大小为 3910K，回收后大小为3910K，总可用大小为 1056768K。我们不是设置的 6M 吗，怎么这么大，没起作用吗。实际上这个值是 CompressedClassSpaceSize +(2*InitialBootClassLoaderMetaspaceSize) 的大小，我们只设置了 MaxMetaspaceSize ，并没有设置这两个参数。使用如下命令可以看到这两个值的默认大小

单位是 byte，CompressedClassSpaceSize 的值是 1048576K(其实就是1G，默认值)，InitialBootClassLoaderMetaspaceSize的值是 4M，用上面的公式计算，正好是 1056768K(1032M)

耗时统计

[Times: user=0.02 sys=0.00, real=0.01 secs]

user=0.02 表示执行用户态代码的耗时，这里也就是 GC 线程消耗的 CPU 时间。如果是多线程收集器，这个值会高于 real 时间。

sys=0.00 表示执行内核态代码的耗时。

real=0.01 表示应用停顿时长，多线程垃圾收集情况下，此数值应该接近(user + sys) / GCThreads（收集线程数），即单核上的平均停顿时间。

CMS 收集器

CMS 是一款老年代垃圾收集器，年轻代使用 ParNew 与之配合使用。它是一款并发、低停顿的垃圾收集器。适用于要求低延迟、即时响应的应用系统。

CMS 规划的内存模型和上面 Parallel Scavenge 的是一致的，可以参考上面的内存分布图。

CMS 采用标记-清除算法，算法过程比较复杂，分为以下几个步骤：

  • 初始标记（CMS initial mark），会导致 stop the world；

  • 并发标记（CMS concurrent mark），与用户线程同时运行；

  • 预清理（CMS-concurrent-preclean），与用户线程同时运行；

  • 可被终止的预清理（CMS-concurrent-abortable-preclean） 与用户线程同时运行；

  • 重新标记（CMS remark），会导致 stop the world；

  • 并发清除（CMS concurrent sweep），与用户线程同时运行；

  • 并发重置状态等待下次CMS的触发(CMS-concurrent-reset)，与用户线程同时运行；

只有初始标记和重新标记这两个步骤会导致 STW，但是这两个步骤耗时很短，其他步骤可以与用户线程同时运行，所以用户几乎感觉不到 JVM 停顿。

使用参数 -XX:+UseConcMarkSweepGC可启用 CMS 垃圾收集器。更详细的参数如下：

使用了-XX:+ExplicitGCInvokesConcurrentAndUnloadsClasses或-XX:+ExplicitGCInvokesConcurrent参数，在进行 Full GC 的时候，比如执行 System.gc() 操作，会触发 CMS GC，以此来提高 GC 效率。

以下是启用 CMS 后摘的一段 GC 日志，由于内容过长，下面我就直接在日志上做注释了。

以上就是对 CMS 垃圾收集器产生日志的分析，因为过程复杂，所以产生的日志内容也比较多。

G1 收集器

G1 收集器是在 JDK 7 版本中就已经正式推出，并且作为 JDK 9 默认的垃圾收集器。

Parallel Scavenge：我追求高吞吐量，现在社会什么最重要，效率呀，有没有。

CMS：效率固然重要，极致的用户体验才是王道啊，不能让用户等啊，不能等啊，低停顿、即时响应是我毕生追求。

G1（一脸不屑）：有句话不只当讲不当讲，首先声明没有恶意，我想说，在座的各位都是垃圾。上面两位说的，我全都有，是的，全都有。(ps：结果被打)

以上纯属开个玩笑，只是为了说明 G1 在满足了低停顿的同时也保证了高吞吐量，适用于多核处理器、大内存容量的服务端系统。

G1 是 CMS 的替代版本，具有如下特点：

  • 横跨年轻代和老年代，不需要其他收集器配合；

  • 并发收集器，可以与用户线程并发执行；

  • 会压缩内存碎片；

  • 可预测的停顿时间与高吞吐量；

与其他的垃圾收集器不同，G1 对堆内存做了不一样的规划，虽然还是使用分代策略，分为老年代、年轻代，年轻代又分为 Eden、Survivior 区，但是只是逻辑划分，物理上并不连续。它是将堆内存分为一系列大小在1M-32M 不等的 Region 区，通过下方的图可以直观的看出效果。

G1 垃圾收集包括年轻代收集和老年代收集两部分。年轻代比较简单，收集器如果检测到存活区对象存活时间达到阈值，就会将这些存活对象转移到新的 Survivor 区或老年代，此过程会导致 stop the world。老年代的收集就比较复杂了，包括如下几个阶段：

  • 初始标记阶段(Initial Marking Phase)，会导致 stop the wrold;

  • 根区域扫描（Root Region Scan），与应用程序并发执行；

  • 根区域扫描（Root Region Scan），与应用程序并发执行；

  • 并发标记（Concurrent Marking），与应用程序并发执行；

  • 最终标记（Remark），会导致 stop the wrold;

  • 复制/清除（Copying/Cleanup），会导致 stop the wrold;

开启 G1 收集器的参数如下：

使用 G1 收集器时，一般不设置年轻代的大小。

以下是一次 G1 收集的日志，简单的分析直接写到下面的日志内了。

其他工具

大多数时候靠肉眼分析日志是很困难的，借助一些分析工具是必不可少的。

在线日志分析网站：https://gceasy.io/ 在线 JVM 参数生成：https://opts.console.perfma.com/result/generate/JlKEV

写文不易，点个在看支持一下

还可以读：

 

推荐阅读

[5.05] 暗喻幻想港中35周年限定版1.03+DLC+金手指+王中王存档 [5.05] 暗喻幻想港中35周年限定版1.03+DLC+金手指+王中王存档
#我与Java虚拟机的故事#连载07：我放弃了对JVM的进一步学习 #我与Java虚拟机的故事#连载07：我放弃了对JVM的进一步学习

相关文章