G1 GC log 解析

最近在研究一个服务与数据库之间的耗时问题，排查到了服务端GC这块，对于GC的日志进行分析一波，在此做个记录。

如下只记录了G1的新生代收集的流程 ！！！

{Heap before GC invocations=11035 (full 0):
 garbage-first heap   total 2097152K, used 1878984K [0x0000000640000000, 0x0000000640202000, 0x00000007c0000000)
  region size 2048K, 594 young (1216512K), 2 survivors (4096K)
 Metaspace       used 96639K, capacity 100818K, committed 101120K, reserved 1138688K
  class space    used 10423K, capacity 11153K, committed 11264K, reserved 1048576K
2021-11-21T16:13:30.692+0800: 2055582.832: [GC pause (G1 Evacuation Pause) (young), 0.0107390 secs]
   [Parallel Time: 7.4 ms, GC Workers: 4]
      [GC Worker Start (ms): Min: 2055582832.5, Avg: 2055582832.5, Max: 2055582832.6, Diff: 0.1]
      [Ext Root Scanning (ms): Min: 2.7, Avg: 2.8, Max: 2.8, Diff: 0.2, Sum: 11.0]
      [Update RS (ms): Min: 2.6, Avg: 2.6, Max: 2.7, Diff: 0.2, Sum: 10.4]
         [Processed Buffers: Min: 118, Avg: 136.8, Max: 165, Diff: 47, Sum: 547]
      [Scan RS (ms): Min: 0.0, Avg: 0.1, Max: 0.2, Diff: 0.1, Sum: 0.4]
      [Code Root Scanning (ms): Min: 0.0, Avg: 0.0, Max: 0.1, Diff: 0.1, Sum: 0.1]
      [Object Copy (ms): Min: 1.6, Avg: 1.7, Max: 1.7, Diff: 0.1, Sum: 6.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: 4]
      [GC Worker Other (ms): Min: 0.0, Avg: 0.1, Max: 0.1, Diff: 0.1, Sum: 0.2]
      [GC Worker Total (ms): Min: 7.1, Avg: 7.2, Max: 7.3, Diff: 0.2, Sum: 28.8]
      [GC Worker End (ms): Min: 2055582839.7, Avg: 2055582839.7, Max: 2055582839.8, Diff: 0.1]
   [Code Root Fixup: 0.2 ms]
   [Code Root Purge: 0.0 ms]
   [Clear CT: 0.2 ms]
   [Other: 2.9 ms]
      [Choose CSet: 0.0 ms]
      [Ref Proc: 1.1 ms]
      [Ref Enq: 0.1 ms]
      [Redirty Cards: 0.1 ms]
      [Humongous Register: 0.1 ms]
      [Humongous Reclaim: 0.0 ms]
      [Free CSet: 0.5 ms]
   [Eden: 1184.0M(1184.0M)->0.0B(1184.0M) Survivors: 4096.0K->4096.0K Heap: 1834.9M(2048.0M)->652.4M(2048.0M)]
Heap after GC invocations=11036 (full 0):
 garbage-first heap   total 2097152K, used 668097K [0x0000000640000000, 0x0000000640202000, 0x00000007c0000000)
  region size 2048K, 2 young (4096K), 2 survivors (4096K)
 Metaspace       used 96639K, capacity 100818K, committed 101120K, reserved 1138688K
  class space    used 10423K, capacity 11153K, committed 11264K, reserved 1048576K
}
 [Times: user=0.03 sys=0.00, real=0.01 secs]

1. 开始GC 标志（Heap before GC ）

invocations=11035 代表第11035次回收 

2. 第一行 概述

2021-11-21T16:13:30.692+0800 - 新生代垃圾收集发生的时间，通过设置-XX:+PrintGCDateStamps参数可以打印出这个时间

2055582.832 - JVM启动后的相对时间

GC pause (G1 Evacuation Pause) (young) - 这次收集的类型:新生代收集，只回收了Eden区(代表是一次 yong GC ,原因是: 疏散停顿（Evacuation Pause）是将活着的对象从一个区域（young or young + old）拷贝到另一个区域的阶段)

