JVM 性能分析 —— G1 日志分析-EW帮帮网

微信交流群：https://732903.hlcode.cn/?id=NK1fWUR

文章目录

日志级别
-XX:+PrintGC（简洁版）
-XX:+PrintGCDetails（详细版）
-XX:G1LogLevel=finest（非常详细版）

日志级别

JVM 日志级别中的 fine、finer 和 finest 这三个级别

fine：JVM 配置参数为 -XX:G1LogLevel=fine 或使用 -XX:+PrintGC。
- 用于输出一些常规性的信息，不会产生太多的日志输出。
finer：JVM 配置参数为 -XX:G1LogLevel=finer 或使用 -XX:+PrintGCDetails。
- 用于输出更加详细的调试信息，帮助开发人员进行问题排查。
finest：JVM 配置参数为 -XX:G1LogLevel=finest。
- 用于输出非常详细的跟踪信息，会产生大量的日志输出。

G1LogLevel 是一个实验性的 VM 选项，需要先通过 -XX:+UnlockExperimentalVMOptions 参数来解锁，才能使用。所以一般使用 -XX:+PrintGC 和 -XX:+PrintGCDetails

GC 暂停类型

GC pause (G1 Evacuation Pause)
- "Evacuation Pause"是 G1 垃圾收集器在执行垃圾收集时使用的一种暂停模式。
- 在这种模式下，G1 会先标记需要回收的对象，然后将存活对象复制到新的内存区域（称为"转移"或"疏散"）。
GC pause (G1 Humongous Allocation)
- 这种暂停发生在 G1 收集器处理大对象 (Humongous Object) 时。
- G1 会触发一个特殊的暂停来回收这些大对象。
Full GC (Allocation Failure)
- 这种暂停是在应用程序内存不足时发生的完全垃圾收集 (Full GC) 。
- G1 无法在年轻代和老年代中找到足够的空间分配新对象时，会触发 Full GC。
Full GC (System.gc())
- 这种 Full GC 是由开发者手动触发的，通过调用 System.gc() 方法。通常不建议频繁调用 System.gc()，因为它可能会导致应用程序性能的严重下降。
- 当开发者调用 System.gc() 时，Java 虚拟机会尝试执行一次完整的垃圾收集。这种 Full GC 与 Allocation Failure 导致的 Full GC 不同，它是由开发者主动触发的。

垃圾回收的示例代码

public class G1GCAnalysis {

    private static final int KB = 1024;
    private static final int cacheSize = 1024;
    private static Random random = new Random();

    public static void main(String[] args) throws InterruptedException {
        long startTime = System.currentTimeMillis();
        long intervalTime = TimeUnit.SECONDS.toMillis(1);
        long endTime = startTime + intervalTime;
        // 缓存数据，用户保存对象，部分晋升到老年代
        Object[] objects = new Object[cacheSize];
        // 设置循环运行1000ms
        while (System.currentTimeMillis() < endTime){
            for (int i = 0; i < 100; i++) {
                // 创建对象，部分对象在新生代被回收，部分对象会晋升到老年代再回收
                byte[] bytes = new byte[64 * KB];
                int randomIndex = random.nextInt(2 * cacheSize);
                if (randomIndex < cacheSize){
                    // 若被覆盖且原引用对象是老年代对象，制造老年代垃圾对象
                    objects[randomIndex] = bytes;
                }
            }
            // 睡眠一下，让对象多熬过几次新生代垃圾回收，以晋升到老年代
            Thread.sleep(10);
        }
    }
}

-XX:+PrintGC（简洁版）

本文分析 G1 日志，所有配置使用 G1 垃圾收集器（-XX:+UseG1GC）；同时设置最大、最小堆内存为 100M（-Xms100M -Xmx100M）；配置打印触发垃圾回收时的时间（-XX:+PrintGCDateStamps）。

-XX:+UseG1GC -Xms100M -Xmx100M -XX:+PrintGCDateStamps

配置 -XX:+PrintGC 日志级别

-XX:+UseG1GC -Xms100M -Xmx100M -XX:+PrintGCDateStamps -XX:+PrintGC

G1 日志输出

2024-08-07T19:05:30.973+0800: [GC pause (G1 Evacuation Pause) (young) 83M->78M(100M), 0.0010787 secs]
2024-08-07T19:05:30.989+0800: [GC pause (G1 Evacuation Pause) (young) (initial-mark) 85M->82M(100M), 0.0012699 secs]
2024-08-07T19:05:30.990+0800: [GC concurrent-root-region-scan-start]
2024-08-07T19:05:30.990+0800: [GC concurrent-root-region-scan-end, 0.0000719 secs]
2024-08-07T19:05:30.990+0800: [GC concurrent-mark-start]
2024-08-07T19:05:30.991+0800: [GC concurrent-mark-end, 0.0007155 secs]
2024-08-07T19:05:30.991+0800: [GC remark, 0.0007150 secs]
2024-08-07T19:05:30.992+0800: [GC cleanup 84M->84M(100M), 0.0003412 secs]
2024-08-07T19:05:31.004+0800: [GC pause (G1 Evacuation Pause) (young) 86M->84M(100M), 0.0012786 secs]
2024-08-07T19:05:31.005+0800: [GC pause (G1 Evacuation Pause) (mixed) 88M->81M(100M), 0.0010569 secs]
2024-08-07T19:05:31.034+0800: [GC pause (G1 Evacuation Pause) (mixed)-- 89M->91M(100M), 0.0017680 secs]
2024-08-07T19:05:31.050+0800: [GC pause (G1 Evacuation Pause) (mixed)-- 99M->100M(100M), 0.0011720 secs]
2024-08-07T19:05:31.051+0800: [Full GC (Allocation Failure)  100M->59M(100M), 0.0096012 secs]

