JVM GC日志详细分析，ParallelGC和G1

yzh_1346983557

已于 2023-01-17 18:36:55 修改

阅读量4.7k

点赞数 2

分类专栏： JVM 文章标签： jvm.gc gc日志 jvm

于 2021-11-22 13:08:14 首次发布

本文链接：https://blog.csdn.net/yzh_1346983557/article/details/121466736

版权

JVM 专栏收录该内容

5 篇文章 1 订阅

订阅专栏

一、默认垃圾回收器：ParallelGC

jvm启动参数：

-XX:+HeapDumpOnOutOfMemoryError 
-XX:HeapDumpPath=/tmp/heapdump.hprof 
-XX:+PrintGCDetails 
-XX:+PrintGCDateStamps 
-Xloggc:/tmp/gc-%t.log

GC日志：

OpenJDK 64-Bit Server VM (25.282-b08) for bsd-amd64 JRE (1.8.0_282-b08), built on Jan 20 2021 11:47:40 by "jenkins" with gcc 4.2.1 Compatible Apple LLVM 10.0.1 (clang-1001.0.46.4)
Memory: 4k page, physical 16777216k(1307840k free)
 
/proc/meminfo:
 
CommandLine flags: -XX:-BytecodeVerificationLocal -XX:-BytecodeVerificationRemote -XX:+HeapDumpOnOutOfMemoryError -XX:HeapDumpPath=/tmp/heapdump.hprof -XX:InitialHeapSize=268435456 -XX:+ManagementServer -XX:MaxHeapSize=4294967296 -XX:+PrintGC -XX:+PrintGCDateStamps -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:TieredStopAtLevel=1 -XX:+UseCompressedClassPointers -XX:+UseCompressedOops -XX:+UseParallelGC 
2021-11-01T19:40:51.674+0800: 0.784: [GC (Allocation Failure) [PSYoungGen: 65536K->8101K(76288K)] 65536K->8117K(251392K), 0.0058830 secs] [Times: user=0.02 sys=0.01, real=0.01 secs] 
2021-11-01T19:40:51.995+0800: 1.104: [GC (Allocation Failure) [PSYoungGen: 73637K->10732K(76288K)] 73653K->11331K(251392K), 0.0097180 secs] [Times: user=0.04 sys=0.01, real=0.01 secs] 
2021-11-01T19:40:52.089+0800: 1.198: [GC (Metadata GC Threshold) [PSYoungGen: 26096K->6926K(76288K)] 26694K->7533K(251392K), 0.0049565 secs] [Times: user=0.02 sys=0.00, real=0.01 secs] 
2021-11-01T19:40:52.094+0800: 1.203: [Full GC (Metadata GC Threshold) [PSYoungGen: 6926K->0K(76288K)] [ParOldGen: 606K->6641K(101376K)] 7533K->6641K(177664K), [Metaspace: 20192K->20192K(1067008K)], 0.0274601 secs] [Times: user=0.13 sys=0.00, real=0.03 secs] 
2021-11-01T19:40:52.622+0800: 1.731: [GC (Allocation Failure) [PSYoungGen: 65536K->7830K(109056K)] 72177K->14480K(210432K), 0.0060188 secs] [Times: user=0.02 sys=0.01, real=0.00 secs] 
2021-11-01T19:40:53.167+0800: 2.277: [GC (Metadata GC Threshold) [PSYoungGen: 94371K->10737K(139264K)] 101020K->17917K(240640K), 0.0065412 secs] [Times: user=0.03 sys=0.01, real=0.01 secs] 
2021-11-01T19:40:53.174+0800: 2.283: [Full GC (Metadata GC Threshold) [PSYoungGen: 10737K->0K(139264K)] [ParOldGen: 7180K->16648K(172544K)] 17917K->16648K(311808K), [Metaspace: 33567K->33567K(1079296K)], 0.0669463 secs] [Times: user=0.45 sys=0.01, real=0.07 secs]

下面详细分析GC日志信息。

Young GC：GC (Allocation Failure)

2021-11-01T19:40:51.674+0800: 0.784: [GC (Allocation Failure) [PSYoungGen: 65536K->8101K(76288K)] 65536K->8117K(251392K), 0.0058830 secs] [Times: user=0.02 sys=0.01, real=0.01 secs]

