参考：
jvm：GC日志解析：G1日志解析
 JVM调优参数大全、参数设置案例、日志分析

1. G1

1.1 gc 日志头

OpenJDK 64-Bit Server VM (25.272-b10) for linux-amd64 JRE (1.8.0_272-b10), built on Oct 19 2020 11:11:12 by "openjdk" with gcc 4.4.7 20120313 (Red Hat 4.4.7-23)
Memory: 4k page, physical 8388608k(4903852k free), swap 16777212k(14997524k free)
CommandLine flags: -XX:CompressedClassSpaceSize=536870912 -XX:GCLogFileSize=31457280 -XX:+HeapDumpOnOutOfMemoryError -XX:HeapDumpPath=/data/logs/java/heap_dump_%p.log -XX:InitialBootClassLoaderMetaspaceSize=268435456 -XX:InitialHeapSize=4294967296 -XX:MaxDirectMemorySize=1073741824 -XX:MaxHeapSize=4294967296 -XX:MaxMetaspaceSize=1073741824 -XX:MetaspaceSize=268435456 -XX:NumberOfGCLogFiles=5 -XX:+PrintGC -XX:+PrintGCDateStamps -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:+PrintHeapAtGC -XX:+UseCompressedClassPointers -XX:+UseCompressedOops -XX:+UseG1GC -XX:+UseGCLogFileRotation

这里分为三部分信息：虚拟机信息、操作系统内存信息、命令行参数

版本和环境信息

虚拟机的版本信息：OpenJDK 64-Bit Server VM (25.272-b10)
操作系统信息：linux-amd64
JRE版本：JRE (1.8.0_272-b10)
JDK的构建信息：built on Oct 19 2020 11:11:12 by “openjdk” with gcc 4.4.7 20120313 (Red Hat 4.4.7-23)

内存信息

内存页大小：4K
物理内存：8G(4.7G空闲)、交换分区16G(14.3G空闲)

1.2 gc 前后堆信息

Heap before GC invocations=302 (full 0):
 garbage-first heap   total 4194304K, used 3492794K [0x00000006e0000000, 0x00000006e0204000, 0x00000007e0000000)
  region size 2048K, 1228 young (2514944K), 45 survivors (92160K)
 Metaspace       used 108788K, capacity 351624K, committed 353612K, reserved 1572864K
  class space    used 12362K, capacity 12998K, committed 13388K, reserved 1048576K

回收次数

Heap before GC invocations=302 (full 0)

invocations=302 说明本次gc开始之前，已经经历过302次垃圾回收。其中full gc是0次。

堆的内存使用情况

garbage-first heap   total 4194304K, used 3492794K [0x00000006e0000000, 0x00000006e0204000, 0x00000007e0000000)

GC之前的堆，[保留]内存共计4G，使用了3492794K（约3.3G）

中括号中是是三个16进制数值。0x-00000006e0000000 ：这个数值共有16个有效值，转化为2进制，就是64个有效值（应用所在物理机的CPU是64位）

第一个数值：0x-00000006e0000000指的是堆保留内存低地址边界

第三个数值：0x-00000007e0000000指的是堆保留内存高地址边界

6e0000000 = 01101111 + 28个0

7e0000000 = 01111111 + 28个0

(7e0000000 - 6e0000000) = 1 + 32个0 = 2的32次方 = 4G

因为启动参数-Xmx设置为4G

第二个数值：0x00000006e0204000，普遍的说法是commited内存的高地址边界。

按照这个说法，那么(这个数值 - 堆保留内存低地址边界)的结果应该近似等于used数值（3.5G）。

实际呢：0x6e0204000 - 0x6e0000000 = 0x204000 = 2113536(十进制数值) ≈ 2.01M

这个数值和3.5G相差甚远。所以这个数值不能直接代表commited内存.

region size 2048K, 1228 young (2514944K), 45 survivors (92160K)

每个region2M，一共1228的young region (占用了2514944K空间)，其中45个是survivors(占用了92160K空间)。在统计的时候，把survivors的region也算到了前面的数值里。

元空间使用情况

Metaspace       used 108788K, capacity 351624K, committed 353612K, reserved 1572864K

Metaspace指的是整个元数据空间的内存占用情况（包括class space）

used：加载的数据占用108M(约)，
capacity：包含数据的chunk块共计占用351624K（有些块是没满的）。每个chunk基于level不同，大小在1k-4M之间不等。
committed：申请所有的chunk块的总空间353612K（这里包含这未被使用的空的chunk块）。
reserved：jvm启动时，基于参数设置，向操作系统申请的预留空间。

class space    used 12362K, capacity 12998K, committed 13388K, reserved 1048576K

class space 见名知意，就存储类(类运行时结构，也叫Klass)的空间

1.3 young GC

