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

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

人行天地间 忽如远行客

9 声望
6 粉丝
0 条评论
推荐阅读
Mysql MDL+DDL 死锁
应用背景: {代码...} 问题描述 {代码...} 找到DBA去排查时,基于他们的经验,他们不承认这是数据库报出的死锁,反而怀疑是我们的应用代码或者JDBC有问题,这 ...问题复现在排查相关资料后,我断定了是mysql的锁的...

ruanjianershu阅读 436

一文搞懂秒杀系统,欢迎参与开源,提交PR,提高竞争力。早日上岸,升职加薪。
前言秒杀和高并发是面试的高频考点,也是我们做电商项目必知必会的场景。欢迎大家参与我们的开源项目,提交PR,提高竞争力。早日上岸,升职加薪。知识点详解秒杀系统架构图秒杀流程图秒杀系统设计这篇文章一万多...

王中阳Go33阅读 2.5k评论 1

封面图
计算机网络连环炮40问
本文已经收录到Github仓库,该仓库包含计算机基础、Java基础、多线程、JVM、数据库、Redis、Spring、Mybatis、SpringMVC、SpringBoot、分布式、微服务、设计模式、架构、校招社招分享等核心知识点,欢迎star~

程序员大彬14阅读 1.7k

万字详解,吃透 MongoDB!
MongoDB 是一个基于 分布式文件存储 的开源 NoSQL 数据库系统,由 C++ 编写的。MongoDB 提供了 面向文档 的存储方式,操作起来比较简单和容易,支持“无模式”的数据建模,可以存储比较复杂的数据类型,是一款非常...

JavaGuide8阅读 1.7k

封面图
花了半个小时基于 ChatGPT 搭建了一个微信机器人
相信大家最近被 ChatGPT 刷屏了,其实在差不多一个月前就火过一次,不会那会好像只在程序员的圈子里面火起来了,并没有被大众认知到,不知道最近是因为什么又火起来了,而且这次搞的人尽皆知。

Java极客技术12阅读 3.2k评论 3

封面图
数据结构与算法:二分查找
一、常见数据结构简单数据结构(必须理解和掌握)有序数据结构:栈、队列、链表。有序数据结构省空间(储存空间小)无序数据结构:集合、字典、散列表,无序数据结构省时间(读取时间快)复杂数据结构树、 堆图二...

白鲸鱼9阅读 5.3k

PHP转Go实践:xjson解析神器「开源工具集」
我和劲仔都是PHP转Go,身边越来越多做PHP的朋友也逐渐在用Go进行重构,重构过程中,会发现php的json解析操作(系列化与反序列化)是真的香,弱类型语言的各种隐式类型转换,很大程度的减低了程序的复杂度。

王中阳Go11阅读 2.7k评论 4

封面图

人行天地间 忽如远行客

9 声望
6 粉丝
宣传栏