1. 2021-11-01T19:40:51.674+0800: 0.784

执行时间戳 + 时区 + jvm启动到当前的时间(秒)

2. GC (Allocation Failure)

GC：进行垃圾回收。

Allocation Failure：给对象分配内存失败，即年轻代没有足够的空间存储新对象。

3. [PSYoungGen: 65536K->8101K(76288K)] 65536K->8117K(251392K), 0.0058830 secs

PSYoungGen: 使用的垃圾回收器的名字。

年轻代GC前 -> 年轻代GC后(年轻代总大小) + 堆GC前 -> 堆GC后(堆的总大小) + 本次GC时间(秒)

堆的总大小，包含年轻代和年老代。

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

时间：用户态耗时 + 内核态耗时 + 真正的总耗时(说明GC是多线程并发执行)

Young GC：GC (Metadata GC Threshold)

2021-11-01T19:40:52.089+0800: 1.198: [GC (Metadata GC Threshold) [PSYoungGen: 26096K->6926K(76288K)] 26694K->7533K(251392K), 0.0049565 secs] [Times: user=0.02 sys=0.00, real=0.01 secs]

重复部分不再赘述。

Metadata GC Threshold：元空间到达阈值进行GC。

Metadata GC Threshold 可能原因：-XX:MetaspaceSize 默认值21M导致元空间不够用引起的GC，所以jvm启动参数中一定要显示声明 -XX:MetaspaceSize 大小，覆盖默认值。

-XX:MetaspaceSize=512M

Full GC (Metadata GC Threshold)

2021-11-01T19:40:52.094+0800: 1.203: [Full GC (Metadata GC Threshold) [PSYoungGen: 6926K->0K(76288K)] [ParOldGen: 606K->6641K(101376K)] 7533K->6641K(177664K), [Metaspace: 20192K->20192K(1067008K)], 0.0274601 secs] [Times: user=0.13 sys=0.00, real=0.03 secs]

1. Full GC (Metadata GC Threshold)

Full GC：全GC，包含年轻代、年老代和元空间。

2. [ParOldGen: 606K->6641K(101376K)] 7533K->6641K(177664K)

ParOldGen：使用的垃圾回收器的名字。

年老代GC前 -> 年老代GC后(年老代总大小) + 堆GC前大小 -> 堆GC后大小(堆的总大小)。

3. [Metaspace: 20192K->20192K(1067008K)]

元空间：GC前大小 -> GC后大小(元空间总大小)

Full GC (Heap Inspection Initiated GC)

2021-11-01T21:01:33.217+0800: 4842.275: [GC (Heap Inspection Initiated GC) [PSYoungGen: 76271K->5961K(164352K)] 92919K->22681K(336896K), 0.0302703 secs] [Times: user=0.06 sys=0.07, real=0.03 secs] 
2021-11-01T21:01:33.248+0800: 4842.305: [Full GC (Heap Inspection Initiated GC) [PSYoungGen: 5961K->0K(164352K)] [ParOldGen: 16720K->15373K(229376K)] 22681K->15373K(393728K), [Metaspace: 39135K->38916K(1085440K)], 0.1303204 secs] [Times: user=0.42 sys=0.09, real=0.13 secs]

Heap Inspection Initiated GC(堆检查启动的GC)：使用了jmap -histo:live 命令导致的Full GC。

Full GC (Heap Dump Initiated GC)

2021-11-02T10:52:48.703+0800: 1189.751: [Full GC (Heap Dump Initiated GC) [PSYoungGen: 438K->0K(4608K)] [ParOldGen: 13507K->13335K(13824K)] 13945K->13335K(18432K), [Metaspace: 40906K->40901K(1087488K)], 0.0482085 secs] [Times: user=0.33 sys=0.00, real=0.05 secs]

执行 jmap -dump:live 触发的FullGC。

Full GC (System.gc())

2021-11-02T10:46:04.307+0800: 785.354: [Full GC (System.gc()) [PSYoungGen: 867K->0K(4608K)] [ParOldGen: 13691K->13507K(13824K)] 14559K->13507K(18432K), [Metaspace: 40906K->40906K(1087488K)], 0.0937626 secs] [Times: user=0.68 sys=0.00, real=0.10 secs]

