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

关注

VIP免费原创 2024-12-21 20:10:21 2.1k 阅读 AI 写同款· GEO 优化 ›

jvm：jvm GC日志解析：G1日志解析 1、背景简介 1.1、应用背景介绍 1）业务特点：流量高峰都集中在白天，凌晨流量很低。 2）应用特点：对外提供了很多核心业务接口，早6点之后，流量逐渐增加。凌晨会通过自动化调度，跑一些数据处理任务，主要都是核心业务数据的缓存预热【从DB(mysql/es)读取，写入到redis】。 1.2、jdk版本(openjdk) 由于oracle声明将针对企业用户对于JDK 8 u191之后的版本需要付费购买商业许可。所以公司统一都切换到了openjdk，目前应用的版本是：openjdk 1.8.0_272- 阅读详情

日志级别

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]