乐趣区

关于java:G1-GC-log-解析

jiezi

最近在钻研一个服务与数据库之间的耗时问题，排查到了服务端 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

哈哈 最初说的有点多了哈，如同和本文主题关系不是太大 ～ ～ ～

退出移动版