没有配置-XX:+DisableExplicitGC情况下，代码 System.gc() 触发的FullGC。

Full GC (Ergonomics)

2021-11-02T10:35:25.797+0800: 146.844: [Full GC (Ergonomics) [PSYoungGen: 2521K->0K(4608K)] [ParOldGen: 13138K->13222K(13824K)] 15659K->13222K(18432K), [Metaspace: 39515K->39515K(1085440K)], 0.0205221 secs] [Times: user=0.09 sys=0.00, real=0.02 secs]

Ergonomics：“人体工程学”，jvm中是自适应调整的意思。默认开启了UseAdaptiveSizePolicy，jvm自动调解gc暂停时间和吞吐量之间的平衡，进行自适应调整引发的gc。

默认 Server 模式下的ParallelGC 收集器组合（Parallel Scavenge + Parallel Old），会在 Minor GC前进行一次判断，也就是 内存空间分配担保机制：

Eden 空间不足发生 Minor GC 之前，虚拟机先检查老年代最大可用的连续空间是否大于新生代所有对象总空间，如果条件成立的话，那么 Minor GC 可以确认是安全的。如果不成立的话虚拟机查看 HandlePromotionFailure 的值是否允许担保失败，如果允许则检查老年代最大可用的连续空间是否大于历次晋升到老年代对象的平均大小，如果大于将继续尝试进行 Minor GC。如果小于或者 HandlePromotionFailure 的值不允许冒险，那么就要进行一次 Full GC。

但是JDK7及以后 HandlePromotionFailure 就失效了。规则变为：只要老年代的连续空间大于新生代对象的总大小或者历次晋升到老年代的对象的平均大小就进行MinorGC，否则FullGC。

Parallel Scavenge是一款注重吞吐量的收集器：Parallel Scavenge的目标是达到一个可控的吞吐量，吞吐量=程序运行时间/（程序运行时间+GC时间），如程序运行了99s，GC耗时1s，吞吐量=99/（99+1）=99%。Parallel Scavenge提供了两个参数用以精确控制吞吐量，分别是用以控制最大GC停顿时间的-XX:MaxGCPauseMillis及直接控制吞吐量的参数-XX:GCTimeRatio。

手动触发Full GC：jmap

jmap -histo:live PID | head -50

or 

jmap -histo:live PID | more

or

jmap -dump:format=b,live,file=heapdump.hprof PID

查看GC统计信息：jstat

jstat -gc pid

// GC统计信息，可重点关注后5个参数：YGC、YGCT、FGC、FGCT、GCT
 S0C    S1C    S0U    S1U      EC       EU        OC         OU       MC     MU    CCSC   CCSU   YGC     YGCT    FGC    FGCT     GCT   
13312.0 13312.0  0.0    0.0   151040.0  1290.0   229376.0   15373.1   41728.0 38916.3 5632.0 5133.5      6    0.063   3      0.225    0.288

垃圾回收器G1

G1下jvm内存布局：

H 它代表 Humongous，其存储的是巨型对象。当新建对象大小超过 Region 大小一半时，直接在新的一个或多个连续 Region 中分配，并标记这些Region为 H。

jvm启动参数：

-Xms100m  
-Xmx100m  
-XX:MetaspaceSize=512M  
-XX:MaxDirectMemorySize=1024M 
-Xss256k 
-XX:+UseG1GC  
-XX:MaxGCPauseMillis=200 
-XX:+HeapDumpOnOutOfMemoryError 
-XX:HeapDumpPath=/tmp/heapdump.hprof 
-XX:+PrintGCDetails 
-XX:+PrintGCDateStamps 
-Xloggc:/tmp/gc-%t.log 
-Duser.timezone=Asia/Shanghai  
-Dfile.encoding=UTF-8

GC pause (G1 Evacuation Pause) (young)

