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次回收 
  1. 第一行 概述
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)拷贝到另一个区域的阶段)

  1. 第二行:详细解析
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列表

  1. 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分区保持不变,如果设置的不是一样的值的话,堆大小会进行自适应调整)

  1. 各阶段耗时
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

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

你可能感兴趣的