JVM系列(十六) 垃圾收集器之 G1 YoungGC日志及过程分析今天我们着重讲解一下G1的GC日志，我们根据GC日志

1.G1垃圾收集器日志分析

前面我们讲解了G1垃圾收集器的阶段及原理包括Region的分区，YoungGC及MixedGC的发生场景，今天我们着重讲解一下G1的GC日志，我们到底能从GC日志中分析出来哪些有用的东西，方便我们在项目中进行JVM调优

1.1 设置JVM参数，运行程序

设置JVM参数,使用G1垃圾收集器 -XX:+UseG1GC

-verbose:gc -XX:+UseG1GC -Xms10M -Xmx10M  -XX:+PrintGC -XX:+PrintGCDetails -XX:+HeapDumpOnOutOfMemoryError -XX:SurvivorRatio=8

程序如下：

package com.jzj.jvmtest.jvmready;

import lombok.extern.slf4j.Slf4j;

@Slf4j
public class G1Test {

    //JVM 参数 -verbose:gc -Xms10M -Xmx10M  -XX:+PrintGC -XX:+PrintGCDetails -XX:+HeapDumpOnOutOfMemoryError -XX:SurvivorRatio=8
    public static void main(String[] args) throws Exception {
        byte[] b = null;
        for (int i = 1; i <= 10; i++) {
            //设置 3M的对象
            log.info("======== " + i + "次添加3M对象");
            b = new byte[1 * 1024 * 1024];
            Thread.sleep(100);

        }
    }
}

1.2 GC日志打印

执行程序最终OOM，并且打印了GC日志，我们逐步来分析下每一个GC日志的步骤

