手撕 JVM 垃圾收集日志

程序员文章站 2022-12-21 14:11:15

下图是本篇的写作大纲，将从以下四个方面介绍怎么样处理 JVM 日志。有准备才能不慌想要分析日志，首先你得有日志呀，对不对。凡是未雨绸蒙总是没错的。所谓有日志的意思，你要把 JVM 参数配置好，日志格式、日志存储位置等参数，当然了，除了日志相关参数外，其他的一些必要参数最好也配置上，比如 Heap ......

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

有准备才能不慌

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

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

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

-xx:+printgcdetails
-xx:+printgcdatestamps
-xloggc:/users/fengzheng/jvmlog/gc.log
-xx:+heapdumponoutofmemoryerror
-xx:heapdumppath=/users/fengzheng/jvmlog

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

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

一个重要概念

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

分析背景

本篇的全部内容都基于 jdk 8 hotspot jvm，分别从 parallelgc 、cms、g1 三种常用的垃圾收集器来分析。可以通过下图查看三种垃圾收集器的对应关系，分别对应图中标示的 1、2、3。
手撕 JVM 垃圾收集日志

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

-xms20m
-xmx20m
-xmn10m
-xx:survivorratio=8
-xx:metaspacesize=6m
-xx:maxmetaspacesize=6m
-xx:+heapdumponoutofmemoryerror
-xx:heapdumppath=/users/fengzheng/jvmlog

简单日志格式

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

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

# minor gc 新生代 gc
[gc (allocation failure)  7164k->704k(19456k), 0.0017002 secs]

# system.gc() 触发 full gc
[gc (system.gc())  4157k->648k(19456k), 0.0019522 secs]
[full gc (system.gc())  648k->609k(19456k), 0.0099904 secs]

# jmap -histo:live 触发 full gc
[gc (heap inspection initiated gc)  938k->737k(19456k), 0.0009119 secs]
[full gc (heap inspection initiated gc)  737k->573k(19456k), 0.0070892 secs]

下图说明了一条简单格式的垃圾收集日志各个字段的含义。
手撕 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。

2019-12-03t16:20:47.980-0800: [gc (system.gc()) [psyounggen: 4068k->656k(9216k)] 4076k->672k(19456k), 0.0016106 secs] [times: user=0.00 sys=0.00, real=0.00 secs] 
2019-12-03t16:20:47.982-0800: [full gc (system.gc()) 
            [psyounggen: 656k->0k(9216k)],
        [paroldgen: 16k->570k(10240k)] 672k->570k(19456k), 
        [metaspace: 3910k->3910k(1056768k)],
 0.0110117 secs] 
 [times: user=0.02 sys=0.00, real=0.01 secs]

为了更清楚的说明各个部分的含义，我居然又画了一张图（ps:画个图真是不容易），看一下各部分代表的含义。
手撕 JVM 垃圾收集日志

[^]: 红色线框描述各个部分的含义

上图标注的是一条 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 ，并没有设置这两个参数。使用如下命令可以看到这两个值的默认大小

jinfo -flag compressedclassspacesize 75867
-xx:compressedclassspacesize=1073741824
jinfo -flag initialbootclassloadermetaspacesize 75867
-xx:initialbootclassloadermetaspacesize=4194304

单位是 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:+useconcmarksweepgc
-xx:cmsinitiatingoccupancyfraction=70
-xx:+explicitgcinvokesconcurrentandunloadsclasses
-xx:+cmsclassunloadingenabled
-xx:+parallelrefprocenabled
# 在重新标记之前对年轻代做一次minor gc
-xx:+cmsscavengebeforeremark

使用了-xx:+explicitgcinvokesconcurrentandunloadsclasses或-xx:+explicitgcinvokesconcurrent参数，在进行 full gc 的时候，比如执行 system.gc() 操作，会触发 cms gc，以此来提高 gc 效率。

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

# system.gc() 触发一次 full gc
# -xx:+explicitgcinvokesconcurrentandunloadsclasses 参数
# 导致full gc 以 cms gc 方式执行
# 先由 parnew 收集器回收年轻代
2019-12-03t16:43:03.179-0800: [gc (system.gc()) 2019-12-03t16:43:03.179-0800: [parnew: 3988k->267k(9216k), 0.0091869 secs] 3988k->919k(19456k), 0.0092257 secs] [times: user=0.02 sys=0.00, real=0.01 secs] 

# 初始标记阶段，标记那些直接被 gc root 引用或者被年轻代存活对象所引用的所有对象
# 老年代当前使用 651k
# 老年代可用大小 10240k=10m
# 当前堆内存使用量 919k
# 当前堆可用内存 19456k=19m
# “1 cms-initial-mark” 这里的 1 表示老生代
2019-12-03t16:43:03.189-0800: [gc (cms initial mark) [1 cms-initial-mark: 651k(10240k)] 919k(19456k), 0.0002156 secs] [times: user=0.00 sys=0.00, real=0.00 secs] 