2021-11-02T18:03:27.713+0800: 0.523: [GC pause (G1 Evacuation Pause) (young), 0.0035728 secs]
   [Parallel Time: 2.0 ms, GC Workers: 10]
      [GC Worker Start (ms): Min: 523.0, Avg: 523.1, Max: 523.1, Diff: 0.1]
      [Ext Root Scanning (ms): Min: 0.1, Avg: 0.3, Max: 1.4, Diff: 1.3, Sum: 3.2]
      [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.2, Diff: 0.2, Sum: 0.4]
      [Object Copy (ms): Min: 0.5, Avg: 1.5, Max: 1.7, Diff: 1.2, Sum: 14.8]
      [Termination (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.2]
         [Termination Attempts: Min: 1, Avg: 25.6, Max: 35, Diff: 34, Sum: 256]
      [GC Worker Other (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.2]
      [GC Worker Total (ms): Min: 1.8, Avg: 1.9, Max: 1.9, Diff: 0.1, Sum: 18.8]
      [GC Worker End (ms): Min: 524.9, Avg: 524.9, Max: 524.9, Diff: 0.0]
   [Code Root Fixup: 0.0 ms]
   [Code Root Purge: 0.0 ms]
   [Clear CT: 0.1 ms]
   [Other: 1.5 ms]
      [Choose CSet: 0.0 ms]
      [Ref Proc: 1.3 ms]
      [Ref Enq: 0.0 ms]
      [Redirty Cards: 0.1 ms]
      [Humongous Register: 0.0 ms]
      [Humongous Reclaim: 0.0 ms]
      [Free CSet: 0.0 ms]
   [Eden: 24576.0K(24576.0K)->0.0B(36864.0K) Survivors: 0.0B->3072.0K Heap: 24576.0K(100.0M)->3466.0K(100.0M)]
 [Times: user=0.02 sys=0.00, real=0.00 secs]

整体结构抽取一下：

GC pause (G1 Evacuation Pause) (young)    // 本次GC总耗时
  ├── Parallel Time    // GC线程并行回收耗时
    ├── GC Worker Start      
    ├── Ext Root Scanning    // 扫描 root 的线程耗时
    ├── Update RS            // 更新 RS 
    ├── Scan RS              // 扫描 RS                
    ├── Code Root Scanning   // 根扫描耗时
    ├── Object Copy          // 对象拷贝
    ├── GC Worker Other      // GC 线程其它耗时
    ├── GC Worker Total      // GC 线程总耗时
    ├── GC Worker End    
  ├── Code Root Fixup
  ├── Code Root Purge
  ├── Clear CT       // 清空 CardTable 耗时，RS 是依赖 CardTable 记录区域存活对象的
  ├── Other          // 其它耗时
    ├── Choose CSet         // 选取 CSet
    ├── Ref Proc            // 弱引用、软引用的处理耗时
    ├── Ref Enq             // 弱引用、软引用的入队耗时
    ├── Redirty Cards
    ├── Humongous Register
    ├── Humongous Reclaim
    ├── Free CSet           // 释放被回收区域的耗时

G1 young GC流程总结：

G1 young GC总耗时 = GC线程并行回收耗时 + 清空 CardTable 耗时 + 其它耗时。

从上方GC日志数据可得到以下结论：

1. GC总耗时时间主要花费在 GC线程并行回收耗时和其它耗时这2个阶段。

2. GC线程并行回收耗时时间主要花费在扫描root的线程耗时和对象copy 这2个阶段。

3. 其它耗时时间主要花费在引用的处理耗时阶段。

总结：GC总耗时时间主要花费在扫描root的线程耗时、对象copy、引用的处理耗时这3个小阶段。G1 young GC是stop the world的。

下面详细分析 G1 的GC日志。

2021-11-02T18:03:27.713+0800: 0.523: [GC pause (G1 Evacuation Pause) (young), 0.0035728 secs]

执行日期+时区+Jvm启动时间(秒)+GC暂停+G1疏散暂停+年轻代GC+消耗总时间(秒)。

G1 Evacuation Pause：G1疏散暂停，把存活的对象拷贝到1个或多个Region中，目标Region可能是Young区，也可能是Young区+Old区，取决于这次YGC是否有晋升到Old区的对象。

Evacuation：中文直译为疏散、撤离，G1中可理解为转移，将对象转移到其它Region中。

[Parallel Time: 2.0 ms, GC Workers: 10]

GC线程并发执行时间2.0ms + 并发GC线程数10个。

[Clear CT: 0.1 ms]

清空 CardTable 耗时0.1ms。

[Other: 1.5 ms]

其它耗时1.5ms。

[Eden: 24576.0K(24576.0K)->0.0B(36864.0K) Survivors: 0.0B->3072.0K Heap: 24576.0K(100.0M)->3466.0K(100.0M)]

Eden区：GC前大小(GC前总大小) -> GC后大小(GC后总大小)

Survivors区：GC前大小 -> GC后大小

Heap区：GC前大小(GC前总大小) -> GC后大小(GC后总大小)

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

用户空间耗时+内核空间耗时+真正GC耗时

Global Concurrent Marking（并发标记）

作用：标记老年代region，提供统计结果供Mixed GC使用，选取收益高的老年代region回收，帮助回收老年代对象。

当堆内存的总体使用比例达到一定数值时，就会触发并发标记。这个默认比例是 45%，但也可以通过 JVM 参数 InitiatingHeapOccupancyPercent 来设置。

阶段 1：Initial Mark（初始标记）

阶段 2：Root Region Scan（Root 区扫描）。此阶段标记所有从“根区域”可达的存活对象。

阶段 3：Concurrent Mark（并发标记）

阶段 4：Remark（再次标记）

阶段 5：Cleanup（清理）
最后这个清理阶段为即将到来的转移阶段做准备，统计标记的Region中所有存活的对象，并将标记的Region进行排序，以提升 GC 的效率。此阶段也为下一次标记执行必需的整理工作（house-keeping activities）——维护并发标记的内部状态。所有不包含存活对象的Region在此阶段都被回收了。

2021-11-18T17:43:33.112+0800: 433.473: [GC pause (G1 Humongous Allocation) (young) (initial-mark), 0.0094487 secs]
   [Parallel Time: 7.6 ms, GC Workers: 10]
      [GC Worker Start (ms): Min: 433473.5, Avg: 433473.6, Max: 433473.7, Diff: 0.1]
      [Ext Root Scanning (ms): Min: 0.7, Avg: 0.8, Max: 0.9, Diff: 0.2, Sum: 7.7]
      [Update RS (ms): Min: 0.4, Avg: 1.2, Max: 3.7, Diff: 3.3, Sum: 11.9]
         [Processed Buffers: Min: 1, Avg: 2.1, Max: 3, Diff: 2, Sum: 21]
      [Scan RS (ms): Min: 0.0, Avg: 0.2, Max: 0.4, Diff: 0.4, Sum: 1.9]
      [Code Root Scanning (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.1]
      [Object Copy (ms): Min: 2.7, Avg: 5.0, Max: 5.9, Diff: 3.2, Sum: 50.1]
      [Termination (ms): Min: 0.0, Avg: 0.1, Max: 0.1, Diff: 0.1, Sum: 1.0]
         [Termination Attempts: Min: 1, Avg: 160.1, Max: 195, Diff: 194, Sum: 1601]
      [GC Worker Other (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.1]
      [GC Worker Total (ms): Min: 7.2, Avg: 7.3, Max: 7.4, Diff: 0.1, Sum: 72.8]
      [GC Worker End (ms): Min: 433480.9, Avg: 433480.9, Max: 433480.9, Diff: 0.0]
   [Code Root Fixup: 0.0 ms]
   [Code Root Purge: 0.0 ms]
   [Clear CT: 0.1 ms]
   [Other: 1.8 ms]
      [Choose CSet: 0.0 ms]
      [Ref Proc: 0.9 ms]
      [Ref Enq: 0.0 ms]
      [Redirty Cards: 0.1 ms]
      [Humongous Register: 0.0 ms]
      [Humongous Reclaim: 0.0 ms]
      [Free CSet: 0.0 ms]
   [Eden: 12288.0K(31744.0K)->0.0B(29696.0K) Survivors: 5120.0K->5120.0K Heap: 66134.6K(100.0M)->56382.0K(100.0M)]
 [Times: user=0.07 sys=0.00, real=0.01 secs] 
2021-11-18T17:43:33.121+0800: 433.482: [GC concurrent-root-region-scan-start]
2021-11-18T17:43:33.123+0800: 433.484: [GC concurrent-root-region-scan-end, 0.0018936 secs]
2021-11-18T17:43:33.123+0800: 433.484: [GC concurrent-mark-start]
2021-11-18T17:43:33.135+0800: 433.496: [GC concurrent-mark-end, 0.0118927 secs]
2021-11-18T17:43:33.135+0800: 433.496: [GC remark 2021-11-18T17:43:33.135+0800: 433.496: [Finalize Marking, 0.0002043 secs] 2021-11-18T17:43:33.135+0800: 433.497: [GC ref-proc, 0.0016572 secs] 2021-11-18T17:43:33.137+0800: 433.498: [Unloading, 0.0039254 secs], 0.0061435 secs]
 [Times: user=0.03 sys=0.00, real=0.01 secs] 
2021-11-18T17:43:33.142+0800: 433.503: [GC cleanup 58301K->43965K(100M), 0.0008515 secs]
 [Times: user=0.01 sys=0.00, real=0.00 secs] 
2021-11-18T17:43:33.142+0800: 433.504: [GC concurrent-cleanup-start]
2021-11-18T17:43:33.142+0800: 433.504: [GC concurrent-cleanup-end, 0.0000188 secs]

G1 Concurrent Marking流程总结：

G1 Concurrent Marking总耗时 = 初始标记耗时(young GC) + 并发根区域扫描耗时 + 并发标记耗时 + 重新标记耗时 + 并发清理耗时。

初始标记、重新标记和并发清理是需要stop the world(STW)的，并发根区域扫描和并发标记是不需要STW的。初始标记虽然STW，但是它同时伴随着young GC的进行，回收了年轻代的eden区。

下面详细分析GC日志。

[GC pause (G1 Humongous Allocation) (young) (initial-mark), 0.0094487 secs]

GC暂停 + G1巨大(对象)分配 + 年轻代GC + 初始标记 + 消耗时间9.4ms。

G1 Humongous Allocation：G1在进行巨大对象的分配时会检查堆内存的占用是否达到Concurrent Marking的阈值45%，如果达到则进行Concurrent Marking。

如果某个对象超过单个 Region 空间的一半，则会被 G1 视为巨型对象，巨型对象会直接分配到老年代的 Humongous 区。如果Region包含巨型对象，则区域中最后一个巨型对象与Region末尾之间的空间将不会使用。如果所有巨大的对象只是比Region的50%大一点，那么这些未使用的空间会导致堆变得碎片化。如果有大量Humongous Allocation触发的GC，老年代可能会形成大量的内存碎片。解决：可增加 -XX:G1HeapRegionSize，即让对象小于 Region 的 50%，让之前的大对象不再被直接分配到 Humongous 区，而是走常规的对象分配方式。但是 -XX:G1HeapRegionSize这个参数需要设置为2的幂次方，最小值是1M，最大值是32M。

initial-mark：初始标记，和young GC是同步进行的，所以也称为第一次回收。

[GC concurrent-root-region-scan-start]

GC 并发根区域的扫描开始。

[GC concurrent-root-region-scan-end, 0.0014241 secs]

GC 并发根区域的扫描结束，耗时1.4ms

[GC concurrent-mark-start]

GC 并发标记开始。

[GC concurrent-mark-end, 0.0163857 secs]

GC 并发标记结束，耗时16.3ms。

[GC remark 2021-11-18T17:43:34.676+0800: 435.037: [Finalize Marking, 0.0006953 secs] 2021-11-18T17:43:34.676+0800: 435.037: [GC ref-proc, 0.0013824 secs] 2021-11-18T17:43:34.678+0800: 435.039: [Unloading, 0.0036554 secs], 0.0059840 secs]

GC 重新标记时间戳：[最终标记，耗时] + 时间戳：[GC 引用-处理，耗时] + 时间戳：[卸载，耗时] + 总耗时5.9ms。

[GC cleanup 52836K->47961K(100M), 0.0006854 secs]

GC 清理清理前堆大小52.8M -> 清理后堆大小47.9M(总大小100M)，耗时0.6ms。

[GC concurrent-cleanup-start]

GC 并发清理开始。

[GC concurrent-cleanup-end, 0.0000113 secs]

GC 并发清理结束，耗时0.01ms。

GC pause (G1 Evacuation Pause) (mixed)

Mixed GC是回收所有年轻代 Region + 部分老年代 Region，Mixed GC是stop the world(STW)的。

2021-11-18T17:43:35.098+0800: 435.459: [GC pause (G1 Evacuation Pause) (mixed), 0.0130780 secs]
   [Parallel Time: 11.6 ms, GC Workers: 10]
      [GC Worker Start (ms): Min: 435459.4, Avg: 435459.5, Max: 435459.5, Diff: 0.1]
      [Ext Root Scanning (ms): Min: 0.1, Avg: 0.2, Max: 0.8, Diff: 0.7, Sum: 2.5]
      [Update RS (ms): Min: 1.0, Avg: 1.4, Max: 1.6, Diff: 0.6, Sum: 14.2]
         [Processed Buffers: Min: 2, Avg: 2.6, Max: 4, Diff: 2, Sum: 26]
      [Scan RS (ms): Min: 1.4, Avg: 1.6, Max: 2.1, Diff: 0.8, Sum: 15.7]
      [Code Root Scanning (ms): Min: 0.0, Avg: 0.0, Max: 0.2, Diff: 0.2, Sum: 0.5]
      [Object Copy (ms): Min: 7.6, Avg: 8.1, Max: 8.4, Diff: 0.8, Sum: 81.4]
      [Termination (ms): Min: 0.0, Avg: 0.1, Max: 0.1, Diff: 0.1, Sum: 0.8]
         [Termination Attempts: Min: 1, Avg: 140.2, Max: 177, Diff: 176, Sum: 1402]
      [GC Worker Other (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.1]
      [GC Worker Total (ms): Min: 11.5, Avg: 11.5, Max: 11.6, Diff: 0.1, Sum: 115.2]
      [GC Worker End (ms): Min: 435471.0, Avg: 435471.0, Max: 435471.0, Diff: 0.0]
   [Code Root Fixup: 0.0 ms]
   [Code Root Purge: 0.0 ms]
   [Clear CT: 0.1 ms]
   [Other: 1.3 ms]
      [Choose CSet: 0.0 ms]
      [Ref Proc: 1.1 ms]
      [Ref Enq: 0.0 ms]
      [Redirty Cards: 0.1 ms]
      [Humongous Register: 0.0 ms]
      [Humongous Reclaim: 0.0 ms]
      [Free CSet: 0.1 ms]
   [Eden: 1024.0K(1024.0K)->0.0B(4096.0K) Survivors: 6144.0K->1024.0K Heap: 51938.3K(100.0M)->47228.9K(100.0M)]
 [Times: user=0.12 sys=0.01, real=0.02 secs]

[GC pause (G1 Evacuation Pause) (mixed), 0.0130780 secs]

GC暂停 + G1疏散暂停 + 混合模式 + 总耗时13ms。

mixed混合GC总耗时 = 线程并行回收耗时 + 清空 CardTable 耗时 + 其它耗时(引用的处理耗时)。

可看到G1 Mixed GC和young GC在真正执行GC时步骤是大致相同的，都是会stop the world，主要区别在于Mixed GC会回收部分Old Region，且Mixed GC在GC前会经历若干次Concurrent Marking以达到可控的GC时间。

[GC pause (G1 Evacuation Pause) (young) (to-space exhausted), 0.0091829 secs]

[GC pause (G1 Evacuation Pause) (mixed) (to-space exhausted), 0.0068124 secs]

to-space：年轻代的幸存者区域 or 年老代。

to-space exhausted：空间耗尽。没有足够的内存用于幸存对象或提升对象，或两者兼而有之，且Java 堆已达到最大值无法扩展。

G1总结：

G1提供了young GC和Mixed GC，两种都是完全Stop The World的，没有提供Full GC。当G1无法回收出足够内存时，JVM会切换为 Serial Old进行Full GC，这时的Full GC会占用大量时间。

* Young GC：选定所有年轻代里的Region。通过控制年轻代的region个数，即年轻代内存大小，来控制young GC的时间开销。

* Mixed GC：选定所有年轻代里的Region，外加根据global concurrent marking统计得出收集收益高的若干老年代Region。在用户指定的开销目标范围内尽可能选择收益高的老年代Region。global concurrent marking，在G1 GC中，它主要是为Mixed GC提供标记服务的，并不是一次GC过程的一个必须环节。

深入理解G1的GC日志-Java知音

Java Hotspot G1 GC的一些关键技术 - 美团技术团队

《Java 虚拟机原理》5.3 G1 原理剖析及日志分析 - 知乎