[GC pause (G1 Evacuation Pause) (young), 0.0026083 secs]
   [Parallel Time: 1.2 ms, GC Workers: 10]
      [GC Worker Start (ms): Min: 308.9, Avg: 308.9, Max: 309.2, Diff: 0.3]
      [Ext Root Scanning (ms): Min: 0.0, Avg: 0.3, Max: 0.6, Diff: 0.6, Sum: 2.6]
      [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.1, Diff: 0.1, Sum: 0.1]
      [Object Copy (ms): Min: 0.5, Avg: 0.8, Max: 1.0, Diff: 0.5, Sum: 8.2]
      [Termination (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
         [Termination Attempts: Min: 1, Avg: 11.8, Max: 18, Diff: 17, Sum: 118]
      [GC Worker Other (ms): Min: 0.0, Avg: 0.0, Max: 0.1, Diff: 0.0, Sum: 0.3]
      [GC Worker Total (ms): Min: 0.9, Avg: 1.1, Max: 1.2, Diff: 0.3, Sum: 11.2]
      [GC Worker End (ms): Min: 310.1, Avg: 310.1, Max: 310.1, 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.0 ms]
   [Eden: 6144.0K(6144.0K)->0.0B(5120.0K) Survivors: 0.0B->1024.0K Heap: 6144.0K(10.0M)->1625.5K(10.0M)]
 [Times: user=0.16 sys=0.00, real=0.00 secs] 
23:46:36.458 [main] INFO com.jzj.jvmtest.jvmready.G1Test - ======== 1次添加3M对象
23:46:36.575 [main] INFO com.jzj.jvmtest.jvmready.G1Test - ======== 2次添加3M对象
===================================================================================
=====================  下面是 并发标记 周期 initial-mark ===========================
===================================================================================

2.GC日志分析

对于上面的日志，我们来逐行看下每个阶段到底干了什么事情

2.1 G1 YoungGC处理及日志分析

GC pause (G1 Evacuation Pause) (young), 0.0026083 secs
- 表示G1转移暂停，YoungGC，持续时间 0.0026083 secs，系统暂定 0.0026083 secs
Parallel Time: 1.2 ms, GC Workers: 10
- 并行开始收集任务，一共由10个GC线程，从新生代垃圾收集到最后一个任务结束一共耗时1.2ms，该过程STW
GC Worker Start (ms): Min: 308.9, Avg: 308.9, Max: 309.2, Diff: 0.3
- GC开始工作， min指的是第一个垃圾收集线程开始工作时，JVM启动后经过的时间， max指的时最后一个垃圾收集器开始工作时，JVM启动后经过的时间，diff指的是min和max的差值，avg表示平均值，理想情况下，我们希望多个线程是同时开始的，即最好的情况是diff=0
Ext Root Scanning (ms): Min: 0.0, Avg: 0.3, Max: 0.6, Diff: 0.6, Sum: 2.6
- 根扫描的耗时时间，每一个GC线程在处理根扫描（全局变量，系统数据字典，线程栈等），所花费的时间，min 最小时间，max最大时间，Sum表示所有线程花费的总时间，尝试找到所有root集合中的节点指向当前的收集集合（CSet）
Update RS (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0
- 更新记忆集Rset的耗时时间，每个分区都有自己的Rset，用过来记录其他分区指向当前分区的指针，如果Rset有更新，新的引用的card卡表会被标记为dirty，放入日志缓冲区，Update RS 表示允许垃圾处理GC线程处理本次垃圾收集前，没有处理好的日志缓冲区，这样可以证当前分区的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]
- 扫描每个新生代分区的RSet耗时，找出有多少指向当前分区的引用来自CSet
Code Root Scanning (ms): Min: 0.0, Avg: 0.0, Max: 0.1, Diff: 0.1, Sum: 0.1]
- Code Root 表示代码中的局部变量的Root节点，code root指经过JIT编译后的代码里，引用了heap中的对象，引用关系保存在RSet中，该过程就是扫描这部分Root节点所花费的时间，为了减少扫描时间，这个阶段只扫描CSet中region的Reset来查看是否有被code root引用的关系。
Object Copy (ms): Min: 0.5, Avg: 0.8, Max: 1.0, Diff: 0.5, Sum: 8.2
- 疏散暂停时间，所有Cset的Region分区，全都要被疏散转移，需要拷贝CSet集合里面所有分区存活对象到新分区Survivor/Old区。所有存活的对象会被复制到thread-local GC allocated buffers（GCLABS）中，GCLABS在目标region中进行分配。
Termination (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
- 当一个垃圾收集线程完成任务时，它就会进入一个临界区，并尝试帮助其他垃圾线程完成任务（steal outstanding tasks）偷其他线程的任务。min表示该垃圾收集线程什么时候尝试terminatie，max表示该垃圾收集回收线程什么时候真正terminated终止
Termination Attempts: Min: 1, Avg: 11.8, Max: 18, Diff: 17, Sum: 118]
- 如果一个垃圾收集线程成功偷取了其他线程的任务，那么它会再次偷取更多的任务，每次重新terminate的时候，这个数值就会增加。
GC Worker Other (ms): Min: 0.0, Avg: 0.0, Max: 0.1, Diff: 0.0, Sum: 0.3]
- GC线程花费在其他工作上（上面都没计算在内的其他）的时间。
GC Worker Total (ms): Min: 0.9, Avg: 1.1, Max: 1.2, Diff: 0.3, Sum: 11.2]
- 汇总展示每个垃圾收集线程的最小、最大、平均、差值和总共时间。
GC Worker End (ms): Min: 310.1, Avg: 310.1, Max: 310.1, Diff: 0.0]
- 汇总线程结束时间。min表示最早结束的垃圾收集线程结束时该JVM启动后的时间；max表示最晚结束的垃圾收集线程结束时该JVM启动后的时间。理想情况下，最好是同一时间结束。

串行执行的步骤

[Code Root Fixup: 0.0 ms]
- 用来将code root修正到正确的回收之后的对象位置所花费的时间。串行执行。
[Code Root Purge: 0.0 ms]
- 清理code root的数据结构。串行执行。
[Clear CT: 0.1 ms]
- 清理 Card Table的耗时，串行执行。
[Other: 1.3 ms] 其他事项耗时。串行执行。
- [Choose CSet: 0.0 ms] 选择要进行回收的分区放入CSet，选择回收分区的时
- [Ref Proc: 1.1 ms] 处理Java中的各种引用如Soft/Weak 弱引用，软引用时间
- [Ref Enq: 0.0 ms] 遍历所有的引用，将不能回收的放入pending队列ReferenceQueues，处理入队时间
- [Redirty Cards: 0.1 ms] 在回收过程中被修改的Card将会被重置为dirty。
- [Humongous Register: 0.0 ms] 巨型对象可以在新生代收集的时候被回收。
- [Humongous Reclaim: 0.0 ms] 确保巨型对象可以被回收，释放该巨型对象所占的分区，重置分区类型，并将分区还到free-list列表，并且更新空闲空间大小。
- [Free CSet: 0.0 ms] 释放CSet中的分区到空闲列表free-list。

