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

贾子杰
206 阅读7分钟

1.G1 MixedGC日志及过程分析

为什么会有YoungGC, MixedGC,这两种GC到底充当了什么样的角色，在G1垃圾收集过程中，普遍分为两种正常的GC，FullGC算异常的

  • Young GC：清除所有年轻代里的Region分区
    • G1是通过调整年轻代Eden区的大小，控制年轻代Region数量来控制YoungGC的开销
  • Mixed GC：清除所有年轻代里的Region及全局并发周期Global Concurrent Marking统计得出收集性价比高的部分老年代Region，在用户指定的停顿时间目标范围内尽可能选择最优的老年代Region回收
    • G1就是通过控制回收老年代Region分区数量来控制Mixed GC的开销的
1.1 设置JVM参数，运行程序

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

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

image.png

本次Byte对象 设置的大小是2M, 你可以变换以下大小比如 1M，2M，3M，会产生不同的效果

比如我之前设置的1M的时候，整个程序运行完成后，没有出现MixedGC， 改成2M后才出现mixedGC 混合收集

运行程序如下：

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++) {
            //设置 2M的对象
            log.info("======== " + i + "次添加3M对象");
            b = new byte[2 * 1024 * 1024];
            Thread.sleep(100);

        }
    }
}
1.2 MixedGC 日志打印

下面我们看下打印的MixedGC日志