# 并发标记开始
# 标记所有存活的对象，它会根据上个阶段找到的 gc roots 遍历查找
2019-12-03t16:43:03.189-0800: [cms-concurrent-mark-start]

# 并发标记阶段耗时统计
2019-12-03t16:43:03.190-0800: [cms-concurrent-mark: 0.001/0.001 secs] [times: user=0.00 sys=0.00, real=0.01 secs] 

# 并发预清理阶段开始
# 在上述并发标记过程中，一些对象的引用可能会发生变化，jvm 会将包含这个对象的区域（card）标记为 dirty
# 在此阶段，能够从 dirty 对象到达的对象也会被标记，这个标记做完之后，dirty card 标记就会被清除了
2019-12-03t16:43:03.190-0800: [cms-concurrent-preclean-start]

# 并发预清理耗时统计
2019-12-03t16:43:03.190-0800: [cms-concurrent-preclean: 0.000/0.000 secs] [times: user=0.00 sys=0.00, real=0.00 secs] 

# 重新标记阶段，目的是完成老年代中所有存活对象的标记
# 上一阶段是并发执行的，在执行过程中对象的引用关系还会发生变化，所以再次标记
# 因为配置了 -xx:+cmsscavengebeforeremark 参数，所以会在标记发生一次 minor gc
# 进行一次minor gc,完成后年轻代可用空间 267k，年轻代总大小9216k
2019-12-03t16:43:03.190-0800: [gc (cms final remark) [yg occupancy: 267 k (9216 k)]
# 更详细的年轻代收集情况
2019-12-03t16:43:03.190-0800: [gc (cms final remark) 2019-12-03t16:43:03.190-0800: [parnew: 267k->103k(9216k), 0.0021800 secs] 919k->755k(19456k), 0.0022127 secs] [times: user=0.00 sys=0.00, real=0.00 secs] 
# 在程序暂停时重新进行扫描(rescan),以完成存活对象的标记
2019-12-03t16:43:03.192-0800: [rescan (parallel) , 0.0002866 secs]
# 第一子阶段：处理弱引用
2019-12-03t16:43:03.193-0800: [weak refs processing, 0.0015605 secs]
# 第二子阶段：卸载不适用的类
2019-12-03t16:43:03.194-0800: [class unloading, 0.0010847 secs]
# 第三子阶段:清理持有class级别 metadata 的符号表(symbol tables),以及内部化字符串对应的 string tables
# 完成后老年代使用量为651k(老年代总大小10240k=10m)
# 整个堆使用量 755k(总堆大小19456k=19m)
2019-12-03t16:43:03.195-0800: [scrub symbol table, 0.0015690 secs]
2019-12-03t16:43:03.197-0800: [scrub string table, 0.0003786 secs][1 cms-remark: 651k(10240k)] 755k(19456k), 0.0075058 secs] [times: user=0.01 sys=0.01, real=0.00 secs]

#开始并发清理 清除未被标记、不再使用的对象以释放内存空间
2019-12-03t16:43:03.198-0800: [cms-concurrent-sweep-start]
#并发清理阶段耗时
2019-12-03t16:43:03.198-0800: [cms-concurrent-sweep: 0.001/0.001 secs] [times: user=0.00 sys=0.00, real=0.00 secs] 

# 开始并发重置，重置cms算法相关的内部数据, 为下一次gc循环做准备
2019-12-03t16:43:03.198-0800: [cms-concurrent-reset-start]
# 重置耗时
2019-12-03t16:43:03.199-0800: [cms-concurrent-reset: 0.000/0.000 secs] [times: user=0.00 sys=0.00, real=0.00 secs] 

# 下面是执行 jmap -histo:live 命令触发的 full gc
# gc 类型是 full gc
# 触发原因是 heap inspection initiated gc
# cms收集老年代：从清理前的650k变为清理后的617k，总的老年代10m,耗时0.0048490秒
# 总堆使用大小由 1245k变为617k，总堆19m
# metaspace: 3912k变为3912k，
# metaspace 总大小显示为  compressedclassspacesize +(2*initialbootclassloadermetaspacesize)
2019-12-03t16:43:20.115-0800: [full gc (heap inspection initiated gc) 2019-12-03t16:43:20.115-0800: [cms: 650k->617k(10240k), 0.0048490 secs] 1245k->617k(19456k), [metaspace: 3912k->3912k(1056768k)], 0.0049050 secs] [times: user=0.00 sys=0.00, real=0.01 secs]

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

g1 收集器

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

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

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

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

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

g1 是 cms 的替代版本，具有如下特点：

横跨年轻代和老年代，不需要其他收集器配合；
并发收集器，可以与用户线程并发执行；
会压缩内存碎片；
可预测的停顿时间与高吞吐量；

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

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 收集器的参数如下：

-xx:+useg1gc
-xx:maxgcpausemillis=100

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

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