Eden: 6144.0K(6144.0K)->0.0B(5120.0K) Survivors: 0.0B->1024.0K Heap: 6144.0K(10.0M)->1625.5K(10.0M) [Times: user=0.16 sys=0.00, real=0.00 secs]

到这里就是我们熟悉的部分

Eden区GC回收前使用6144K(回收前总大小6144K)->回收后大小使用0.0B(Eden区回收后总大小5120K)
suivivors区GC回收前大小0.0B->回收后大小1024K
整堆HEAP回收前使用6144K(整堆大小10M)->回收后整堆使用1625.5K(总堆大小10M) 4.user是用户态总共占用cpu时间（多线程并行执行算总和），sys是系统内核的总共占用cpu时间，real是wall clock time

3.全局并发标记

3.1 GC日志全局并发周期

G1的YoungGC完成之后，下一步就开始全局并发标记，G1的全局并发标记周期主要包括如下几个过程：

1 初始标记(initial mark)
2 根扫描(Root region scanning)
3 并发标记(concurrent marking)
4 最终标记(remark)
5 清理(cleanup)

[GC pause (G1 Humongous Allocation) (young) (initial-mark), 0.0013339 secs]
   [Parallel Time: 1.0 ms, GC Workers: 10]
      [GC Worker Start (ms): Min: 453.9, Avg: 454.0, Max: 454.0, Diff: 0.1]
      [Ext Root Scanning (ms): Min: 0.2, Avg: 0.3, Max: 0.3, Diff: 0.1, Sum: 2.8]
      [Update RS (ms): Min: 0.0, Avg: 0.1, Max: 0.5, Diff: 0.5, Sum: 0.9]
         [Processed Buffers: Min: 0, Avg: 1.1, Max: 2, Diff: 2, Sum: 11]
      [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.1, Diff: 0.1, Sum: 0.1]
      [Object Copy (ms): Min: 0.1, Avg: 0.4, Max: 0.5, Diff: 0.5, Sum: 4.2]
      [Termination (ms): Min: 0.0, Avg: 0.0, Max: 0.1, Diff: 0.1, Sum: 0.4]
         [Termination Attempts: Min: 1, Avg: 13.5, Max: 21, Diff: 20, Sum: 135]
      [GC Worker Other (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.1]
      [GC Worker Total (ms): Min: 0.8, Avg: 0.8, Max: 0.9, Diff: 0.1, Sum: 8.4]
      [GC Worker End (ms): Min: 454.8, Avg: 454.8, Max: 454.8, Diff: 0.0]
   [Code Root Fixup: 0.0 ms]
   [Code Root Purge: 0.0 ms]
   [Clear CT: 0.1 ms]
   [Other: 0.3 ms]
      [Choose CSet: 0.0 ms]
      [Ref Proc: 0.2 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: 1024.0K(5120.0K)->0.0B(3072.0K) Survivors: 1024.0K->1024.0K Heap: 4584.0K(10.0M)->3766.6K(10.0M)]
 [Times: user=0.00 sys=0.00, real=0.00 secs] 
[GC concurrent-root-region-scan-start]
[GC concurrent-root-region-scan-end, 0.0004062 secs]
[GC concurrent-mark-start]
[GC concurrent-mark-end, 0.0020466 secs]
[GC remark [Finalize Marking, 0.0001629 secs] [GC ref-proc, 0.0000789 secs] [Unloading, 0.0006677 secs], 0.0010284 secs]
 [Times: user=0.00 sys=0.00, real=0.00 secs] 
[GC cleanup 4790K->4790K(10M), 0.0005226 secs]
 [Times: user=0.00 sys=0.00, real=0.00 secs]

3.1 全局并发标记周期日志分析（concurrent marking cycle）

我们下面看下这个过程的GC日志

[GC pause (G1 Humongous Allocation) (young) (initial-mark), 0.0018078 secs]
- GC暂停，暂停原因是大对象分配，在全局并发标记阶段
[Parallel Time: 1.2 ms, GC Workers: 10]
- 并行收集任务，此过程STW，耗时1.2ms，GC垃圾回收的线程数是10
[GC Worker Start (ms): Min: 445.7, Avg: 445.7, Max: 445.7, Diff: 0.1]
- GC开始工作， min指的是第一个垃圾收集线程开始工作时，JVM启动后经过的时间， max指的时最后一个垃圾收集器开始工作时，JVM启动后经过的时间，diff指的是min和max的差值，avg表示平均值，理想情况下，我们希望多个线程是同时开始的，即最好的情况是diff=0
[Ext Root Scanning (ms): Min: 0.3, Avg: 0.3, Max: 0.4, Diff: 0.1, Sum: 3.1]
- 扫描的耗时时间，每一个GC线程在处理根扫描（全局变量，系统数据字典，线程栈等），所花费的时间
[Update RS (ms): Min: 0.0, Avg: 0.0, Max: 0.1, Diff: 0.1, Sum: 0.4]
- 更新记忆集Rset的耗时时间，通过更新记忆集Rset，保证当前分区的RSet是最新的
...... 中间的过程在上面YoungGC的时候讲解过具体的内容
[Eden: 1024.0K(5120.0K)->0.0B(1024.0K) Survivors: 1024.0K->1024.0K Heap: 5596.7K(10.0M)->5843.5K(10.0M)]
- 最终结果Eden区GC回收前使用1024K(回收前总大小5120K)->回收后大小使用0.0B(Eden区回收后总大小1024K)
- suivivors区GC回收前大小1024K->回收后大小1024K
- 整堆HEAP回收前使用5596.7K(整堆大小10M)->回收后整堆使用5843.5K(总堆大小10M)

不同的是此阶段出现了下面的标记

[GC concurrent-root-region-scan-start]
- initial mark结束后，就开始了跟扫描 root-region-scan，当初始标记结束后，新生代收集也完成了对象的复制工作，存活的对象都进入了Survivor区，这部分进入Survivor的对象全部都会被标记为根，同时刚刚扫描的Surivivor区也被标记为根分区RootRegion，只有完成了该阶段，才能STW，进行下一次Ygc
[GC concurrent-root-region-scan-end, 0.0004062 secs]
- 根分区扫描结束
[GC concurrent-mark-start], 0.0008744 secs]
- 并发标记阶段开始，开始标记整个堆的存活对象，该阶段是可以与用户线程一起执行的，并发标记的线程数可以由参数-XX:ConcGCThreads可配置，默认线程数是GC线程工作的1/4
[GC concurrent-mark-end, 0.0020466 secs]
- 并发标记结束
[GC remark [Finalize Marking, 0.0001629 secs]
- GC remark 重新标记阶段，该阶段STW, 会标记并发阶段变化的对象，并计算整个堆的垃圾情况，清空剩余的SATB缓冲区，此阶段所有存活的对象都会被标记
- Finalize Marking 最终标记阶段
[GC ref-proc, 0.0000789 secs]
- 软引用，弱引用等引用处理
[Unloading, 0.0006677 secs], 0.0010284 secs]
- 卸载类信息
[GC cleanup 4790K->4790K(10M), 0.0005226 secs]
- 清理阶段，此阶段没有对象存活的老年代和巨型对象占用的分区都会被清理和释放出来，然后按照排序，选择最优，性价比最高的分区进行清理

最终该阶段完成后， G1 收集器的全局并发周期也分析完毕，至此,YoungGC的日志分析已经全部结束了

下一篇，我们讲解G1 MixedGC的日志分析

JVM系列(十六) 垃圾收集器之 G1 YoungGC日志及过程分析