[GC pause (G1 Humongous Allocation) (mixed) (to-space exhausted), 0.0039504 secs]
   [Parallel Time: 2.9 ms, GC Workers: 10]
      [GC Worker Start (ms): Min: 1108.6, Avg: 1108.7, Max: 1108.8, Diff: 0.2]
      [Ext Root Scanning (ms): Min: 0.0, Avg: 0.3, Max: 1.5, Diff: 1.5, 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.5, Max: 3, Diff: 3, Sum: 5]
      [Scan RS (ms): Min: 0.0, Avg: 0.0, Max: 0.1, Diff: 0.1, Sum: 0.2]
      [Code Root Scanning (ms): Min: 0.0, Avg: 0.0, Max: 0.5, Diff: 0.5, Sum: 0.5]
      [Object Copy (ms): Min: 1.3, Avg: 2.4, Max: 2.6, Diff: 1.3, Sum: 24.0]
      [Termination (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.2]
         [Termination Attempts: Min: 1, Avg: 6.1, Max: 12, Diff: 11, Sum: 61]
      [GC Worker Other (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.1]
      [GC Worker Total (ms): Min: 2.6, Avg: 2.8, Max: 2.8, Diff: 0.2, Sum: 27.6]
      [GC Worker End (ms): Min: 1111.4, Avg: 1111.4, Max: 1111.4, Diff: 0.0]
   [Code Root Fixup: 0.0 ms]
   [Code Root Purge: 0.0 ms]
   [Clear CT: 0.3 ms]
   [Other: 0.7 ms]
      [Evacuation Failure: 0.4 ms]
      [Choose CSet: 0.0 ms]
      [Ref Proc: 0.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: 1024.0K(1024.0K)->0.0B(1024.0K) Survivors: 0.0B->0.0B Heap: 5764.3K(10.0M)->3716.3K(10.0M)]
 [Times: user=0.02 sys=0.00, real=0.00 secs]

2.MixedGC日志分析

2.1 MixedGC日志分析

混合收集不仅仅单指的是一次GC，有可能包括多次YoungGC和多次MixedGC

  • [GC pause (G1 Humongous Allocation) (mixed) (to-space exhausted), 0.0039504 secs]
    • mixed表示此次GC是混合收集，混合收集不仅仅包括所有的新生代，还包括部分性价比比较高的老年代，在时间允许的范围内，选择回收性价比最高的Region
    • to-space exhausted 空间耗尽(对象转移失败)，没有空闲Region分配给年老代(old) 或者 Survivor区 或者两种情况都有
    • java堆已达到最大值无法扩展。这种情况发生在 G1 将存活对象从Eden区的From 复制转移到 目标空间To区域或者Survivor区域时发生。

简单理解：年老代 or 幸存区 不够用

  • [Parallel Time: 2.9 ms, GC Workers: 10]
    • 并行开始收集任务，该过程STW， 从新生代垃圾收集到最后一个任务结束一共耗时2.9ms，一共由10个GC线程
  • [GC Worker Start (ms): Min: 1108.6, Avg: 1108.7, Max: 1108.8, Diff: 0.2]
    • GC开始工作， min指的是第一个垃圾收集线程开始工作时，JVM启动后经过的时间， max指的时最后一个垃圾收集器开始工作时，JVM启动后经过的时间，diff指的是min和max的差值，avg表示平均值，理想情况下，我们希望多个线程是同时开始的，即最好的情况是diff=0
  • [Ext Root Scanning (ms): Min: 0.0, Avg: 0.3, Max: 1.5, Diff: 1.5, Sum: 2.6]
    • 根扫描的耗时时间，每一个GC线程在处理根扫描（全局变量，系统数据字典，线程栈等），所花费的时间
  • [Update RS (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
    • 更新记忆集Rset的耗时时间
  • [Processed Buffers: Min: 0, Avg: 0.5, Max: 3, Diff: 3, Sum: 5]
    • 日志缓冲区处理时间
  • [Scan RS (ms): Min: 0.0, Avg: 0.0, Max: 0.1, Diff: 0.1, Sum: 0.2]
    • 扫描每个新生代分区的RSet耗时，找出有多少指向当前分区的引用来自CSet
  • [Code Root Scanning (ms): Min: 0.0, Avg: 0.0, Max: 0.5, Diff: 0.5, Sum: 0.5]
    • Code Root 表示代码中的局部变量的Root节点,扫描这部分节点需要的时间
  • [Object Copy (ms): Min: 1.3, Avg: 2.4, Max: 2.6, Diff: 1.3, Sum: 24.0]
    • 复制存活对象到Survivor区花费的时间
  • [Termination (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.2]
    • 线程处理完，进入临界区时间，GC线程终止前，会检查还有没对象没处理完，如果没处理完，请求终止的GC线程会去帮助完成
  • [Termination Attempts: Min: 1, Avg: 6.1, Max: 12, Diff: 11, Sum: 61]
    • 成功偷取其他线程的任务，他会再次尝试多次偷取，Termination Attempts表示每个工作线程尝试终止的次数
  • [GC Worker Other (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.1]
    • GC线程花费在其他工作上
  • [GC Worker Total (ms): Min: 2.6, Avg: 2.8, Max: 2.8, Diff: 0.2, Sum: 27.6]
    • GC线程工作总时间
  • [GC Worker End (ms): Min: 1111.4, Avg: 1111.4, Max: 1111.4, Diff: 0.0]
    • 单个GC工作结束时间，和Worker Start 相对应，min，avg，max，diff都是同样的相对应
  • [Code Root Fixup: 0.0 ms]
    • 串行执行 修复Code root的时间
  • [Code Root Purge: 0.0 ms]
    • 串行执行 清理Code root的时间
  • [Clear CT: 0.3 ms]
    • 串行执行 清理Card Table卡表时间
  • [Other: 0.7 ms] 其他时间
    • [Evacuation Failure: 0.4 ms]
      • 当应用存活对象占用了大量内存，以至于回收剩余对象没有足够的空间拷贝时，就会触发 Evacuation failure
    • [Choose CSet: 0.0 ms] 选择要进行回收的分区放入CSet
    • [Ref Proc: 0.1 ms] 处理Soft/Weak 弱引用，软引用时间
    • [Ref Enq: 0.0 ms] 处理弱引用，软引用的入队时间
    • [Redirty Cards: 0.1 ms] 重新脏化卡表
    • [Humongous Register: 0.0 ms]
      • 巨型对象回收的信息，youngGC阶段会对RSet中有引用的短命的巨型对象进行回收，巨型对象会直接回收
    • [Humongous Reclaim: 0.0 ms]
      • 确保巨型对象可以被回收，释放该巨型对象所占的分区
    • [Free CSet: 0.0 ms]
      • 释放被回收的Cset区域
  • [Eden: 1024.0K(1024.0K)->0.0B(1024.0K) Survivors: 0.0B->0.0B Heap: 5764.3K(10.0M)->3716.3K(10.0M)]
  1. Eden区GC回收前使用1024K(回收前总大小1024K)->回收后大小使用0.0B(Eden区回收后总大小1024K)
  2. suivivors区GC回收前大小0.0B->回收后大小1024K
  3. 整堆HEAP回收前使用5764.3K(整堆大小10M)->回收后整堆使用3716.3K(总堆大小10M)

3.G1 的FullGC

3.1 运行程序FullGC

我们把Byte对象调成4M运行一下，就可以看到OOM， 发生了FullGC

b = new byte[4 * 1024 * 1024];

执行结果发生FullGC

[Full GC (Allocation Failure)  6052K->5308K(10M), 0.0031376 secs]
   [Eden: 0.0B(1024.0K)->0.0B(1024.0K) Survivors: 1024.0K->0.0B Heap: 6052.7K(10.0M)->5308.8K(10.0M)], [Metaspace: 5088K->5088K(1056768K)]
 [Times: user=0.00 sys=0.00, real=0.00 secs] 
[Full GC (Allocation Failure)  5308K->5234K(10M), 0.0027910 secs]
   [Eden: 0.0B(1024.0K)->0.0B(1024.0K) Survivors: 0.0B->0.0B Heap: 5308.8K(10.0M)->5234.1K(10.0M)], [Metaspace: 5088K->5088K(1056768K)]
 [Times: user=0.00 sys=0.00, real=0.00 secs] 
java.lang.OutOfMemoryError: Java heap space
3.2 FullGC日志分析

G1模式下的FullGC

  • 在G1的正常工作流程中没有Full GC的概念
  • 老年代的收集全靠Mixed GC来完成
  • G1的FullGC是单线程完成操作的
  • 该过程是会STW的，代价比较高
  • 当Mixed GC 无法清除足够的垃圾时，或者Mixed GC实在无法跟上程序分配内存的速度，就会导致老年代填满无法继续进行Mixed GC
  • 无法进行MixedGC时，会使用Serial Old GC来收集整个堆，这才是真正的Full GC

下面我们分析下FullGC的日志

  • [Full GC (Allocation Failure) 6052K->5308K(10M), 0.0031376 secs]
    • 堆空间不足，无法分配对象，堆空间gc前6052K，gc后5308K，堆空间一共10M
  • [Eden: 0.0B(1024.0K)->0.0B(1024.0K) Survivors: 1024.0K->0.0B Heap: 6052.7K(10.0M)->5308.8K(10.0M)]
    • Eden区gc前使用0.0B(Eden区总大小1024K)，gc后Eden区gc后使用0.0B(Eden区一共1024K)
    • Suivivor区gc前1024.0K，gc后Survivor区使用0.0B
    • Heap总堆gc前使用6052.7K (gc前总堆10M)，gc后使用5308.8K(gc后总堆10M)
  • [Metaspace: 5088K->5088K(1056768K)]
    • 元空间 GC前5088K，GC后5088K，一共1056768K

4. G1 垃圾回收流程总结

  • Young CG 和 Mixed GC，是G1回收空间的主要活动
  • 当应用开始运行时，堆内存可用空间还比较大，只会在年轻代满时，触发年轻代收集
  • 随着老年代内存对象的分配，占用空间的增长，当到达参数-XX:InitiatingHeapOccupancyPercent(老年代占整堆比，默认45%) IHOP阈值时，G1开始着手准备收集老年代空间
  • YoungGC后，MixedGC会经过全局并发标记周期，识别出高收益的老年代分区
  • G1并不会马上开启一次混合收集，而是让应用线程先运行一段时间，等待触发一次年轻代收集YoungGC,YoungGC期间会产生STW空闲时间
  • G1会利用这次YongGC的STW时间段，G1将开始整理混合收集周期 mixedGC
  • 此过程应用线程可以与GC线程并行处理，当接下来的几次年轻代YoungGC收集垃圾时，将会有老年代分区加入到CSet
  • 触发混合收集
avatar
文章
阅读
粉丝