---

3. 第二行：详细解析

Parallel Time：并行收集任务在运行过程中引发的STW（Stop The World）时间，从新生代垃圾收集开始到最后一个任务结束，共花费26.6ms

GC Workers：有4个线程负责垃圾收集，通过参数-XX:ParallelGCThreads设置，这个参数的值的设置，跟CPU有关，如果物理CPU支持的线程个数小于8，则最多设置为8；如果物理CPU支持的线程个数大于8，则默认值为number * 5/8

GC Worker Start：第一个垃圾收集线程开始工作时JVM启动后经过的时间（min）；最后一个垃圾收集线程开始工作时JVM启动后经过的时间（max）；diff表示min和max之间的差值。理想情况下，你希望他们几乎是同时开始，即diff趋近于0。

Code Root Scanning：扫描代码中的root节点（局部变量）花费的时间

GC Worker Other：垃圾收集线程在完成其他任务的时间

GC Worker Total：展示每个垃圾收集线程的最小、最大、平均、差值和总共时间。

GC Worker End：min表示最早结束的垃圾收集线程结束时该JVM启动后的时间；max表示最晚结束的垃圾收集线程结束时该JVM启动后的时间。理想情况下，diff 无限趋近于 0 

Code Root Fixup ：释放用于管理并行垃圾收集活动的数据结构，应该接近于0，该步骤是线性执行

Code Root Purge：清理更多的数据结构，应该很快，耗时接近于0，也是线性执行

Choose CSet：选择要进行回收的分区放入CSet（G1选择的标准是垃圾最多的分区优先，也就是存活对象率最低的分区优先）

Ref Proc：处理Java中的各种引用 例如soft、weak、final、phantom、JNI等

Ref Enq：遍历所有的引用，将不能回收的放入pending列表

Humongous Register：JDK8 提供了一个特性，巨型对象可以在新生代收集的时候被回收 可以通过G1ReclaimDeadHumongousObjectsAtYoungGC设置，默认为true

Humongous Reclaim：确保巨型对象可以被回收、释放该巨型对象所占的分区，重置分区类型，并将分区还到free列表，并且更新空闲空间大小

Free CSet：将要释放的分区还回到free列表

---

4. GC前后变化

Eden: 1184.0M(1184.0M)->0.0B(1184.0M): （1）当前新生代收集触发的原因是Eden空间满了，分配了 1184.0M ，使用了1184.0M（2）所有的Eden分区都被疏散处理了，在新生代结束后Eden分区的使用大小成为了0.0B 

Survivors: 4096.0K->4096.0K  Eden区回收处理，但survivors并未改变，说明很多对象都在Eden区就被回收了

Heap: 1834.9M(2048.0M)->652.4M(2048.0M) （1）在本次垃圾收集活动开始的时候，堆空间整体使用量是1834.9M，堆空间的最大值是2048M；（2）在本次垃圾收集结束后，堆空间的使用量是652.4M，最大值保持不变(注:此处我的启动脚本设置了-xmn和-xmx是一样大的，所以Eden分区保持不变，如果设置的不是一样的值的话，堆大小会进行自适应调整）

---

5. 各阶段耗时

user=0.03: 垃圾收集线程在新生代垃圾收集过程中消耗的CPU时间，这个时间跟垃圾收集线程的个数有关

sys=0.00: 内核态线程消耗的CPU时间

real=0.01: 本次垃圾收集真正消耗的时间

总结：

基本上GC 上面的日志基本上已经够用了，如果想更精细一点可以加上 -XX:+PrintAdaptiveSizePolicy 打印内存调节的过程

---

备注：
1、之前收藏过一个老哥写的博客，关于G1GC的日志分析可以来这里看看，讲的也挺详细的https://blog.csdn.net/weixin_...
2、出现GC问题大家除了观察GC日志，也要合理利用工具哦，我一般用的工具是
GcEasy、MAT, dump文件分析的话一般用的是 heaphero 和 fastthread

哈哈 最后说的有点多了哈，好像和本文主题关系不是太大 ～ ～ ～