G1 日志详解

[GC pause (G1 Evacuation Pause) (young) 83M->78M(100M), 0.0010787 secs]
- GC pause (G1 Evacuation Pause) (young) 表示 G1 收集器在年轻代进行正常垃圾收集时发生的暂停。每一次 YGC 回收整个新生代分区。
- 83M->78M(100M) 表示垃圾收集前后，年轻代已使用内存从 83M 降低到 78M，年轻代总内存 100M。
- 0.0010787 secs 表示这次 YGC 暂停持续了大约 1.0787 毫秒。
[GC pause (G1 Evacuation Pause) (young) (initial-mark) 85M->82M(100M), 0.0012699 secs]
- 这是 G1 收集器同时进行年轻代垃圾收集 (YGC) 和初始标记的暂停。（初始标记在 YGC 的同时完成）
- 年轻代已使用内存从 85M 降低到 82M，年轻代总内存 100M；耗时大约 1.2699 毫秒。
- 初始标记是 G1 收集器 GC 流程的一个重要步骤，用于快速找到标记根对象。
[GC concurrent-root-region-scan-start]
- 这表示 G1 收集器开始并发扫描根区域。
- 并发根区域扫描可以在应用程序运行的同时快速找出哪些区域包含了根对象。
[GC concurrent-root-region-scan-end, 0.0000719 secs]
- 这表示 G1 收集器的并发根区域扫描操作已经结束。
- 这个并发扫描根区域操作总共持续了 0.0719 毫秒。
[GC concurrent-mark-start]
- 这表示 G1 收集器开始并发标记阶段。
[GC concurrent-mark-end, 0.0007155 secs]
- 这表示 G1 收集器的并发标记操作已经结束。
- 这个并发标记操作总共持续了 0.7155 毫秒。
[GC remark, 0.0007150 secs]
- 这表示 G1 收集器进入了 Remark（重新标记）阶段，这个阶段持续了 0.7150 毫秒。
[GC cleanup 84M->84M(100M), 0.0003412 secs]
- 这表示 G1 收集器进入了 Cleanup 清理阶段的暂停。
- 该阶段主要作用：统计存活对象、交换标记位图、重置RSet、把空闲分区放到空闲分区列表中。
- 清理阶段并不会清理垃圾对象，也不会执行存活对象的拷贝，所以内存几乎不会变化。
- 堆已用内存从 84M 降为 84M，总内存为 100M，整个清理阶段持续了 0.3412 毫秒。
[GC pause (G1 Evacuation Pause) (mixed) 88M->81M(100M), 0.0010569 secs]
- 这是 G1 收集器在进行混合（年轻代和老年代）垃圾收集时发生的暂停。
- 堆已用内存从 88M 降为 81M，总堆内存为 100M，整个 Mixed GC 持续了 1.0569 毫秒。
[Full GC (Allocation Failure) 100M->59M(100M), 0.0096012 secs]
- 这是一次完整的垃圾收集的暂停，发生在无法在年轻代和老年代找到足够内存分配新对象时。
- 导致这次 Full GC 的原因是发生了内存分配失败（Allocation Failure）。
- 在这个 Full GC 中，G1 会回收整个堆内存，从 100MB 压缩到 59MB，整个 Full GC 操作持续了约 9.6 毫秒。

-XX:+PrintGCDetails（详细版）

配置 -XX:+PrintGCDetails 日志级别

-XX:+UseG1GC -Xms100M -Xmx100M -XX:+PrintGCDateStamps -XX:+PrintGCDetails

G1 日志输出

-XX:+PrintGCDetails 日志级别统计GC线程整体工作情况，-XX:G1LogLevel=finest 日志级别除了输出GC线程统计信息外，还会输出每个GC线程的工作情况，-XX:G1LogLevel=finest 日志级别输出信息包含 -XX:+PrintGCDetails 日志级别的输出信息，所以在下面介绍 -XX:G1LogLevel=finest 时进行每行日志的详细解释。可以直接跳转到 -XX:G1LogLevel=finest 一节。

