G1回收器的GC日志详解 #

常用GC日志相关启动参数 #

参数	描述
-XX:+UseGCLogFileRotation	打开或关闭GC日志滚动记录功能；要求必须设置 `-Xloggc` 参数
-XX:NumberOfGCLogFiles=xx	设置滚动日志文件的个数，必须大于1; 日志文件命名策略是，{filename}.0, {filename}.1, …, {filename}.n-1，其中n是该参数的值；要求必须设置 `-Xloggc` 参数
-XX:GCLogFileSize=50m	设置滚动日志文件的大小，必须大于8k; 当前写日志文件大小超过该参数值时，日志将写入下一个文件；要求必须设置 `-Xloggc` 参数
-Xloggc:/xx/xx/gc.log	指定GC日志文件路径
-XX:+PrintGCDetails	启用在每次GC时打印详细消息。默认禁用
-XX:+PrintGCDateStamps	启用输出GC发生时的时间戳（2021-09-26T15:15:50.529-0800），默认禁用
-XX:+PrintGCTimeStamps	启用在每次GC时打印时间（JVM启动到发生GC时候的秒数）。默认禁用
-XX:+PrintGCApplicationConcurrentTime	启用打印自上次暂停结束（例如，GC暂停）以来经过的时间。默认禁用
-XX:+PrintGCApplicationStoppedTime	启用打印暂停（例如，GC暂停）持续的时间。默认禁用

注意：参数-XX:+PrintGCApplicationStoppedTime的名称容易给人造成误导，他实际上打印的是程序在安全点暂停的时间，并非我们理解中的GC导致的STW的时间，安全点暂停不只是垃圾回收会发生，还有许多其他原因会导致安全点暂停，比如：

Deoptimization
Biased lock revocation
Thread dump
Heap inspection
Class redifinition
其他…( 点击查看)

可以配合 -XX:+PrintSafepointStatistics 和 –XX:PrintSafepointStatisticsCount=1 打印出具体的停顿原因。（这个开关开启后会定时采集，但是根据网上资料显示，采集的时候会触发所有线程进入安全点，所以此处不建议打开这个开关）

GC日志详解 #

此处先贴上本文用于测试的JVM启动参数

-XX:+UseG1GC (使用G1垃圾回收器)
-XX:+PrintGCDetails 
-XX:+PrintGCDateStamps 
-XX:+PrintGCTimeStamps 
-XX:+PrintGCApplicationConcurrentTime 
-XX:+PrintGCApplicationStoppedTime

下面对GC日志的内容进行解析

加上 -XX:+PrintGCApplicationStoppedTime 后会打印出如下日志 #

2021-10-09T16:47:25.754-0800: 0.088: Total time for which application threads were stopped: 0.0000828 seconds, Stopping threads took: 0.0000176 seconds

加上 -XX:+PrintGCApplicationConcurrentTime 后会打印出如下日志 #

2021-10-09T16:47:25.754-0800: 0.088: Application time: 0.0001107 seconds

一次停顿开始到结束的分析 #

2021-10-11T10:59:19.768-0800: 4.471: Application time: 0.0007241 seconds
2021-10-11T10:59:19.851-0800: 4.554: [GC remark 2021-10-11T10:59:19.851-0800: 4.554: [Finalize Marking, 0.0003405 secs] 2021-10-11T10:59:19.851-0800: 4.554: [GC ref-proc, 0.0000916 secs] 2021-10-11T10:59:19.851-0800: 4.554: [Unloading, 0.0003733 secs], 0.0010369 secs]
 [Times: user=0.00 sys=0.00, real=0.00 secs] 
2021-10-11T10:59:19.852-0800: 4.555: Total time for which application threads were stopped: 0.0840818 seconds, Stopping threads took: 0.0829986 seconds

GC日志中，可能会出现【Application time…】紧接着【Total time for which application threads were stopped…】行出现，这种情况，并非停顿后什么事情都没做，其实上文已经提到，造成停顿的原因有很多，并非只有GC会导致停顿，所以如果出现此种情况，是其他原因导致的停顿，具体是何原因，可以通过配置其他JVM参数，打印出具体的停顿详情，此处不做赘述

G1的GC日志分析 #

回顾：垃圾回收器

G1回收器主要有四种回收方式：