GC 日志中大部分都是 young gc 日志。即使是发生了混合 gc，在整个混合 gc 周期中也是包含着至少一次 young gc 的。可以这么粗略的认为：混合 gc = 各种并发阶段 + 穿插这 n 次 young gc + n 次 mixed gc。而且标记为 mixed 的 gc 日志的格式和 young gc 的格式是相同，区别只是在于各种数值。所以重点精细分析 young gc 日志的内容。而混合 gc 重点关注的通过 gc 日志来分析是他的各个组成阶段、以及回收步骤。下面是一个常规的 young gc 的日志片段。

2021-11-06T06:07:37.195+0800: 23577.357: [GC pause (G1 Evacuation Pause) (young), 0.1141917 secs]
   [Parallel Time: 97.6 ms, GC Workers: 4]
      [GC Worker Start (ms): Min: 23577359.3, Avg: 23577359.3, Max: 23577359.4, Diff: 0.1]
      [Ext Root Scanning (ms): Min: 3.4, Avg: 4.5, Max: 7.6, Diff: 4.2, Sum: 18.0]
      [Update RS (ms): Min: 12.0, Avg: 14.7, Max: 15.7, Diff: 3.6, Sum: 58.9]
         [Processed Buffers: Min: 32, Avg: 69.8, Max: 98, Diff: 66, Sum: 279]
      [Scan RS (ms): Min: 0.4, Avg: 0.5, Max: 0.5, Diff: 0.0, Sum: 1.9]
      [Code Root Scanning (ms): Min: 0.0, Avg: 0.1, Max: 0.1, Diff: 0.1, Sum: 0.3]
      [Object Copy (ms): Min: 77.2, Avg: 77.6, Max: 77.8, Diff: 0.6, Sum: 310.2]
      [Termination (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
         [Termination Attempts: Min: 1, Avg: 1.0, Max: 1, Diff: 0, Sum: 4]
      [GC Worker Other (ms): Min: 0.1, Avg: 0.1, Max: 0.1, Diff: 0.1, Sum: 0.4]
      [GC Worker Total (ms): Min: 97.4, Avg: 97.4, Max: 97.5, Diff: 0.1, Sum: 389.8]
      [GC Worker End (ms): Min: 23577456.8, Avg: 23577456.8, Max: 23577456.8, Diff: 0.1]
   [Code Root Fixup: 0.0 ms]
   [Code Root Purge: 0.0 ms]
   [Clear CT: 0.8 ms]
   [Other: 15.8 ms]
      [Choose CSet: 0.0 ms]
      [Ref Proc: 9.0 ms]
      [Ref Enq: 0.0 ms]
      [Redirty Cards: 0.2 ms]
      [Humongous Register: 1.5 ms]
      [Humongous Reclaim: 0.1 ms]
      [Free CSet: 3.7 ms]
   [Eden: 2366.0M(2366.0M)->0.0B(2372.0M) Survivors: 92160.0K->86016.0K Heap: 3410.9M(4096.0M)->1055.1M(4096.0M)]
 [Times: user=0.28 sys=0.13, real=0.12 secs]

1.3.1 gc 类型

2021-11-06T06:07:37.195+0800: 23577.357: [GC pause (G1 Evacuation Pause) (young), 0.1141917 secs]

2021年11月6日早晨6点07分37秒，距离 jvm 进程启动过去了23577.357秒(约6小时30分钟) [针对年轻代的数据迁移产生的停顿，花了0.114秒]
(young) 指的是年轻代gc，如果是 (mixed) 则指的是混合gc(年轻代+老年代)
(G1 Evacuation Pause) 指的是产生本次gc的原因，空间使用达到阈值，
- 如果是young gc则意味着年轻代已满
- 如果是mixed gc则大多数情况下是老年代空间占整个堆空间比例达到阈值（默认45%）
- 这个地方还可能是 (G1 Humongous Allocation) 表示巨型对象空间分配申请。每一个巨型对象的的内存分配都会触发一次gc尝试，如果当前已经处在并发标记周期阶段了，则不会主动发起gc，否则会主动发起gc。所以应用程序开发一定要注意避免产生巨型对象。

1.3.2 并行执行时间

GC动作中有很多细节步骤，这些步骤中有些是可以并行执行的，有些是必须串行执行的。但是无论并行还是串行，都可以是多个GC线程协同工作的。

并行执行的部分

# 多线程并行回收，一共4个工作线程，花了83.8毫秒
[Parallel Time: 97.6 ms, GC Workers: 4]
   # 4个回收线程的启动时间（这是数值指的是jvm进程启动时间点 - 当前时间点 的毫秒时间差）min就是最早启动的，max就是最晚启动的，avg就是平均的启动时间，diff = max-min 
   [GC Worker Start (ms): Min: 23577359.3, Avg: 23577359.3, Max: 23577359.4, Diff: 0.1]
   # 外部根扫描（堆外扫描）：外部根包括(JVM系统目录、VM数据结构、JNI线程句柄、硬件寄存器、全局变量、线程堆栈根)
   [Ext Root Scanning (ms): Min: 3.4, Avg: 4.5, Max: 7.6, Diff: 4.2, Sum: 18.0]
   # 更新RSet：每个region都维护一个Rset，在有外部region引用本region内对象时，会记录外部region的card table索引。但这个引用信息的变更，是同步先写到一个队列，然后由一个单独的线程（叫做：并发优化线程）读取队列并异步更新RSet。所以，就可能存在这样的情况，垃圾回收时，队列中还存在着未被处理的变更日志，那么RSet信息就是不完整的。所以这个阶段要STW，检查队列中是否还有未处理完的变更记录，补充更新到RSet。
   [Update RS (ms): Min: 12.0, Avg: 14.7, Max: 15.7, Diff: 3.6, Sum: 58.9]
      # 已处理的缓冲：指的就是队列中那部分还没被消费完的变更记录。
      [Processed Buffers: Min: 32, Avg: 69.8, Max: 98, Diff: 66, Sum: 279]
   # 扫描所有region的RSet，来确定自己内部的存活对象。
   [Scan RS (ms): Min: 0.4, Avg: 0.5, Max: 0.5, Diff: 0.0, Sum: 1.9]
   # 代码根扫描：扫描的是被JIT即时编译器编译后的代码对堆的region内部对象的引用情况。
   [Code Root Scanning (ms): Min: 0.0, Avg: 0.1, Max: 0.1, Diff: 0.1, Sum: 0.3]
   # 对象迁移：这一步就是将存活对象迁移到新的region和survivor，也有一部分会晋升到老年代region。回收老的region。
   [Object Copy (ms): Min: 77.2, Avg: 77.6, Max: 77.8, Diff: 0.6, Sum: 310.2]
   # GC终止耗时：工作线程终止
   [Termination (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
      # 终止尝试次数：1次
      [Termination Attempts: Min: 1, Avg: 1.0, Max: 1, Diff: 0, Sum: 4]
   # 该部分并非GC的活动，而是JVM的活动导致占用了GC暂停时间(例如JNI编译)
   [GC Worker Other (ms): Min: 0.1, Avg: 0.1, Max: 0.1, Diff: 0.1, Sum: 0.4]
   # 4个回收线程总执行耗时
   [GC Worker Total (ms): Min: 97.4, Avg: 97.4, Max: 97.5, Diff: 0.1, Sum: 389.8]
   # 4个回收线程的结束时间（这是数值指的是jvm进程启动时间点 - 当前时间点 的毫秒时间差）
   [GC Worker End (ms): Min: 23577456.8, Avg: 23577456.8, Max: 23577456.8, Diff: 0.1]

串行执行时间

# 代码根修正：代码根所引用的存活对象，从一个region迁移到了另外的region，那么就需要更新他对这个对象的引用地址
   [Code Root Fixup: 0.0 ms]
   # 代码根清理：清理代码根中不再被使用的代码
   [Code Root Purge: 0.0 ms]
   # 清理card table：清理全局卡表中的已扫描标志
   [Clear CT: 0.8 ms]
   # 其他操作耗时
   [Other: 15.8 ms]
      # 选择要回收的集合（只有在混合回收时，这一步才有意义，需要基于停顿时间的考量，利用启发性算法重新界定需要回收哪些region。单纯的young gc，就是所有年轻代region）
      [Choose CSet: 0.0 ms]
      # 引用处理：针对软引用（内存不足才回收）、弱引用（发生gc就可回收）、虚引用、final引用、JNI引用
      [Ref Proc: 9.0 ms]
      # 可以被回收的引用入队。
      [Ref Enq: 0.0 ms]
      # 上一步的引用处理，会更新RSet信息，所以也需要同步标记全局开标中对应的card table为脏卡片
      [Redirty Cards: 0.2 ms]
      # 巨型对象注册（统计）：虽然巨型对象是存储在老年代分区的，但是G1内部也做了特殊优化手段，在young gc是也会顺带回收一些巨型对象分区。在young gc时，会基于region的RSet确定外部对自己的引用。
      # 而一旦Rset所对应的region是一个Humongous region（以下简称：H-Region），又通过逐层引用排查发现该H-Region已经不再被引用。那么就意味着这个H-Region可被回收。
      [Humongous Register: 1.5 ms]
      # 回收H-Region的耗时
      [Humongous Reclaim: 0.1 ms]
      # 回收CSet中region的空间，并将这些region重新置为空闲。
      [Free CSet: 3.7 ms]

空间信息

[Eden: 2366.0M(2366.0M)->0.0B(2372.0M) Survivors: 92160.0K->86016.0K Heap: 3410.9M(4096.0M)->1055.1M(4096.0M)]

伊甸区：回收前总内存一共2366M，使用了2366M。回收后总内存增长了6M，变为2372M，但是使用内存变为OM，这是因为已经都被回收。
幸存区：回收前，内存使用90M，回收后内存使用84M。
整个堆空间：总内存一直都是4G，回收前使用了3410M，回收后使用了1055M。差值是2355M，对比伊甸区被清空的2366M和幸存区减少的8M，这中间有19M的差值。可以估算有19M的数据晋升到了老年代。

用时统计

[Times: user=0.28 sys=0.13, real=0.12 secs]

user: 垃圾收集线程在新生代垃圾收集过程中消耗的CPU时间，这个时间跟垃圾收集线程的个数有关，可能会比real time大很多；
sys: 内核用时
real: 真实用时

1.4 mixed gc

1.4.1 概述

前文已经介绍过mixed gc不是一个gc动作，是一套动作，包含多个步骤，多次gc。下面来看一个完整的mixed gc的日志样例。

{Heap before GC invocations=439 (full 0):
 garbage-first heap   total 4194304K, used 3719960K [0x00000006e0000000, 0x00000006e0204000, 0x00000007e0000000)
  region size 2048K, 895 young (1832960K), 25 survivors (51200K)
 Metaspace       used 115155K, capacity 358590K, committed 358860K, reserved 1572864K
  class space    used 12989K, capacity 13737K, committed 13772K, reserved 1048576K
2021-11-06T14:24:22.132+0800: 53382.293: [GC pause (G1 Evacuation Pause) (young) (initial-mark), 0.0597538 secs]
   [Parallel Time: 51.9 ms, GC Workers: 4]
      [GC Worker Start (ms): Min: 53382297.2, Avg: 53382297.2, Max: 53382297.2, Diff: 0.1]
      [Ext Root Scanning (ms): Min: 5.2, Avg: 5.5, Max: 5.7, Diff: 0.5, Sum: 22.0]
      [Update RS (ms): Min: 7.1, Avg: 7.2, Max: 7.2, Diff: 0.1, Sum: 28.8]
         [Processed Buffers: Min: 52, Avg: 57.8, Max: 67, Diff: 15, Sum: 231]
      [Scan RS (ms): Min: 0.2, Avg: 0.3, Max: 0.3, Diff: 0.0, Sum: 1.0]
      [Code Root Scanning (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
      [Object Copy (ms): Min: 37.5, Avg: 37.8, Max: 38.1, Diff: 0.6, Sum: 151.1]
      [Termination (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
         [Termination Attempts: Min: 1, Avg: 1.0, Max: 1, Diff: 0, Sum: 4]
      [GC Worker Other (ms): Min: 0.1, Avg: 0.1, Max: 0.3, Diff: 0.2, Sum: 0.5]
      [GC Worker Total (ms): Min: 50.8, Avg: 50.8, Max: 50.9, Diff: 0.1, Sum: 203.4]
      [GC Worker End (ms): Min: 53382348.0, Avg: 53382348.1, Max: 53382348.1, Diff: 0.1]
   [Code Root Fixup: 0.0 ms]
   [Code Root Purge: 0.0 ms]
   [Clear CT: 0.3 ms]
   [Other: 7.5 ms]
      [Choose CSet: 0.0 ms]
      [Ref Proc: 1.9 ms]
      [Ref Enq: 0.0 ms]
      [Redirty Cards: 0.1 ms]
      [Humongous Register: 0.0 ms]
      [Humongous Reclaim: 0.1 ms]
      [Free CSet: 2.2 ms]
   [Eden: 1740.0M(1740.0M)->0.0B(1736.0M) Survivors: 51200.0K->51200.0K Heap: 3632.8M(4096.0M)->1896.8M(4096.0M)]
Heap after GC invocations=440 (full 0):
 garbage-first heap   total 4194304K, used 1942303K [0x00000006e0000000, 0x00000006e0204000, 0x00000007e0000000)
  region size 2048K, 25 young (51200K), 25 survivors (51200K)
 Metaspace       used 115155K, capacity 358590K, committed 358860K, reserved 1572864K
  class space    used 12989K, capacity 13737K, committed 13772K, reserved 1048576K
}
 [Times: user=0.16 sys=0.04, real=0.06 secs] 
2021-11-06T14:24:22.192+0800: 53382.353: [GC concurrent-root-region-scan-start]
2021-11-06T14:24:22.249+0800: 53382.410: [GC concurrent-root-region-scan-end, 0.0567419 secs]
2021-11-06T14:24:22.249+0800: 53382.410: [GC concurrent-mark-start]
2021-11-06T14:24:22.776+0800: 53382.938: [GC concurrent-mark-end, 0.5277478 secs]
2021-11-06T14:24:22.778+0800: 53382.939: [GC remark 2021-11-06T14:24:22.778+0800: 53382.939: [Finalize Marking, 0.0004157 secs] 2021-11-06T14:24:22.778+0800: 53382.940: [GC ref-proc, 1.2651008 secs] 2021-11-06T14:24:24.043+0800: 53384.205: [Unloading, 0.0628071 secs], 1.3315890 secs]
 [Times: user=1.33 sys=0.19, real=1.33 secs] 
2021-11-06T14:24:24.111+0800: 53384.272: [GC cleanup 1908M->1577M(4096M), 0.0058486 secs]
 [Times: user=0.02 sys=0.00, real=0.01 secs] 
2021-11-06T14:24:24.118+0800: 53384.279: [GC concurrent-cleanup-start]
2021-11-06T14:24:24.119+0800: 53384.280: [GC concurrent-cleanup-end, 0.0009447 secs]
{Heap before GC invocations=441 (full 0):
 garbage-first heap   total 4194304K, used 3380949K [0x00000006e0000000, 0x00000006e0204000, 0x00000007e0000000)
  region size 2048K, 893 young (1828864K), 25 survivors (51200K)
 Metaspace       used 115106K, capacity 358512K, committed 358860K, reserved 1572864K
  class space    used 12982K, capacity 13724K, committed 13772K, reserved 1048576K
2021-11-06T14:26:53.067+0800: 53533.229: [GC pause (G1 Evacuation Pause) (young), 0.1490704 secs]
   [Parallel Time: 60.2 ms, GC Workers: 4]
      [GC Worker Start (ms): Min: 53533231.3, Avg: 53533231.4, Max: 53533231.4, Diff: 0.2]
      [Ext Root Scanning (ms): Min: 4.3, Avg: 5.2, Max: 7.3, Diff: 2.9, Sum: 20.8]
      [Update RS (ms): Min: 22.6, Avg: 24.2, Max: 25.1, Diff: 2.6, Sum: 96.9]
         [Processed Buffers: Min: 54, Avg: 69.0, Max: 104, Diff: 50, Sum: 276]
      [Scan RS (ms): Min: 0.0, Avg: 0.3, Max: 0.4, Diff: 0.4, Sum: 1.1]
      [Code Root Scanning (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
      [Object Copy (ms): Min: 20.1, Avg: 21.5, Max: 22.7, Diff: 2.6, Sum: 86.1]
      [Termination (ms): Min: 7.3, Avg: 8.6, Max: 10.4, Diff: 3.1, Sum: 34.5]
         [Termination Attempts: Min: 455, Avg: 509.0, Max: 567, Diff: 112, Sum: 2036]
      [GC Worker Other (ms): Min: 0.0, Avg: 0.1, Max: 0.2, Diff: 0.2, Sum: 0.4]
      [GC Worker Total (ms): Min: 59.9, Avg: 60.0, Max: 60.1, Diff: 0.3, Sum: 239.9]
      [GC Worker End (ms): Min: 53533291.3, Avg: 53533291.3, Max: 53533291.4, Diff: 0.1]
   [Code Root Fixup: 0.0 ms]
   [Code Root Purge: 0.0 ms]
   [Clear CT: 0.3 ms]
   [Other: 88.5 ms]
      [Choose CSet: 0.0 ms]
      [Ref Proc: 82.9 ms]
      [Ref Enq: 0.1 ms]
      [Redirty Cards: 0.1 ms]
      [Humongous Register: 1.5 ms]
      [Humongous Reclaim: 0.1 ms]
      [Free CSet: 2.3 ms]
   [Eden: 1736.0M(1736.0M)->0.0B(154.0M) Survivors: 51200.0K->51200.0K Heap: 3301.7M(4096.0M)->1570.4M(4096.0M)]
Heap after GC invocations=442 (full 0):
 garbage-first heap   total 4194304K, used 1608107K [0x00000006e0000000, 0x00000006e0204000, 0x00000007e0000000)
  region size 2048K, 25 young (51200K), 25 survivors (51200K)
 Metaspace       used 115106K, capacity 358512K, committed 358860K, reserved 1572864K
  class space    used 12982K, capacity 13724K, committed 13772K, reserved 1048576K
}
 [Times: user=0.26 sys=0.07, real=0.14 secs] 
{Heap before GC invocations=442 (full 0):
 garbage-first heap   total 4194304K, used 1765803K [0x00000006e0000000, 0x00000006e0204000, 0x00000007e0000000)
  region size 2048K, 102 young (208896K), 25 survivors (51200K)
 Metaspace       used 115106K, capacity 358512K, committed 358860K, reserved 1572864K
  class space    used 12982K, capacity 13724K, committed 13772K, reserved 1048576K
2021-11-06T14:27:05.068+0800: 53545.229: [GC pause (G1 Evacuation Pause) (mixed), 0.0407992 secs]
   [Parallel Time: 35.3 ms, GC Workers: 4]
      [GC Worker Start (ms): Min: 53545230.0, Avg: 53545230.1, Max: 53545230.1, Diff: 0.1]
      [Ext Root Scanning (ms): Min: 2.1, Avg: 2.5, Max: 3.3, Diff: 1.3, Sum: 10.0]
      [Update RS (ms): Min: 4.0, Avg: 4.4, Max: 4.6, Diff: 0.6, Sum: 17.8]
         [Processed Buffers: Min: 32, Avg: 48.2, Max: 59, Diff: 27, Sum: 193]
      [Scan RS (ms): Min: 2.8, Avg: 3.1, Max: 3.4, Diff: 0.6, Sum: 12.4]
      [Code Root Scanning (ms): Min: 0.0, Avg: 0.3, Max: 0.6, Diff: 0.5, Sum: 1.1]
      [Object Copy (ms): Min: 24.5, Avg: 24.9, Max: 25.1, Diff: 0.6, Sum: 99.5]
      [Termination (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
         [Termination Attempts: Min: 1, Avg: 1.8, Max: 3, Diff: 2, Sum: 7]
      [GC Worker Other (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.1]
      [GC Worker Total (ms): Min: 35.2, Avg: 35.2, Max: 35.3, Diff: 0.1, Sum: 140.9]
      [GC Worker End (ms): Min: 53545265.3, Avg: 53545265.3, Max: 53545265.3, Diff: 0.0]
   [Code Root Fixup: 0.0 ms]
   [Code Root Purge: 0.0 ms]
   [Clear CT: 0.3 ms]
   [Other: 5.2 ms]
      [Choose CSet: 0.4 ms]
      [Ref Proc: 1.8 ms]
      [Ref Enq: 0.0 ms]
      [Redirty Cards: 0.1 ms]
      [Humongous Register: 0.2 ms]
      [Humongous Reclaim: 0.0 ms]
      [Free CSet: 1.8 ms]
   [Eden: 154.0M(154.0M)->0.0B(188.0M) Survivors: 51200.0K->16384.0K Heap: 1724.4M(4096.0M)->1145.9M(4096.0M)]
Heap after GC invocations=443 (full 0):
 garbage-first heap   total 4194304K, used 1173387K [0x00000006e0000000, 0x00000006e0204000, 0x00000007e0000000)
  region size 2048K, 8 young (16384K), 8 survivors (16384K)
 Metaspace       used 115106K, capacity 358512K, committed 358860K, reserved 1572864K
  class space    used 12982K, capacity 13724K, committed 13772K, reserved 1048576K
}
 [Times: user=0.13 sys=0.02, real=0.04 secs] 
{Heap before GC invocations=443 (full 0):
 garbage-first heap   total 4194304K, used 1365899K [0x00000006e0000000, 0x00000006e0204000, 0x00000007e0000000)
  region size 2048K, 102 young (208896K), 8 survivors (16384K)
 Metaspace       used 115106K, capacity 358512K, committed 358860K, reserved 1572864K
  class space    used 12982K, capacity 13724K, committed 13772K, reserved 1048576K
2021-11-06T14:27:20.626+0800: 53560.788: [GC pause (G1 Evacuation Pause) (mixed), 0.1076664 secs]
   [Parallel Time: 101.8 ms, GC Workers: 4]
      [GC Worker Start (ms): Min: 53560789.1, Avg: 53560789.1, Max: 53560789.1, Diff: 0.1]
      [Ext Root Scanning (ms): Min: 2.2, Avg: 2.5, Max: 2.7, Diff: 0.5, Sum: 9.8]
      [Update RS (ms): Min: 15.1, Avg: 15.1, Max: 15.1, Diff: 0.0, Sum: 60.5]
         [Processed Buffers: Min: 57, Avg: 70.8, Max: 85, Diff: 28, Sum: 283]
      [Scan RS (ms): Min: 11.7, Avg: 12.3, Max: 12.9, Diff: 1.3, Sum: 49.1]
      [Code Root Scanning (ms): Min: 0.4, Avg: 1.0, Max: 1.5, Diff: 1.1, Sum: 4.0]
      [Object Copy (ms): Min: 65.4, Avg: 66.1, Max: 66.9, Diff: 1.4, Sum: 264.6]
      [Termination (ms): Min: 4.3, Avg: 4.7, Max: 5.3, Diff: 1.1, Sum: 18.8]
         [Termination Attempts: Min: 408, Avg: 490.0, Max: 617, Diff: 209, Sum: 1960]
      [GC Worker Other (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.1]
      [GC Worker Total (ms): Min: 101.6, Avg: 101.7, Max: 101.7, Diff: 0.1, Sum: 406.7]
      [GC Worker End (ms): Min: 53560890.7, Avg: 53560890.8, Max: 53560890.8, Diff: 0.0]
   [Code Root Fixup: 0.1 ms]
   [Code Root Purge: 0.0 ms]
   [Clear CT: 0.4 ms]
   [Other: 5.4 ms]
      [Choose CSet: 0.5 ms]
      [Ref Proc: 1.7 ms]
      [Ref Enq: 0.0 ms]
      [Redirty Cards: 0.4 ms]
      [Humongous Register: 0.2 ms]
      [Humongous Reclaim: 0.0 ms]
      [Free CSet: 1.7 ms]
   [Eden: 188.0M(188.0M)->0.0B(2440.0M) Survivors: 16384.0K->16384.0K Heap: 1333.9M(4096.0M)->859.0M(4096.0M)]
Heap after GC invocations=444 (full 0):
 garbage-first heap   total 4194304K, used 879616K [0x00000006e0000000, 0x00000006e0204000, 0x00000007e0000000)
  region size 2048K, 8 young (16384K), 8 survivors (16384K)
 Metaspace       used 115106K, capacity 358512K, committed 358860K, reserved 1572864K
  class space    used 12982K, capacity 13724K, committed 13772K, reserved 1048576K
}
 [Times: user=0.36 sys=0.06, real=0.10 secs]

为了便于从宏观上观察整个mixed gc的步骤，我们把gc pause类型日志内的一些细节内容省略掉，因为内部的具体内容格式是和我们前面介绍过的young gc的格式是一致的。
精简后的内容如下：

{
Heap before GC...    
2021-11-06T14:24:22.132+0800: 53382.293: [GC pause (G1 Evacuation Pause) (young) (initial-mark), 0.0597538 secs]
...
[Eden: 1740.0M(1740.0M)->0.0B(1736.0M) Survivors: 51200.0K->51200.0K Heap: 3632.8M(4096.0M)->1896.8M(4096.0M)]
Heap after GC invocations=440 (full 0):
 garbage-first heap   total 4194304K, used 1942303K [0x00000006e0000000, 0x00000006e0204000, 0x00000007e0000000)
  region size 2048K, 25 young (51200K), 25 survivors (51200K)
  ...  
}
 [Times: user=0.16 sys=0.04, real=0.06 secs] 
 
// 华丽分割线：这是一个young gc，但是重点是后面标记了initial-mark，说明这是一个并发标记周期的开始。

2021-11-06T14:24:22.192+0800: 53382.353: [GC concurrent-root-region-scan-start]
2021-11-06T14:24:22.249+0800: 53382.410: [GC concurrent-root-region-scan-end, 0.0567419 secs]
2021-11-06T14:24:22.249+0800: 53382.410: [GC concurrent-mark-start]
2021-11-06T14:24:22.776+0800: 53382.938: [GC concurrent-mark-end, 0.5277478 secs]
2021-11-06T14:24:22.778+0800: 53382.939: [GC remark 2021-11-06T14:24:22.778+0800: 53382.939: [Finalize Marking, 0.0004157 secs] 2021-11-06T14:24:22.778+0800: 53382.940: [GC ref-proc, 1.2651008 secs] 2021-11-06T14:24:24.043+0800: 53384.205: [Unloading, 0.0628071 secs], 1.3315890 secs]
 [Times: user=1.33 sys=0.19, real=1.33 secs] 
2021-11-06T14:24:24.111+0800: 53384.272: [GC cleanup 1908M->1577M(4096M), 0.0058486 secs]
 [Times: user=0.02 sys=0.00, real=0.01 secs] 
2021-11-06T14:24:24.118+0800: 53384.279: [GC concurrent-cleanup-start]
2021-11-06T14:24:24.119+0800: 53384.280: [GC concurrent-cleanup-end, 0.0009447 secs]

// 华丽分割线：这里的步骤就是并发标记、重新标记、并发清理了。 到这，也表示一个并发标记周期结束了。

{
Heap before GC...    
2021-11-06T14:26:53.067+0800: 53533.229: [GC pause (G1 Evacuation Pause) (young), 0.1490704 secs]
...
[Eden: 1736.0M(1736.0M)->0.0B(154.0M) Survivors: 51200.0K->51200.0K Heap: 3301.7M(4096.0M)->1570.4M(4096.0M)]
Heap after GC invocations=442 (full 0):
 garbage-first heap   total 4194304K, used 1608107K [0x00000006e0000000, 0x00000006e0204000, 0x00000007e0000000)
  region size 2048K, 25 young (51200K), 25 survivors (51200K)
 ...  
}
 [Times: user=0.36 sys=0.06, real=0.10 secs]
 
// 华丽分割线：这是一次单纯的young gc，只清理了年轻代。

{
Heap before GC...    
2021-11-06T14:27:05.068+0800: 53545.229: [GC pause (G1 Evacuation Pause) (mixed), 0.0407992 secs]
...
[Eden: 154.0M(154.0M)->0.0B(188.0M) Survivors: 51200.0K->16384.0K Heap: 1724.4M(4096.0M)->1145.9M(4096.0M)]
Heap after GC invocations=443 (full 0):
 garbage-first heap   total 4194304K, used 1173387K [0x00000006e0000000, 0x00000006e0204000, 0x00000007e0000000)
  region size 2048K, 8 young (16384K), 8 survivors (16384K)
 ...  
}
 [Times: user=0.36 sys=0.06, real=0.10 secs]
 
// 华丽分割线：这是一次混合gc，年轻代和老年代都被清理

{
Heap before GC...    
2021-11-06T14:27:20.626+0800: 53560.788: [GC pause (G1 Evacuation Pause) (mixed), 0.1076664 secs]
...
[Eden: 188.0M(188.0M)->0.0B(2440.0M) Survivors: 16384.0K->16384.0K Heap: 1333.9M(4096.0M)->859.0M(4096.0M)]
Heap after GC invocations=444 (full 0):
 garbage-first heap   total 4194304K, used 879616K [0x00000006e0000000, 0x00000006e0204000, 0x00000007e0000000)
  region size 2048K, 8 young (16384K), 8 survivors (16384K)
... 
}
 [Times: user=0.36 sys=0.06, real=0.10 secs] 
 
// 华丽分割线：这也是一次混合gc，年轻代和老年代都被清理。 

// 再往下的日志就是一次普通的young gc了。所以认为上面的mixed gc 日志结束，就是一个完整的mixed回收的结束了。

一个完整的 mixed gc过程是从 (young) (initial-mark) 开始，到 (mixed) 结束。

具体到哪一条(mixed)结束呢，从(initial-mark)往后找，找到的第一个GC pause是mixed类型的日志，如果这个mixed之后的GC pause日志不是mixed类型了，说明这个mixed日志就是这个 mixed gc过程的结束。

整个mixed gc过程由几部分组成：并发标记周期（1个或者N个）+ 普通young gc（0次或者多次） + 混合回收周期

1.4.2 并发标记周期

从 (young) (initial-mark) 开始到 GC concurrent-cleanup-end 结束

initial-mark 初始标记

GC pause (G1 Evacuation Pause) (young) (initial-mark)
并发标记周期的开始步骤，一定是伴随着一次young gc一起产生。初始标记做的事情是标记根节点。这一步是需要STW的，正好可以和young gc一起做了，因为young gc也是STW，等于是搭个顺风车。

concurrent-root-region 根分区扫描

初始标记完成之后，也就意味着完成了一个young gc，存活的对象都被转移到了survivor分区。那么这些survivor分区的对象就是存活对象，他们都会被标记为根对象，这个过程称为根分区扫描，实际上扫描的是survivor分区。这个过程因为扫描的是survivor分区，所以这个过程不能和young gc同时进行，因为young gc会造成survivor分区的变化。

Concurrent Marking 并发标记

并发标记和应用线程并发执行。这一过程会扫描老年代，标记可达对象。

GC remark 重新标记

STW的。这一过程会处理引用变更日志缓冲区的未被处理的日志。同时，[GC ref-proc]引用处理也是重新标记阶段的一部分。这一步是可以多线程并行执行。

GC cleanup 独占清理

紧跟重新标记，此时还是STW的，同时这一步还会做三个事情：

RSet梳理：启发式算法或根据Rset尺寸对分区定义不同的等级。（RSet尺寸越大，说明对本分区的引用越多，那么本分区的等级也会越高）
堆分区梳理：针对老年代的分区，基于释放空间和暂停目标，定识别出回收收益高的region。
识别所有空闲分区：标记那些内部对象都是非存活的分区。

GC concurrent-cleanup 并发清理

回收线程和应用程序并发执行，回收上一步被标记为空闲的分区。

1.4.3 混合回收周期

在上面介绍的并发标记周期中，虽然也经历了回收(清理)动作（GC concurrent-cleanup），但是只是仅仅清理了那些对象都不存活的空闲分区。对于那些部分对象存活的年轻代和老年代分区还没有进行数据的迁移和分区的清理动作。但是在并发标记周期中已经识别出了应该回收哪些分区，所以接下来都是gc pause动作，会包含一次或多次的GC pause。最后一次的GC pause是mixed类型。混合回收周期内，也是可以发生单纯的young gc的。

我们上面的的例子里，混合回收周期内就包含了一次young gc + 两次mixed gc。

1.5 晋升日志

2022-06-17T19:01:50.328-0800: 1.425: [GC pause (G1 Evacuation Pause) (young)
Desired survivor size 7864320 bytes, new threshold 15 (max 15)
- age   1:    2059704 bytes,    2059704 total
- age   2:      86824 bytes,    2146528 total
- age   3:    2537176 bytes,    4683704 total
- age   4:    1230912 bytes,    5914616 total
, 0.0068678 secs]

Desired survivor size：期望晋升完成后，空间不超过此
new threshold 15：此次晋升阀值，超过此阀值进去老年代。若对象大小超过 Desired survivor size，则会减少晋升阀值
max 15：默认晋升阀值
age：年龄代大小
0.0068678 secs： gc 时间

如果觉得文章对你有用，请随意赞赏

java jvm 垃圾收集器 gc

GC 日志分析

https://blog.rainsheep.cn/archives/1655469210448

作者

Rainsheep

发布于

2022-06-17

更新于

2023-12-28

许可协议

CC BY 4.0