2024-08-07T19:25:46.191+0800: [GC pause (G1 Evacuation Pause) (young), 0.0013358 secs]
   [Parallel Time: 0.7 ms, GC Workers: 13]
      [GC Worker Start (ms): Min: 930.5, Avg: 930.7, Max: 931.0, Diff: 0.6]
      [Ext Root Scanning (ms): Min: 0.0, Avg: 0.1, Max: 0.2, Diff: 0.2, Sum: 1.3]
      [Update RS (ms): Min: 0.0, Avg: 0.0, Max: 0.1, Diff: 0.1, Sum: 0.4]
         [Processed Buffers: Min: 0, Avg: 0.6, Max: 2, Diff: 2, Sum: 8]
      [Scan RS (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
      [Code Root Scanning (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
      [Object Copy (ms): Min: 0.0, Avg: 0.2, Max: 0.3, Diff: 0.3, Sum: 3.2]
      [Termination (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.2]
         [Termination Attempts: Min: 1, Avg: 1.0, Max: 1, Diff: 0, Sum: 13]
      [GC Worker Other (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.1]
      [GC Worker Total (ms): Min: 0.1, Avg: 0.4, Max: 0.6, Diff: 0.6, Sum: 5.4]
      [GC Worker End (ms): Min: 931.1, Avg: 931.1, Max: 931.1, Diff: 0.0]
   [Code Root Fixup: 0.0 ms]
   [Code Root Purge: 0.0 ms]
   [Clear CT: 0.1 ms]
   [Other: 0.5 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: 7168.0K(7168.0K)->0.0B(5120.0K) Survivors: 1024.0K->1024.0K Heap: 85.4M(100.0M)->81.8M(100.0M)]
 [Times: user=0.00 sys=0.00, real=0.00 secs] 
 
2024-08-07T19:25:46.206+0800: [GC pause (G1 Evacuation Pause) (young) (initial-mark), 0.0008776 secs]
   [Parallel Time: 0.5 ms, GC Workers: 13]
      [GC Worker Start (ms): Min: 945.0, Avg: 945.0, Max: 945.1, Diff: 0.1]
      [Ext Root Scanning (ms): Min: 0.1, Avg: 0.1, Max: 0.1, Diff: 0.1, Sum: 1.4]
      [Update RS (ms): Min: 0.0, Avg: 0.0, Max: 0.1, Diff: 0.1, Sum: 0.3]
         [Processed Buffers: Min: 0, Avg: 0.7, Max: 1, Diff: 1, Sum: 9]
      [Scan RS (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
      [Code Root Scanning (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
      [Object Copy (ms): Min: 0.2, Avg: 0.2, Max: 0.3, Diff: 0.1, Sum: 3.2]
      [Termination (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.2]
         [Termination Attempts: Min: 1, Avg: 1.0, Max: 1, Diff: 0, Sum: 13]
      [GC Worker Other (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.1]
      [GC Worker Total (ms): Min: 0.4, Avg: 0.4, Max: 0.4, Diff: 0.1, Sum: 5.2]
      [GC Worker End (ms): Min: 945.4, Avg: 945.4, Max: 945.4, Diff: 0.0]
   [Code Root Fixup: 0.0 ms]
   [Code Root Purge: 0.0 ms]
   [Clear CT: 0.1 ms]
   [Other: 0.3 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: 5120.0K(5120.0K)->0.0B(4096.0K) Survivors: 1024.0K->1024.0K Heap: 86.8M(100.0M)->84.2M(100.0M)]
 [Times: user=0.00 sys=0.00, real=0.00 secs] 
2024-08-07T19:25:46.207+0800: [GC concurrent-root-region-scan-start]
2024-08-07T19:25:46.207+0800: [GC concurrent-root-region-scan-end, 0.0000562 secs]
2024-08-07T19:25:46.207+0800: [GC concurrent-mark-start]
2024-08-07T19:25:46.209+0800: [GC concurrent-mark-end, 0.0011842 secs]
2024-08-07T19:25:46.209+0800: [GC remark 2024-08-07T19:25:46.209+0800: [Finalize Marking, 0.0001029 secs] 2024-08-07T19:25:46.209+0800: [GC ref-proc, 0.0001504 secs] 2024-08-07T19:25:46.209+0800: [Unloading, 0.0004994 secs], 0.0010246 secs]
 [Times: user=0.00 sys=0.00, real=0.00 secs] 
2024-08-07T19:25:46.210+0800: [GC cleanup 88M->88M(100M), 0.0004343 secs]
 [Times: user=0.00 sys=0.00, real=0.00 secs] 
 
2024-08-07T19:25:46.223+0800: [GC pause (G1 Evacuation Pause) (mixed), 0.0022383 secs]
   [Parallel Time: 1.9 ms, GC Workers: 13]
      [GC Worker Start (ms): Min: 962.3, Avg: 962.3, Max: 962.3, Diff: 0.1]
      [Ext Root Scanning (ms): Min: 0.1, Avg: 0.1, Max: 0.1, Diff: 0.1, Sum: 1.2]
      [Update RS (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.3]
         [Processed Buffers: Min: 0, Avg: 0.8, Max: 1, Diff: 1, Sum: 10]
      [Scan RS (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
      [Code Root Scanning (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
      [Object Copy (ms): Min: 0.6, Avg: 0.6, Max: 0.6, Diff: 0.0, Sum: 7.7]
      [Termination (ms): Min: 0.0, Avg: 0.2, Max: 1.1, Diff: 1.1, Sum: 2.5]
         [Termination Attempts: Min: 1, Avg: 1.0, Max: 1, Diff: 0, Sum: 13]
      [GC Worker Other (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.1]
      [GC Worker Total (ms): Min: 0.7, Avg: 0.9, Max: 1.8, Diff: 1.1, Sum: 11.9]
      [GC Worker End (ms): Min: 963.0, Avg: 963.2, Max: 964.1, Diff: 1.1]
   [Code Root Fixup: 0.0 ms]
   [Code Root Purge: 0.0 ms]
   [Clear CT: 0.1 ms]
   [Other: 0.3 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: 4096.0K(4096.0K)->0.0B(4096.0K) Survivors: 1024.0K->1024.0K Heap: 90.1M(100.0M)->83.3M(100.0M)]
 [Times: user=0.00 sys=0.00, real=0.00 secs] 
 
 2024-08-07T19:25:46.332+0800: [Full GC (Allocation Failure)  100M->61M(100M), 0.0138486 secs]
   [Eden: 0.0B(5120.0K)->0.0B(15.0M) Survivors: 0.0B->0.0B Heap: 100.0M(100.0M)->61.4M(100.0M)], [Metaspace: 3381K->3381K(1056768K)]
 [Times: user=0.02 sys=0.00, real=0.01 secs]

-XX:G1LogLevel=finest（非常详细版）

配置 -XX:G1LogLevel=finest 日志级别

-XX:+UseG1GC -Xms100M -Xmx100M -XX:+PrintGCDateStamps -XX:+UnlockExperimentalVMOptions -XX:G1LogLevel=finest

YGC 日志

2024-08-07T19:39:27.817+0800: [GC pause (G1 Evacuation Pause) (young), 0.0045330 secs]
	// G1 垃圾收集器执行并行工作的总时间为3.3毫秒，一共有13个并行的GC线程
   [Parallel Time: 3.3 ms, GC Workers: 13]
		// 每个GC工作线程的启动时间点(相对JVM启动时间), Min线程最早开始的时间点，Avg平均开始时间点，Max最晚开始时间点，Diff 为最早最晚时间差，值越大说明线程启动时间越不均衡，线程启动时间依赖于GC进入安全点的情况。
      [GC Worker Start (ms):  488.1  488.1  488.2  488.2  488.2  488.2  488.2  488.2  488.2  488.2  488.2  488.2  488.3
       Min: 488.1, Avg: 488.2, Max: 488.3, Diff: 0.1]
		// 根扫描耗时统计,分为Java根：分别为Thread、JNI、CLDG；JVM根下面的StringTable、Universe、JNI Handles、ObjectSynchronizer、FlatProfiler、Management、SystemDictionary、JVMTI。最小耗时为0.0ms,平均耗时为0.1ms,最大耗时为0.1ms,总耗时为1.0ms。
      [Ext Root Scanning (ms):  0.1  0.1  0.1  0.1  0.1  0.1  0.1  0.1  0.1  0.1  0.1  0.0  0.0
       Min: 0.0, Avg: 0.1, Max: 0.1, Diff: 0.1, Sum: 1.0]
			// 线程根的扫描，主要包括线程对象和栈帧中的局部变量
         [Thread Roots (ms):  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0
          Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
			// 字符串常量池的扫描，字符串是一种重要的根对象。
         [StringTable Roots (ms):  0.1  0.1  0.1  0.1  0.1  0.1  0.1  0.1  0.1  0.1  0.0  0.0  0.0
          Min: 0.0, Avg: 0.1, Max: 0.1, Diff: 0.1, Sum: 0.9]
			// Java 虚拟机内部的一些根对象的扫描,例如类加载器、方法区等。
         [Universe Roots (ms):  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0
          Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
			// JNI 句柄的扫描,JNI 句柄是 Java 与本地代码交互时使用的一种引用机制。
         [JNI Handles Roots (ms):  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0
          Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
			// 对象监视器的扫描,主要用于检查被锁定的对象。
         [ObjectSynchronizer Roots (ms):  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0
          Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
			// 性能分析器使用的根对象的扫描
         [FlatProfiler Roots (ms):  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0
          Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
			// Java 管理接口使用的根对象的扫描
         [Management Roots (ms):  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0
          Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
			// 系统类加载器使用的根对象的扫描
         [SystemDictionary Roots (ms):  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0
          Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
			// 类加载器依赖图的扫描
         [CLDG Roots (ms):  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0
          Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
			// JVMTI 使用的根对象的扫描
         [JVMTI Roots (ms):  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0
          Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
			// 处理代码缓存中的根对象所花费的时间。代码缓存是 JVM 用来存储已编译的代码的区域,这些代码需要在垃圾收集过程中进行扫描和处理。
         [CodeCache Roots (ms):  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0
          Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.3]
			// 表示处理 Concurrent Mark 阶段中的根对象所花费的时间。Concurrent Mark 是垃圾收集算法的一个阶段,它会并发地扫描和标记存活的对象。
         [CM RefProcessor Roots (ms):  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0
          Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
			// 表示等待 Strong Concurrent Level Decomposition (CLD) 所花费的时间。Strong CLD 是垃圾收集算法的一个阶段,它会并发地分解类加载器的层次结构。
         [Wait For Strong CLD (ms):  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0
          Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
			// 表示处理 Weak Concurrent Level Decomposition (CLD) 根对象所花费的时间。Weak CLD 是垃圾收集算法的另一个阶段,它会并发地处理弱引用。
         [Weak CLD Roots (ms):  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0
          Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
			// 表示 Snapshot-At-The-Beginning (SATB) 过滤所花费的时间。SATB 是垃圾收集算法的一个阶段,它会过滤掉那些在 SATB 快照中已经被标记为存活的对象。
         [SATB Filtering (ms):  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0
          Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
		// GC线程更新Rset所消耗的时间。最小耗时为0毫秒,平均耗时为0毫秒,最大耗时为0毫秒,时间差为0毫秒,总耗时为0.2毫秒。
      [Update RS (ms):  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0
       Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.2]
         [Processed Buffers:  1  1  1  0  1  1  1  1  0  0  0  0  1
          Min: 0, Avg: 0.6, Max: 1, Diff: 1, Sum: 8]
		// 表示扫描RSet所消耗的时间
      [Scan RS (ms):  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0
       Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
		// 扫描代码根所消耗的时间
      [Code Root Scanning (ms):  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0
       Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
		// 复制存活对象所消耗的时间，可以看到复制基本上是最花时间的操作
      [Object Copy (ms):  2.6  2.6  2.6  2.6  2.6  2.5  2.5  2.6  2.6  2.6  2.6  2.6  2.6
       Min: 2.5, Avg: 2.6, Max: 2.6, Diff: 0.1, Sum: 33.7]
		// GC线程结束的耗时信息
      [Termination (ms):  0.1  0.0  0.0  0.0  0.0  0.1  0.1  0.0  0.0  0.1  0.0  0.0  0.0
       Min: 0.0, Avg: 0.0, Max: 0.1, Diff: 0.1, Sum: 0.5]
         [Termination Attempts:  1  1  1  1  1  1  1  1  1  1  1  1  1
          Min: 1, Avg: 1.0, Max: 1, Diff: 0, Sum: 13]
		// 表示垃圾收集工作线程在其他工作中所消耗的时间
      [GC Worker Other (ms):  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0
       Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.1]
		// 表示每个GC工作线程在整个工作过程中所消耗的总时间
      [GC Worker Total (ms):  2.8  2.8  2.8  2.8  2.8  2.7  2.7  2.7  2.7  2.7  2.7  2.7  2.7
       Min: 2.7, Avg: 2.7, Max: 2.8, Diff: 0.1, Sum: 35.6]
		// 表示每个GC工作线程结束工作的时间点
      [GC Worker End (ms):  490.9  490.9  490.9  490.9  490.9  490.9  490.9  490.9  490.9  490.9  490.9  490.9  490.9
       Min: 490.9, Avg: 490.9, Max: 490.9, Diff: 0.0]
	// 表示修复代码根节点的时间消耗
   [Code Root Fixup: 0.0 ms]
	// 表示清除代码根节点的时间消耗
   [Code Root Purge: 0.0 ms]
	// 表示清除卡表的时间消耗
   [Clear CT: 0.4 ms]
	// 表示其他杂项工作的时间消耗
   [Other: 0.8 ms]
		// 表示选择CSet的时间消耗
      [Choose CSet: 0.0 ms]
		// 表示处理引用的时间消耗,发现哪些引用对象可以清除
      [Ref Proc: 0.6 ms]
		// 表示入队引用的时间消耗，引用重新激活
      [Ref Enq: 0.0 ms]
		// 表示重构脏卡片的时间消耗
      [Redirty Cards: 0.1 ms]
         [Parallel Redirty:  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0
          Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
			// 每个线程重构脏卡片的数量
         [Redirtied Cards:  9  0  0  0  0  0  0  0  0  0  0  0  0
          Min: 0, Avg: 0.7, Max: 9, Diff: 9, Sum: 9]
		// 表示大对象注册的时间消耗
      [Humongous Register: 0.0 ms]
			// 这里说明有0个大对象
         [Humongous Total: 0]
			// 这里说明有0个大对象可回收
         [Humongous Candidate: 0]
		// 表示回收大对象的时间消耗
      [Humongous Reclaim: 0.0 ms]
			// 表示回收大对象的个数
         [Humongous Reclaimed: 0]
		// 表示释放CSet中的分区的时间消耗，有新生代和老年代的信息
      [Free CSet: 0.0 ms]
         [Young Free CSet: 0.0 ms]
         [Non-Young Free CSet: 0.0 ms]
	// 垃圾收集前后堆的使用情况,
		// Eden区从28.0M减少到0.0B,预留空间从28.0M减少到22.0M。
		// Survivor区从6144.0K减少到5120.0K。
		// 总堆从73.1M减少到56.3M,总堆大小为100.0M。
   [Eden: 28.0M(28.0M)->0.0B(22.0M) Survivors: 6144.0K->5120.0K Heap: 73.1M(100.0M)->56.3M(100.0M)]
	// 这次垃圾收集的总时间消耗,总共消耗0.01秒。
 [Times: user=0.00 sys=0.00, real=0.01 secs]

并发标记日志

Mixed GC 主要分为两个阶段：并发标记和垃圾回收阶段。

1、并发标记阶段：

初始标记子阶段：初始标记阶段是复用了新生代收集的结果，即新生代垃圾收集回收后的新生代Survivor分区作为根，所以混合收集一定发生在新生代回收之后，且不需要再进行一次初始标记。初始标记子阶段(initial-mark)与YGC一致，不再赘述。
并发标记子阶段
重新标记子阶段
清理子阶段：该阶段主要作用是统计存活对象、交换标记位图、重置RSet、把空闲分区放到空闲分区列表中。清理阶段并不会清理垃圾对象，也不会执行存活对象的拷贝，所以内存几乎不会变化。

2、垃圾回收阶段

这里分析并发标记阶段得日志。

// 初始标记阶段是复用了新生代收集的结果，即新生代垃圾收集回收后的新生代Survivor分区作为根，所以混合收集一定发生在新生代回收之后，且不需要再进行一次初始标记。初始标记子阶段(initial-mark)与YGC一致，不再赘述。
2024-08-07T19:39:27.862+0800: [GC pause (G1 Evacuation Pause) (young) (initial-mark), 0.0036482 secs]
   [Parallel Time: 1.7 ms, GC Workers: 13]
      [GC Worker Start (ms):  534.3  534.3  534.3  534.3  534.3  534.3  534.3  534.4  534.4  534.4  534.4  534.4  534.5
       Min: 534.3, Avg: 534.4, Max: 534.5, Diff: 0.2]
      [Ext Root Scanning (ms):  0.2  0.2  0.2  0.1  0.2  0.2  0.2  0.1  0.1  0.1  0.1  0.1  0.0
       Min: 0.0, Avg: 0.1, Max: 0.2, Diff: 0.2, Sum: 1.8]
         [Thread Roots (ms):  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0
          Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.1]
         [StringTable Roots (ms):  0.0  0.1  0.1  0.1  0.1  0.1  0.1  0.1  0.1  0.1  0.1  0.1  0.0
          Min: 0.0, Avg: 0.1, Max: 0.1, Diff: 0.1, Sum: 1.1]
         [Universe Roots (ms):  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0
          Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
         [JNI Handles Roots (ms):  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0
          Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
         [ObjectSynchronizer Roots (ms):  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0
          Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
         [FlatProfiler Roots (ms):  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0
          Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
         [Management Roots (ms):  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0
          Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
         [SystemDictionary Roots (ms):  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0
          Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
         [CLDG Roots (ms):  0.1  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0
          Min: 0.0, Avg: 0.0, Max: 0.1, Diff: 0.1, Sum: 0.1]
         [JVMTI Roots (ms):  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0
          Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
         [CodeCache Roots (ms):  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.1
          Min: 0.0, Avg: 0.0, Max: 0.1, Diff: 0.1, Sum: 0.2]
         [CM RefProcessor Roots (ms):  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0
          Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
         [Wait For Strong CLD (ms):  0.1  0.0  0.1  0.0  0.0  0.0  0.1  0.0  0.0  0.0  0.0  0.0  0.0
          Min: 0.0, Avg: 0.0, Max: 0.1, Diff: 0.1, Sum: 0.4]
         [Weak CLD Roots (ms):  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0
          Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
         [SATB Filtering (ms):  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0
          Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
      [Update RS (ms):  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.1
       Min: 0.0, Avg: 0.0, Max: 0.1, Diff: 0.1, Sum: 0.2]
         [Processed Buffers:  0  1  0  1  0  0  0  1  1  0  1  0  2
          Min: 0, Avg: 0.5, Max: 2, Diff: 2, Sum: 7]
      [Scan RS (ms):  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0
       Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
      [Code Root Scanning (ms):  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0
       Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
      [Object Copy (ms):  1.4  1.4  1.4  1.4  1.4  1.4  1.4  1.4  1.4  1.4  1.4  1.4  1.3
       Min: 1.3, Avg: 1.4, Max: 1.4, Diff: 0.1, Sum: 18.1]
      [Termination (ms):  0.1  0.1  0.0  0.1  0.0  0.1  0.0  0.1  0.0  0.0  0.0  0.1  0.1
       Min: 0.0, Avg: 0.0, Max: 0.1, Diff: 0.1, Sum: 0.6]
         [Termination Attempts:  1  1  1  1  1  1  1  1  1  1  1  1  1
          Min: 1, Avg: 1.0, Max: 1, Diff: 0, Sum: 13]
      [GC Worker Other (ms):  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0
       Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.2]
      [GC Worker Total (ms):  1.7  1.7  1.6  1.7  1.6  1.6  1.6  1.6  1.6  1.6  1.6  1.6  1.5
       Min: 1.5, Avg: 1.6, Max: 1.7, Diff: 0.2, Sum: 20.9]
      [GC Worker End (ms):  536.0  536.0  536.0  536.0  536.0  536.0  536.0  536.0  536.0  536.0  536.0  536.0  536.0
       Min: 536.0, Avg: 536.0, Max: 536.0, Diff: 0.0]
   [Code Root Fixup: 0.0 ms]
   [Code Root Purge: 0.0 ms]
   [Clear CT: 0.7 ms]
   [Other: 1.3 ms]
      [Choose CSet: 0.0 ms]
      [Ref Proc: 0.4 ms]
      [Ref Enq: 0.0 ms]
      [Redirty Cards: 0.6 ms]
         [Parallel Redirty:  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0
          Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
         [Redirtied Cards:  7  2  0  0  0  0  0  0  0  0  0  0  0
          Min: 0, Avg: 0.7, Max: 7, Diff: 7, Sum: 9]
      [Humongous Register: 0.0 ms]
         [Humongous Total: 0]
         [Humongous Candidate: 0]
      [Humongous Reclaim: 0.0 ms]
         [Humongous Reclaimed: 0]
      [Free CSet: 0.0 ms]
         [Young Free CSet: 0.0 ms]
         [Non-Young Free CSet: 0.0 ms]
   [Eden: 22.0M(22.0M)->0.0B(16.0M) Survivors: 5120.0K->4096.0K Heap: 78.3M(100.0M)->65.5M(100.0M)]
 [Times: user=0.00 sys=0.00, real=0.00 secs] 
// 并发标记根扫描开始
2024-08-07T19:39:27.866+0800: [GC concurrent-root-region-scan-start]
// 并发标记根扫描结束，总耗时0.1862毫秒
2024-08-07T19:39:27.866+0800: [GC concurrent-root-region-scan-end, 0.0001862 secs]
// 并发标记子阶段开始，从所有的根引用出发，对整个堆进行标记
2024-08-07T19:39:27.866+0800: [GC concurrent-mark-start]
// 并发标记子阶段结束，总耗时0.5459毫秒。
2024-08-07T19:39:27.867+0800: [GC concurrent-mark-end, 0.0005459 secs]
// 重新标记（再标记）子阶段：
	// Finalize Marking: 完成标记过程,耗时0.0002165秒。
	// GC ref-proc: 处理引用对象,耗时 0.0000921 秒。
	// Unloading: 卸载未使用的类,包括 System Dictionary Unloading 和 Parallel Unloading 两个子阶段,总耗时0.0003583秒。
	// Deallocate Metadata: 释放元数据,耗时0.0000178秒。
	// 整个重新标子记阶段总耗时0.0009108秒。
2024-08-07T19:39:27.867+0800: [GC remark 2024-08-07T19:39:27.867+0800: [Finalize Marking, 0.0002165 secs] 2024-08-07T19:39:27.867+0800: [GC ref-proc, 0.0000921 secs] 2024-08-07T19:39:27.867+0800: [Unloading 2024-08-07T19:39:27.867+0800: [System Dictionary Unloading, 0.0000131 secs] 2024-08-07T19:39:27.867+0800: [Parallel Unloading, 0.0003452 secs] 2024-08-07T19:39:27.868+0800: [Deallocate Metadata, 0.0000178 secs], 0.0004277 secs], 0.0009108 secs]
 [Times: user=0.00 sys=0.00, real=0.00 secs] 
// 清理子阶段，整个清理阶段耗时0.0003662秒。
2024-08-07T19:39:27.868+0800: [GC cleanup 68M->68M(100M), 0.0003662 secs]
 [Times: user=0.00 sys=0.00, real=0.00 secs]

Mixed GC 日志

Mixed GC 其实和 YGC 的日志类似，这里也不再赘述。

2024-08-07T19:39:28.435+0800: [GC pause (G1 Evacuation Pause) (mixed) (to-space exhausted), 0.0007272 secs]
   [Parallel Time: 0.3 ms, GC Workers: 13]
      [GC Worker Start (ms):  1107.3  1107.3  1107.3  1107.3  1107.3  1107.4  1107.4  1107.4  1107.4  1107.4  1107.4  1107.4  1107.4
       Min: 1107.3, Avg: 1107.4, Max: 1107.4, Diff: 0.0]
      [Ext Root Scanning (ms):  0.1  0.1  0.1  0.1  0.1  0.1  0.1  0.1  0.1  0.1  0.1  0.1  0.1
       Min: 0.1, Avg: 0.1, Max: 0.1, Diff: 0.0, Sum: 1.4]
         [Thread Roots (ms):  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0
          Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
         [StringTable Roots (ms):  0.1  0.1  0.1  0.1  0.1  0.1  0.1  0.1  0.1  0.1  0.1  0.1  0.1
          Min: 0.1, Avg: 0.1, Max: 0.1, Diff: 0.0, Sum: 1.2]
         [Universe Roots (ms):  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0
          Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
         [JNI Handles Roots (ms):  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0
          Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
         [ObjectSynchronizer Roots (ms):  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0
          Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
         [FlatProfiler Roots (ms):  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0
          Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
         [Management Roots (ms):  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0
          Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
         [SystemDictionary Roots (ms):  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0
          Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
         [CLDG Roots (ms):  0.1  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0
          Min: 0.0, Avg: 0.0, Max: 0.1, Diff: 0.1, Sum: 0.1]
         [JVMTI Roots (ms):  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0
          Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
         [CodeCache Roots (ms):  0.0  0.0  0.0  0.1  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0
          Min: 0.0, Avg: 0.0, Max: 0.1, Diff: 0.0, Sum: 0.5]
         [CM RefProcessor Roots (ms):  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0
          Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
         [Wait For Strong CLD (ms):  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0
          Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
         [Weak CLD Roots (ms):  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0
          Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
         [SATB Filtering (ms):  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0
          Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
      [Update RS (ms):  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0
       Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.3]
         [Processed Buffers:  1  1  4  1  1  5  1  1  0  1  0  1  1
          Min: 0, Avg: 1.4, Max: 5, Diff: 5, Sum: 18]
      [Scan RS (ms):  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0
       Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.2]
      [Code Root Scanning (ms):  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0
       Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
      [Object Copy (ms):  0.1  0.1  0.1  0.1  0.1  0.1  0.1  0.1  0.1  0.1  0.1  0.1  0.1
       Min: 0.1, Avg: 0.1, Max: 0.1, Diff: 0.0, Sum: 1.3]
      [Termination (ms):  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0
       Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.2]
         [Termination Attempts:  1  1  2  1  1  1  1  1  1  2  1  1  1
          Min: 1, Avg: 1.2, Max: 2, Diff: 1, Sum: 15]
      [GC Worker Other (ms):  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0
       Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.1]
      [GC Worker Total (ms):  0.3  0.3  0.3  0.3  0.3  0.3  0.3  0.3  0.3  0.3  0.3  0.2  0.2
       Min: 0.2, Avg: 0.3, Max: 0.3, Diff: 0.0, Sum: 3.5]
      [GC Worker End (ms):  1107.6  1107.6  1107.6  1107.6  1107.6  1107.6  1107.6  1107.6  1107.6  1107.6  1107.6  1107.6  1107.6
       Min: 1107.6, Avg: 1107.6, Max: 1107.6, Diff: 0.0]
   [Code Root Fixup: 0.0 ms]
   [Code Root Purge: 0.0 ms]
   [Clear CT: 0.1 ms]
   [Other: 0.3 ms]
      [Evacuation Failure: 0.1 ms]
         [Recalculate Used: 0.0 ms]
         [Remove Self Forwards: 0.1 ms]
         [Restore RemSet: 0.0 ms]
      [Choose CSet: 0.0 ms]
      [Ref Proc: 0.1 ms]
      [Ref Enq: 0.0 ms]
      [Redirty Cards: 0.1 ms]
         [Parallel Redirty:  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0
          Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
         [Redirtied Cards:  25  10  0  0  0  0  0  0  0  0  0  0  0
          Min: 0, Avg: 2.7, Max: 25, Diff: 25, Sum: 35]
      [Humongous Register: 0.0 ms]
         [Humongous Total: 0]
         [Humongous Candidate: 0]
      [Humongous Reclaim: 0.0 ms]
         [Humongous Reclaimed: 0]
      [Free CSet: 0.0 ms]
         [Young Free CSet: 0.0 ms]
         [Non-Young Free CSet: 0.0 ms]
   [Eden: 1024.0K(4096.0K)->0.0B(5120.0K) Survivors: 1024.0K->0.0B Heap: 100.0M(100.0M)->100.0M(100.0M)]
 [Times: user=0.00 sys=0.00, real=0.00 secs]

Full GC 日志

// 这标志着一次Full GC的开始,原因是 Allocation Failure(内存分配失败)。在此次Full GC中,堆的已使用量从100M减少到61M,总堆大小为100M。
整个 Full GC 过程耗时 0.0112862 秒。
2024-08-07T19:39:28.437+0800: [Full GC (Allocation Failure)  100M->61M(100M), 0.0112862 secs]
	// Eden区的已使用空间从5120.0K降到0.0B(即为空)。
	// Survivor区的大小没有变化,始终为0.0B。
	// 整个堆空间使用量从100.0M降到61.6M。
	// Metaspace的占用量没有变化,仍为3901K,最大容量为1056768K。
   [Eden: 0.0B(5120.0K)->0.0B(15.0M) Survivors: 0.0B->0.0B Heap: 100.0M(100.0M)->61.6M(100.0M)], [Metaspace: 3901K->3901K(1056768K)]
 // 这记录了Full GC过程中CPU的使用情况：user time:0.01 秒、sys time:0.00 秒、real time:0.01 秒
 [Times: user=0.01 sys=0.00, real=0.01 secs]

JVM 性能分析 —— G1 日志分析

文章目录

日志级别

-XX:+PrintGC（简洁版）

-XX:+PrintGCDetails（详细版）

-XX:G1LogLevel=finest（非常详细版）

YGC 日志

并发标记日志

Mixed GC 日志

Full GC 日志

网站公告

今日签到

热门文章

最新发布