Young GC: 所有Eden区域满了后触发，并行收集，且完全STW
并发标记: 它的第一个阶段初始化标记和YGC一起发生，这个周期的目的就是找到回收价值最大的Region集合（垃圾很多，存活对象很少），为接下来的Mixed GC服务
Mixed GC: 回收所有年轻代的Region和部分老年代的Region，Mixed GC可能连续发生多次
Full GC: 非常慢，对应用来说简直就是灾难，会STW且回收所有类型的Region

1、Young GC日志分析 #

YGC是G1模式下遇到的频率最高的GC

2021-10-11T09:59:38.643+0800: 1.183: [GC pause (G1 Evacuation Pause) (young), 0.0095075 secs]
   [Parallel Time: 2.5 ms, GC Workers: 8]
      [GC Worker Start (ms): Min: 1182.9, Avg: 1183.2, Max: 1183.4, Diff: 0.5]
      [Ext Root Scanning (ms): Min: 0.0, Avg: 0.2, Max: 0.5, Diff: 0.5, Sum: 1.4]
      [Update RS (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.1]
         [Processed Buffers: Min: 0, Avg: 0.0, Max: 0, Diff: 0, Sum: 0]
      [Scan RS (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
      [Code Root Scanning (ms): Min: 0.0, Avg: 0.0, Max: 0.2, Diff: 0.2, Sum: 0.3]
      [Object Copy (ms): Min: 1.0, Avg: 1.2, Max: 1.7, Diff: 0.7, Sum: 10.0]
      [Termination (ms): Min: 0.0, Avg: 0.5, Max: 0.6, Diff: 0.6, Sum: 3.8]
         [Termination Attempts: Min: 1, Avg: 11.9, Max: 20, Diff: 19, Sum: 95]
      [GC Worker Other (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.1]
      [GC Worker Total (ms): Min: 1.7, Avg: 2.0, Max: 2.2, Diff: 0.5, Sum: 15.7]
      [GC Worker End (ms): Min: 1185.1, Avg: 1185.2, Max: 1185.3, Diff: 0.2]
   [Code Root Fixup: 0.0 ms]
   [Code Root Purge: 0.0 ms]
   [Clear CT: 0.2 ms]
   [Other: 6.7 ms]
      [Choose CSet: 0.0 ms]
      [Ref Proc: 6.1 ms]
      [Ref Enq: 0.3 ms]
      [Redirty Cards: 0.3 ms]
      [Humongous Register: 0.0 ms]
      [Humongous Reclaim: 0.0 ms]
      [Free CSet: 0.0 ms]
   [Eden: 4860.0M(4860.0M)->0.0B(4860.0M) Survivors: 52.0M->52.0M Heap: 5466.5M(8192.0M)->607.1M(8192.0M)]
 [Times: user=0.03 sys=0.01, real=0.01 secs]

这段日志是典型的Evacuation阶段日志（GC pause (G1 Evacuation Pause) (young)）。Evacution这个词在G1中出现的频率非常高，中文意思是疏散，在G1中可以理解为拷贝&清理，就是把存活的对象拷贝到1个或者多个Region中，目标Region可能只是Young区，也可能是Young区+Old区，取决于这次YGC是否有符合晋升到Old区的对象

还有其他很常见的young GC类型: GC pause (G1 Humongous Allocation) (young) 等有时候还会出现一些其他的参数比如: GC pause (G1 Evacuation Pause) (young) (to-space exhausted) 等，本文未提到的可以在出现后进行搜索，此处不赘述

详细分析 #

首行日志如下, 表示本次YGC发生在JVM启动后1.183秒的时候, 整个过程耗时0.0095075秒

2021-10-11T09:59:38.643+0800: 1.183: [GC pause (G1 Evacuation Pause) (young), 0.0095075 secs]

[Parallel Time: 2.5 ms, GC Workers: 8] GC Workers从开始并行收集到最后一个GC Worker结束所发生的STW的时间:2.5ms, 并行收集的GC Worker的数量: 4个, 可以通过-XX:ParallelGCThreads来指定
- [GC Worker Start (ms): Min: 1182.9, Avg: 1183.2, Max: 1183.4, Diff: 0.5] GC Worker开始工作的时间点, 最小值: 1182.9ms, 平均值: 1183.2ms, 最大值: 1183.4ms, 这三个值, 都是自JVM启动以来的时间戳; Diff: 0.5ms, 表示第一个和最后一个线程启动时间点的差. 理想情况下, 你希望他们同时启动, 也就是Diff越小越好
- [Ext Root Scanning (ms): Min: 0.0, Avg: 0.2, Max: 0.5, Diff: 0.5, Sum: 1.4] 扫描外部ROOT(thread stack roots, JNI, global variables, system dictionary, etc..)所花费的时间
- [Update RS (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.1] 每一个Region都有自己的RSet(Remembered Set), 通过它可以找到脏卡表, 脏卡表中存放了引用当前Region中的对象的【外部对象】的地址. 当向当前Region写入对象时, 有一个写入后置屏障会把引用这个对象的外部对象的地址维护到脏卡表中, 一旦满了, 并发细化线程就会与运行应用程序线程并行处理这些脏卡表. Update RS的出现, 使GC Worker能够在收集开始之前，把脏卡表中的数据更新到RSet中，以确保每个RSet都是最新的
- [Processed Buffers: Min: 0, Avg: 0.0, Max: 0, Diff: 0, Sum: 0] 这显示了在Update RS期间处理了多少更新缓冲区(包含了脏卡表和日志缓冲区)
- [Scan RS (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0] 扫描每个Region的RSet, 以找到指向Collection Set中所有Region中的对象的外部对象的引用所耗费的时间
- [Code Root Scanning (ms): Min: 0.0, Avg: 0.0, Max: 0.2, Diff: 0.2, Sum: 0.3] 扫描Code Root耗时。Code Root是JIT编译后的代码里引用了heap中的对象
- [Object Copy (ms): Min: 1.0, Avg: 1.2, Max: 1.7, Diff: 0.7, Sum: 10.0] 复制对象所耗费的时间, 在疏散暂停时间, 必须疏散在Collection Set中的所有Region, 复制对象会把所有还活着的对象复制到新的Region中, 新的Region可能是Survivor类型Region，也可能是Old类型Region(如果达到晋升条件的话)
- [Termination (ms): Min: 0.0, Avg: 0.5, Max: 0.6, Diff: 0.6, Sum: 3.8] 当一个GC Worker完成工作, 它会进入一个同步的终止例程, 在那里它与其他工作器同步并尝试窃取未完成的任务. 时间表示从GC Worker第一次尝试终止到实际终止所用的时间 [Termination Attempts: Min: 1, Avg: 11.9, Max: 20, Diff: 19, Sum: 95] 终止尝试的次数, 如果GC Worker成功窃取任务, 它会重新进入终止例程并尝试窃取更多工作或终止, 每次任务被窃取并重新进入终止时，终止尝试的次数将增加
- [GC Worker Other (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.1] GC Worker花费在非上述任务的时间
- [GC Worker Total (ms): Min: 1.7, Avg: 2.0, Max: 2.2, Diff: 0.5, Sum: 15.7] 每个GC Worker花费的时间的最小值、最大值、平均值、差异和总和
- [GC Worker End (ms): Min: 1185.1, Avg: 1185.2, Max: 1185.3, Diff: 0.2] 所有GC Worker工作结束时的时间点, 最小值: 1185.1ms, 平均值: 1185.2ms, 最大值: 1185.3ms, 这三个值, 都是自JVM启动以来的时间戳; Diff: 0.2ms, 表示第一个和最后一个线程结束之间的时间差. 理想情况下，你希望他们同时结束, 也就是Diff越小越好
[Code Root Fixup: 0.0 ms] 遍历指向Collection Set的标记方法以修复在 GC 期间可能移动的指针
[Code Root Purge: 0.0 ms] 清除代码ROOT表中的条目
[Clear CT: 0.2 ms] 清除脏卡表
[Other: 6.7 ms]
- [Choose CSet: 0.0 ms] 选择需要进入Collection Set的Regions耗费的时间
- [Ref Proc: 6.1 ms] 处理 soft/weak/final/phantom/JNI 引用消耗的时间, 建议配置参数：-XX:+ParallelRefProcEnabled（这个参数默认是关闭的），即让这个阶段并行处理
- [Ref Enq: 0.3 ms] 把循环引用排入待处理列表
- [Redirty Cards: 0.3 ms] 把收集过程中修改过的卡表标记为脏
- [Humongous Register: 0.0 ms] G1ReclaimDeadHumongousObjectsAtYoungGC(JDK 8u60后默认启用)参数被启用的话, G1 将尝试在 Young GC 期间急切地收集 Humongous Region, 这里表示评估 Humongous Region 是否是急切回收的候选Region并记录它们所花费的时间
- [Humongous Reclaim: 0.0 ms] 确保Humongous对象死亡和清理，释放Region，重置Region类型并将Region返回到空闲列表并计算释放空间所花费的时间
- [Free CSet: 0.0 ms] 被疏散的区域被添加回空闲列表的时间
[Eden: 4860.0M(4860.0M)->0.0B(4860.0M) Survivors: 52.0M->52.0M Heap: 5466.5M(8192.0M)->607.1M(8192.0M)] 整个Eden区从占用4860.0M到回收后的0.0B，并且GC前后整个Eden区大小没有变化，还是4860.0M; Survivors从52.0M变成52.0M; 整个堆回收前占用5466.5M，回收后占用607.1M，并且整个堆大小是8192.0M：
[Times: user=0.03 sys=0.01, real=0.01 secs] user: CPU工作在用户态所花费的时间; sys: CPU工作在内核态所花费的时间; real: 此次GC事件所花费的总时间

2、并发标记日志分析 #

2021-10-11T10:59:19.764-0800: 4.467: Application time: 0.1068320 seconds
2021-10-11T10:59:19.764-0800: 4.467: [GC pause (G1 Humongous Allocation) (young) (initial-mark), 0.0027074 secs]
   [Parallel Time: 1.0 ms, GC Workers: 13]
      [GC Worker Start (ms): Min: 4467.5, Avg: 4467.7, Max: 4467.8, Diff: 0.3]
      [Ext Root Scanning (ms): Min: 0.0, Avg: 0.3, Max: 0.5, Diff: 0.4, Sum: 3.5]
      [Update RS (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
         [Processed Buffers: Min: 0, Avg: 0.0, Max: 0, Diff: 0, Sum: 0]
      [Scan RS (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
      [Code Root Scanning (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
      [Object Copy (ms): Min: 0.3, Avg: 0.4, Max: 0.5, Diff: 0.2, Sum: 4.6]
      [Termination (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.2]
         [Termination Attempts: Min: 1, Avg: 11.4, Max: 15, Diff: 14, Sum: 148]
      [GC Worker Other (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.2]
      [GC Worker Total (ms): Min: 0.5, Avg: 0.7, Max: 0.8, Diff: 0.3, Sum: 8.5]
      [GC Worker End (ms): Min: 4468.3, Avg: 4468.3, Max: 4468.3, Diff: 0.0]
   [Code Root Fixup: 0.0 ms]
   [Code Root Purge: 0.0 ms]
   [Clear CT: 0.2 ms]
   [Other: 1.5 ms]
      [Choose CSet: 0.0 ms]
      [Ref Proc: 0.4 ms]
      [Ref Enq: 0.0 ms]
      [Redirty Cards: 0.2 ms]
      [Humongous Register: 0.0 ms]
      [Humongous Reclaim: 0.6 ms]
      [Free CSet: 0.0 ms]
   [Eden: 0.0B(2586.0M)->0.0B(3154.0M) Survivors: 2048.0K->2048.0K Heap: 1907.9M(6000.0M)->633.1K(6000.0M)]
 [Times: user=0.01 sys=0.00, real=0.00 secs] 
2021-10-11T10:59:19.767-0800: 4.470: Total time for which application threads were stopped: 0.0029008 seconds, Stopping threads took: 0.0000174 seconds

2021-10-11T10:59:19.767-0800: 4.470: [GC concurrent-root-region-scan-start]
2021-10-11T10:59:19.768-0800: 4.471: [GC concurrent-root-region-scan-end, 0.0003417 secs]
2021-10-11T10:59:19.768-0800: 4.471: [GC concurrent-mark-start]
2021-10-11T10:59:19.768-0800: 4.471: [GC concurrent-mark-end, 0.0003601 secs]

2021-10-11T10:59:19.768-0800: 4.471: Application time: 0.0007241 seconds
2021-10-11T10:59:19.851-0800: 4.554: [GC remark 2021-10-11T10:59:19.851-0800: 4.554: [Finalize Marking, 0.0003405 secs] 2021-10-11T10:59:19.851-0800: 4.554: [GC ref-proc, 0.0000916 secs] 2021-10-11T10:59:19.851-0800: 4.554: [Unloading, 0.0003733 secs], 0.0010369 secs]
 [Times: user=0.00 sys=0.00, real=0.00 secs] 
2021-10-11T10:59:19.852-0800: 4.555: Total time for which application threads were stopped: 0.0840818 seconds, Stopping threads took: 0.0829986 seconds

2021-10-11T10:59:19.852-0800: 4.555: Application time: 0.0000406 seconds
2021-10-11T10:59:19.852-0800: 4.555: [GC cleanup 1907M->1907M(6000M), 0.0010576 secs]
 [Times: user=0.01 sys=0.00, real=0.00 secs] 
2021-10-11T10:59:19.853-0800: 4.556: Total time for which application threads were stopped: 0.0010885 seconds, Stopping threads took: 0.0000052 seconds

2021-10-11T10:59:19.853-0800: 4.556: [GC concurrent-cleanup-start]
2021-10-11T10:59:19.853-0800: 4.556: [GC concurrent-cleanup-end, 0.0000152 secs]

详细分析 #

2021-10-11T10:59:19.764-0800: 4.467: Application time: 0.1068320 seconds
2021-10-11T10:59:19.764-0800: 4.467: [GC pause (G1 Humongous Allocation) (young) (initial-mark), 0.0027074 secs]
...(此处上面已经解析过，省略)
2021-10-11T10:59:19.767-0800: 4.470: Total time for which application threads were stopped: 0.0029008 seconds, Stopping threads took: 0.0000174 seconds

[GC pause (G1 Humongous Allocation) (young) (initial-mark), 0.0027074 secs] 全局并发标记的第一个阶段，即初始化标记，是STW的，是伴随YGC一起发生的，0.0027074表示YGC的耗时

2021-10-11T10:59:19.767-0800: 4.470: [GC concurrent-root-region-scan-start]
2021-10-11T10:59:19.768-0800: 4.471: [GC concurrent-root-region-scan-end, 0.0003417 secs]
2021-10-11T10:59:19.768-0800: 4.471: [GC concurrent-mark-start]
2021-10-11T10:59:19.768-0800: 4.471: [GC concurrent-mark-end, 0.0003601 secs]

[GC concurrent-root-region-scan-start] 开始并发ROOT区域扫描，G1 GC扫描Survivor区直接可达的老年代区域对象，并标记被引用的对象。这一过程必须在young GC之前完成。主要扫描哪些老年代对象是可达的，毕竟我们进行young GC的时候会移动Survivor区，移动之后就找不到哪些老年代对象是可达的了

[GC concurrent-root-region-scan-end, 0.0003417 secs] 结束并发ROOT区域扫描，并统计这个阶段的耗时0.0003417秒

[GC concurrent-mark-start] 开始并发标记，在整个堆中进行并发标记(和应用程序并发执行)，此过程可能被young GC中断([GC concurrent-mark-abort])。在并发标记阶段，若发现区域对象中的所有对象都是垃圾，那这个区域会被立即回收。同时，并发标记过程中，会计算每个区域的对象活性(区域中存活对象的比例)。默认情况下，并发线程数是并行线程数的 25%。也可以通过 -XX:ConcGCThreads 显式设置

[GC concurrent-mark-end, 0.0003601 secs] 结束并发标记，并统计这个阶段的耗时0.0003601秒

2021-10-11T10:59:19.768-0800: 4.471: Application time: 0.0007241 seconds
2021-10-11T10:59:19.851-0800: 4.554: [GC remark 
	2021-10-11T10:59:19.851-0800: 4.554: [Finalize Marking, 0.0003405 secs] 
	2021-10-11T10:59:19.851-0800: 4.554: [GC ref-proc, 0.0000916 secs] 
	2021-10-11T10:59:19.851-0800: 4.554: [Unloading, 0.0003733 secs], 0.0010369 secs]
...(此处上面已经解析过，省略)
2021-10-11T10:59:19.852-0800: 4.555: Total time for which application threads were stopped: 0.0840818 seconds, Stopping threads took: 0.0829986 seconds

[GC remark … , 0.0010369 secs] 再次标记，是STW的，由于应用程序持续进行，需要修正上一次的标记结果。G1中采用了比CMS更快的初始快照算法：snapshot-at-the-beginning (SATB)。并统计这个阶段耗时0.0010369秒

2021-10-11T10:59:19.852-0800: 4.555: Application time: 0.0000406 seconds
2021-10-11T10:59:19.852-0800: 4.555: [GC cleanup 1907M->1907M(6000M), 0.0010576 secs]
...(此处上面已经解析过，省略)
2021-10-11T10:59:19.853-0800: 4.556: Total time for which application threads were stopped: 0.0010885 seconds, Stopping threads took: 0.0000052 seconds

[GC cleanup 1907M->1907M(6000M), 0.0010576 secs] 是STW的。计算各个区域的存活对象和GC回收比例，并进行排序，识别可以混合回收的区域。为下一次mark做铺垫。清理没有活对象的Old Regions和Humongous regions，并清理对应的RSet。根据Old Regions的活跃度进行排序，为了下一个周期作准备

2021-10-11T10:59:19.853-0800: 4.556: [GC concurrent-cleanup-start]
2021-10-11T10:59:19.853-0800: 4.556: [GC concurrent-cleanup-end, 0.0000152 secs]

[GC concurrent-cleanup-start] 并发清理，对上一步处理的空白Region进行最终的清理，随着Region被完全清理，它们被添加到临时列表中。清理完成后，临时列表将合并到辅助空闲Region列表中，等待它们添加回主空闲列表

[GC concurrent-cleanup-end, 0.0000152 secs] 并发清理结束，并统计这个阶段的耗时0.0000152秒

3、混合回收日志分析 #

2021-09-09T01:40:35.929+0800: 51284.606: [GC pause (G1 Evacuation Pause) (mixed), 0.2057858 secs]
   [Parallel Time: 203.0 ms, GC Workers: 8]
      [GC Worker Start (ms): Min: 51284605.7, Avg: 51284605.8, Max: 51284605.9, Diff: 0.2]
      [Ext Root Scanning (ms): Min: 0.8, Avg: 1.0, Max: 1.2, Diff: 0.4, Sum: 7.6]
      [Update RS (ms): Min: 1.0, Avg: 1.2, Max: 1.4, Diff: 0.4, Sum: 9.4]
         [Processed Buffers: Min: 2, Avg: 6.9, Max: 19, Diff: 17, Sum: 55]
      [Scan RS (ms): Min: 0.0, Avg: 0.6, Max: 2.8, Diff: 2.8, Sum: 4.6]
      [Code Root Scanning (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.1]
      [Object Copy (ms): Min: 197.7, Avg: 200.0, Max: 200.6, Diff: 2.9, Sum: 1599.6]
      [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: 8]
      [GC Worker Other (ms): Min: 0.0, Avg: 0.1, Max: 0.1, Diff: 0.0, Sum: 0.4]
      [GC Worker Total (ms): Min: 202.6, Avg: 202.7, Max: 202.8, Diff: 0.2, Sum: 1621.8]
      [GC Worker End (ms): Min: 51284808.5, Avg: 51284808.6, Max: 51284808.6, Diff: 0.0]
   [Code Root Fixup: 0.1 ms]
   [Code Root Purge: 0.0 ms]
   [Clear CT: 0.2 ms]
   [Other: 2.4 ms]
      [Choose CSet: 0.0 ms]
      [Ref Proc: 0.3 ms]
      [Ref Enq: 0.0 ms]
      [Redirty Cards: 1.7 ms]
      [Humongous Register: 0.0 ms]
      [Humongous Reclaim: 0.0 ms]
      [Free CSet: 0.1 ms]
   [Eden: 448.0M(448.0M)->0.0B(6656.0M) Survivors: 768.0M->128.0M Heap: 14.8G(24.0G)->14.7G(24.0G)]
 [Times: user=1.63 sys=0.00, real=0.20 secs]

详细分析 #

2021-09-09T01:40:35.929+0800: 51284.606: [GC pause (G1 Evacuation Pause) (mixed), 0.2057858 secs]
...(省略)

Mixed GC的整个子任务和YGC完全一样，只是回收的范围（CSet）不一样而已，YGC只回收Young区，而Mixed GC回收Young区 + 部分Old区

4、Full GC日志分析 #

2021-10-11T17:55:14.544-0800: 77.036: [Full GC (Allocation Failure)  6000M->5715M(6000M), 0.5855982 secs]
   [Eden: 0.0B(300.0M)->0.0B(300.0M) Survivors: 0.0B->0.0B Heap: 6000.0M(6000.0M)->5715.4M(6000.0M)], [Metaspace: 3025K->3025K(1056768K)]
 [Times: user=0.59 sys=0.00, real=0.59 secs]

详细分析 #

在 G1 中，Full GC 是单线程的 Stop The World (STW) 暂停，它将疏散和压缩所有区域。您可以从 Full GC 日志中获得三个重要信息

GC原因：Allocation Failure，这有助于你进行调整，其他常见的原因有：Metadata GC Threshold、System.gc()
发生频率，几小时几天一次的FGC问题不大，但是几分钟或者分钟多次，则需要重视
Full GC的耗时，如果时间很长，那就需要重视

参考资料 #

尚硅谷视频资料-宋红康详解java虚拟机

Collecting and reading G1 garbage collector logs

深入理解G1的GC日志

Logging stop-the-world pauses in JVM

Analyzing gc logs

How to measure Java GC Stop The World time