# 进行了一次年轻代 gc,耗时0.0008029s
[gc pause (g1 humongous allocation) (young), 0.0008029 secs]
# 4个gc线程并行执行
   [parallel time: 0.5 ms, gc workers: 4]
   # gc 线程耗时统计，反应收集的稳定性和效率
      [gc worker start (ms): min: 90438.1, avg: 90438.2, max: 90438.4, diff: 0.3]
      # 扫描堆外内存耗时统计
      [ext root scanning (ms): min: 0.0, avg: 0.2, max: 0.2, diff: 0.2, sum: 0.6]
      # 更新和扫描rsets 耗时统计
      [update rs (ms): min: 0.0, avg: 0.1, max: 0.2, diff: 0.2, sum: 0.2]
         [processed buffers: min: 0, avg: 0.2, max: 1, diff: 1, sum: 1]
      [scan rs (ms): min: 0.0, avg: 0.0, max: 0.0, diff: 0.0, sum: 0.0]
      #扫描堆中的 root 对象耗时统计
      [code root scanning (ms): min: 0.0, avg: 0.0, max: 0.0, diff: 0.0, sum: 0.0]
      # 拷贝存活对象耗时统计
      [object copy (ms): min: 0.0, avg: 0.0, max: 0.0, diff: 0.0, sum: 0.1]
      # gc 线程确保自身安全停止耗时统计
      [termination (ms): min: 0.0, avg: 0.1, max: 0.2, diff: 0.2, sum: 0.5]
         [termination attempts: min: 1, avg: 1.0, max: 1, diff: 0, sum: 4]
      [gc worker other (ms): min: 0.0, avg: 0.0, max: 0.0, diff: 0.0, sum: 0.0]
      # gc的worker 线程的工作时间总计
      [gc worker total (ms): min: 0.1, avg: 0.4, max: 0.5, diff: 0.3, sum: 1.5]
      # gc的worker 线程完成作业的时间统计
      [gc worker end (ms): min: 90438.6, avg: 90438.6, max: 90438.6, diff: 0.0]
   # 修复gc期间code root指针改变的耗时
   [code root fixup: 0.0 ms]
   # 清除code root耗时
   [code root purge: 0.0 ms]
   # 清除card tables 中的dirty card的耗时
   [clear ct: 0.0 ms]
   # 其他方面比如选择cset、处理已用对象、引用入referencequeues、释放cset中的region等的耗时
   [other: 0.3 ms]
      [choose cset: 0.0 ms]
      [ref proc: 0.1 ms]
      [ref enq: 0.0 ms]
      [redirty cards: 0.0 ms]
      [humongous register: 0.0 ms]
      [humongous reclaim: 0.0 ms]
      [free cset: 0.0 ms]
   # 收集前 eden区使用量 1024k(总容量9216k),收集后容量0b(总容量9216k)
   # survivors 区收集前后的大小
   # 堆空间收集前使用量13.4m(总量20m),收集后650.2k
   [eden: 1024.0k(9216.0k)->0.0b(9216.0k) survivors: 1024.0k->1024.0k heap: 13.4m(20.0m)->650.2k(20.0m)]
 [times: user=0.00 sys=0.00, real=0.00 secs] 

# 初始标记阶段，耗时0.0031800s
2019-12-03t16:48:25.456-0800: [gc pause (g1 humongous allocation) (young) (initial-mark), 0.0031800 secs][parallel time: 2.5 ms, gc workers: 4]
      [gc worker start (ms): min: 4115.2, avg: 4115.4, max: 4115.8, diff: 0.6]
      ...
   [eden: 3072.0k(10.0m)->0.0b(9216.0k) survivors: 0.0b->1024.0k heap: 9216.0k(20.0m)->744.0k(20.0m)]
 [times: user=0.01 sys=0.00, real=0.00 secs] 
 
# root区扫描 
2019-12-03t16:48:25.460-0800: [gc concurrent-root-region-scan-start]
2019-12-03t16:48:25.462-0800: [gc concurrent-root-region-scan-end, 0.0024198 secs]
# 并发标记
2019-12-03t16:48:25.462-0800: [gc concurrent-mark-start]
2019-12-03t16:48:25.462-0800: [gc concurrent-mark-end, 0.0001306 secs]

# 再次标记
2019-12-03t16:48:25.462-0800: [gc remark 2019-12-03t16:48:25.462-0800: [finalize marking, 0.0015922 secs] 2019-12-03t16:48:25.464-0800: [gc ref-proc, 0.0004899 secs] 2019-12-03t16:48:25.465-0800: [unloading, 0.0016093 secs], 0.0040544 secs]
 [times: user=0.01 sys=0.00, real=0.00 secs] 
# 清理工作 
2019-12-03t16:48:25.467-0800: [gc cleanup 4000k->4000k(20m), 0.0003710 secs]
 [times: user=0.00 sys=0.00, real=0.00 secs]