程序员scholar
  • Java底层
  • Java底层 - JVM
scholar
2024-02-01
目录

JVM - 分析GC日志

# 1. GC 类型详解

在 HotSpot 虚拟机中，垃圾收集 (Garbage Collection, GC) 根据其操作范围的不同，主要可以分为两大类：部分收集 (Partial GC) 和整堆收集 (Full GC)。

  • 部分收集 (Partial GC)：指并非对整个 Java 堆进行回收的 GC 事件。它又可以细分为：

    • 新生代收集 (Minor GC / Young GC / YGC)：最常见的 GC 类型，仅对新生代（Eden 区和两个 Survivor 区）进行的垃圾收集。Minor GC 通常比较频繁，但回收速度也比较快，STW (Stop-The-World) 时间较短。
    • 老年代收集 (Major GC / Old GC)：仅对老年代进行的垃圾收集。在 HotSpot 中，目前只有 CMS (Concurrent Mark Sweep) 垃圾收集器会存在单独收集老年代的行为。
    • 重要区分：很多情况下，Major GC 会与 Full GC 概念混淆。当谈论 Major GC 时，需要根据上下文判断，它可能指代单独的老年代回收 (特指 CMS)，也可能泛指 Full GC（尤其是在 Parallel Scavenge 等收集器中，它们通常没有单独的老年代回收）。本篇后续如无特指，将 Full GC 用于描述整堆回收。
    • 混合收集 (Mixed GC)：同时收集整个新生代以及部分老年代区域的垃圾收集。这是 G1 (Garbage-First) 收集器独有的回收模式。

  • 整堆收集 (Full GC)：对整个 Java 堆（包括新生代和老年代）以及方法区 (Metaspace/PermGen) 进行的全面垃圾收集。Full GC 通常意味着较长时间的 STW，对应用程序的响应性能影响最大，是 JVM 调优中需要重点关注和尽量避免的目标。

常见触发 Full GC 的情况：

  1. 老年代空间不足: 当对象从新生代晋升到老年代，或者有大对象直接尝试在老年代分配时，如果老年代剩余空间不足以容纳这些对象，会触发 Full GC。
  2. 方法区/元空间不足: 当加载的类信息、常量池等数据填满了方法区或元空间（达到 -XX:MaxMetaspaceSize 或 -XX:MaxPermSize 限制）时，会触发 Full GC 来尝试回收不再使用的类和元数据。
  3. 显式调用 System.gc(): 程序代码中直接调用 System.gc() 方法建议 JVM 进行 Full GC。虽然不保证立即执行，但通常会触发。可以通过 -XX:+DisableExplicitGC 参数禁用此行为。
  4. Minor GC 后晋升老年代的平均大小 > 老年代可用内存: 这是一种动态判断机制。如果在 Minor GC 后，JVM 预估存活并需要晋升到老年代的对象平均大小超过了老年代当前可用的连续空间，可能会提前触发 Full GC 以确保有足够空间。
  5. CMS GC 出现 concurrent mode failure: 在 CMS 并发执行过程中，如果业务线程创建对象的速度超过了 CMS 回收的速度，导致老年代空间不足以容纳新对象，CMS 会失败，JVM 会退化 (Fallback) 到使用单线程的 Serial Old 收集器进行 Full GC，这会导致非常长的 STW。
  6. G1 GC 在 Mixed GC 期间无法回收足够内存: G1 的 Mixed GC 如果执行后，老年代空间仍然不足，或者并发标记过程中发现需要回收整个堆，也可能触发 Full GC (通常是 G1 自己实现的 Full GC，也可能是退化)。

# 2. GC 日志分类与示例

GC 日志是分析 JVM 内存和 GC 行为最直接、最重要的依据。不同的 GC 类型会产生不同格式的日志。

# Minor GC (Young GC) 日志示例

[GC (Allocation Failure) [PSYoungGen: 31744K->2192K(36864K)] 31744K->2200K(121856K), 0.0139308 secs] [Times: user=0.05 sys=0.01, real=0.01 secs]
1

日志解读:

image-20220201230156081 (图示：Minor GC 日志结构概览)

image-20210506202156090 (图示：Minor GC 日志各部分详细含义)

  • [GC 或 [Full GC: 表明 GC 的类型。这里是 [GC，代表部分收集，结合后面的 PSYoungGen 可知是 Minor GC。
  • (Allocation Failure): GC 触发原因。Allocation Failure 表示本次 GC 是因为新生代空间不足，无法为新创建的对象分配内存而触发的。这是最常见的 Minor GC 原因。
  • [PSYoungGen: 31744K->2192K(36864K)]:
    • PSYoungGen: GC 发生的区域。PSYoungGen 表示使用的是 Parallel Scavenge 收集器管理的新生代。不同收集器名称不同（见后文）。
    • 31744K: GC 前新生代已使用的大小 (字节 K)。
    • -> 2192K: GC 后新生代已使用的大小 (字节 K)。通常是存活对象被移到 Survivor 区或晋升到老年代后的大小。
    • (36864K): 新生代总容量 (字节 K)。注意：这里的总容量通常指 Eden 区 + 一个 Survivor 区的大小 (From 或 To 区)，因为 Minor GC 时只有一个 Survivor 区是活跃的（To 区）。所以它并不完全等于 Eden + S0 + S1 的总和。
  • 31744K->2200K(121856K):
    • 31744K: GC 前整个 Java 堆已使用的大小。
    • -> 2200K: GC 后整个 Java 堆已使用的大小。对比 GC 前后的堆大小变化，可以大致了解有多少对象被回收，有多少晋升到了老年代。
    • (121856K): 整个 Java 堆的总容量。
  • 0.0139308 secs: 本次 GC 事件持续的总时间 (STW 时间)，单位是秒。这是衡量 GC 性能的关键指标之一。
  • [Times: user=0.05 sys=0.01, real=0.01 secs]: 提供更详细的 GC 耗时信息 (见后文解释)。

# Full GC 日志示例

[Full GC (Metadata GC Threshold) [PSYoungGen: 5104K->0K(132096K)] [ParOldGen: 416K->5453K(50176K)] 5520K->5453K(182272K), [Metaspace: 20637K->20637K(1067008K)], 0.0245883 secs] [Times: user=0.06 sys=0.00, real=0.02 secs]
1

日志解读:

image-20220201230218472 (图示：Full GC 日志结构概览)

image-20210506202349072 (图示：Full GC 日志各部分详细含义)

  • [Full GC: 表明这是一次整堆收集。
  • (Metadata GC Threshold): GC 触发原因。Metadata GC Threshold 表示此次 Full GC 是因为元空间 (Metaspace) 使用量达到了阈值，需要回收类元数据等。
  • [PSYoungGen: 5104K->0K(132096K)]: Full GC 通常也会清理新生代。显示新生代 (PSYoungGen) 在 GC 前后的内存使用变化。这里从 5104K 降到了 0K。
  • [ParOldGen: 416K->5453K(50176K)]:
    • ParOldGen: GC 发生的区域。ParOldGen 表示使用的是 Parallel Old 收集器管理的老年代。
    • 416K->5453K(50176K): 老年代在 GC 前后及总容量。这里看到 GC 后老年代使用量反而增加了 (从 416K 到 5453K)，这通常意味着 Full GC 过程中，新生代的一些存活对象被晋升到了老年代。
  • 5520K->5453K(182272K): 整个堆在 GC 前后的内存使用变化及总容量。
  • [Metaspace: 20637K->20637K(1067008K)]:
    • Metaspace: 显示元空间的 GC 情况。
    • 20637K->20637K(1067008K): 元空间在 GC 前后的使用变化及总容量 (配置的最大值)。这里看到使用量没有减少，说明本次 Full GC (虽然由 Metaspace 触发) 未能成功卸载任何类。
  • 0.0245883 secs: 本次 Full GC 事件持续的总时间 (STW 时间)。
  • [Times: user=0.06 sys=0.00, real=0.02 secs]: 详细耗时信息。

# 3. GC 日志结构深度剖析

理解 GC 日志的关键在于识别其中的各个组成部分及其含义。

# 识别垃圾收集器类型

日志中表示回收区域的名称直接反映了所使用的垃圾收集器：

  • Serial 收集器 (新生代): [DefNew (Default New Generation)
  • ParNew 收集器 (新生代): [ParNew (Parallel New Generation)
  • Parallel Scavenge 收集器 (新生代): [PSYoungGen (常用，JDK 8 Server 默认)
  • Serial Old 收集器 (老年代): [Tenured (有时也可能叫 SerialOld 或其他，不常见)
  • Parallel Old 收集器 (老年代): [ParOldGen (Parallel Old Generation, 搭配 Parallel Scavenge)
  • CMS 收集器 (老年代): [CMS (Concurrent Mark Sweep) - 日志格式更复杂，包含并发阶段信息。
  • G1 收集器: 日志格式完全不同，通常包含 [GC pause (G1 Evacuation Pause) (young) 或 (mixed) 等标识，并以 Region 为单位报告回收情况，不直接显示 YoungGen 或 OldGen 整体。

# 解读 GC 触发原因

括号中紧跟 GC 或 Full GC 的内容说明了触发本次 GC 的原因：

  • Allocation Failure: 最常见的新生代 GC 原因，表示在新生代 Eden 区分配对象时空间不足。
  • Metadata GC Threshold: (JDK 8+) 由于 Metaspace 使用量达到阈值 (由 -XX:MetaspaceSize 和 -XX:MinMetaspaceFreeRatio 等参数控制) 而触发的 Full GC。
  • CMS Initial Mark / CMS Final Remark / CMS Concurrent Mark 等: CMS 收集器不同阶段的标识。
  • G1 Evacuation Pause (young) / (mixed): G1 收集器的 Minor GC 或 Mixed GC。
  • Ergonomics: JVM 内部根据自适应策略 (如 UseAdaptiveSizePolicy 开启时) 判断需要进行 GC 以满足性能目标 (如停顿时间、吞吐量) 而触发。
  • System.gc(): 程序代码中显式调用了 System.gc() 方法。

# 分析 GC 前后内存变化

日志中 [区域名: X K -> Y K (Z K)] 和 A K -> B K (C K) 的格式非常重要：

  • [区域名: X K -> Y K (Z K)]:

    • 区域名: 如 PSYoungGen, ParOldGen, Metaspace。
    • X: 该区域在 GC 前 已使用的内存大小 (KB)。
    • Y: 该区域在 GC 后 已使用的内存大小 (KB)。
    • Z: 该区域的总容量 (KB)。
      • 重点注意: 对于新生代 (YoungGen)，这个 Z 通常不等于 Eden + S0 + S1 的总和，而是等于 Eden + 一个 Survivor 区 的大小，因为 Minor GC 时只有一个 Survivor 区是活跃的 (作为 To Space)。

  • A K -> B K (C K):

    • 这部分表示整个 Java 堆（新生代 + 老年代）在 GC 前后的内存使用情况。
    • A: GC 前 整个堆已使用的内存大小 (KB)。
    • B: GC 后 整个堆已使用的内存大小 (KB)。 A - B 大致等于本次 GC 回收的总内存量（不完全精确，因为可能有新对象分配）。
    • C: 整个堆的总容量 (KB)。

通过比较 GC 前后各区域及总堆内存的变化，可以推断：

  • Minor GC 回收了多少新生代内存 (YoungGen 的 X - Y)。
  • 有多少对象从新生代晋升到了老年代（OldGen 的 Y - X，或通过 Heap 的 B - OldGen Y - YoungGen Y 计算）。
  • Full GC 回收了多少老年代内存 (OldGen 的 X - Y)。
  • Full GC 是否成功回收了 Metaspace 或卸载了类 (Metaspace 的 X - Y)。

# 理解 GC 耗时 (user, sys, real)

日志末尾的 [Times: user=U sys=S, real=R secs] 提供了 GC 执行时间的详细分类：

  • user: 指 CPU 在用户态 (User Mode) 执行 GC 代码所花费的 CPU 时间总和。这部分时间是 GC 线程实际消耗的 CPU 计算时间。如果 GC 是多线程并行的，user 时间是所有线程消耗的 CPU 时间之和。
  • sys: 指 CPU 在内核态 (Kernel Mode) 执行 GC 相关操作（如系统调用、等待系统资源）所花费的 CPU 时间总和。通常较小。
  • real: 指从 GC 事件开始到结束所经历的墙钟时间 (Wall Clock Time)，也就是应用程序实际停顿 (STW) 的时间。这是用户感受到的卡顿时间。

时间关系分析:

  • 对于并行 GC (Parallel GC, ParNew, G1 的 STW 阶段)：由于多个 GC 线程同时工作，它们消耗的 CPU 时间总和 (user + sys) 通常会大于实际经历的墙钟时间 (real)。例如，如果有 4 个核并行 GC，理想情况下 real ≈ (user + sys) / 4。
  • 对于串行 GC (Serial GC)：只有一个 GC 线程工作，理论上 real ≈ user + sys。
  • 如果 real >> (user + sys): 这通常意味着 GC 过程中存在非 CPU 瓶颈，导致 GC 线程等待时间过长。常见原因包括：
    • 操作系统 I/O 负载过高: 例如，磁盘读写繁忙、网络拥塞，导致 GC 需要等待 I/O 操作完成（如日志写入、内存交换 Swapping）。
    • CPU 资源不足/竞争: 系统中其他进程占用了大量 CPU，导致 GC 线程无法获得足够的 CPU 时间片。
    • JVM 进程被换出 (Swapped out): 如果物理内存不足，操作系统可能将 JVM 进程的部分内存交换到磁盘，GC 时需要换回，导致大量等待。

因此，分析 user, sys, real 时间有助于判断 GC 慢的原因是 GC 任务本身繁重，还是受到了外部环境的影响。

# 4. GC 日志分析工具推荐

手动分析 GC 日志费时费力且容易出错，使用专业的 GC 日志分析工具可以大大提高效率。

  • GCEasy

    • 官网: https://gceasy.io/
    • 特点:
      • 在线分析器，直接上传 GC 日志文件即可获得分析报告。
      • 功能强大，提供内存泄漏检测、GC 暂停原因分析、JVM 配置建议、关键性能指标 (吞吐量、延迟)、交互式图表等。
      • 界面友好，易于使用。
      • 大部分核心功能免费，高级功能可能需要付费。
    • 适用场景: 快速诊断、获取优化建议、可视化分析。

  • GCViewer

    • 源码: https://github.com/chewiebug/GCViewer
    • 下载/Wiki: https://github.com/chewiebug/GCViewer/wiki/Changelog
    • 特点:
      • 离线分析工具 (Java 程序)，需要下载运行。
      • 专门用于可视化 GC 日志数据 (-verbose:gc 或 -Xloggc 生成的日志)。
      • 生成各种图表，如堆内存变化、GC 暂停时间分布、吞吐量等。
      • 计算关键性能指标（累积暂停、最长暂停、吞吐量等）。
      • 开源免费。
    • 适用场景: 本地详细分析 GC 日志、可视化 GC 过程、对比调优前后效果。

  • GCHisto

    • 特点: 较旧的工具，似乎已停止维护，可能存在 Bug。需要从 SVN 拉取源码编译。不推荐作为首选。

  • HPjmeter (源自 HP)

    • 特点: 功能强大，但可能只支持特定格式的 GC 日志（例如 HP JVM 或特定参数生成的日志）。集成了 HPjtune 功能。使用上可能有限制。

建议: 对于大多数用户，GCEasy (在线) 和 GCViewer (离线) 是分析 GC 日志的优秀选择，功能覆盖全面且易于使用。结合这些工具，可以更深入地理解应用的 GC 行为，并有效地进行 JVM 调优。

编辑此页 (opens new window)
上次更新: 2025/04/05, 20:16:54
JVM - 运行时参数

←

Theme by Vdoing | Copyright © 2019-2025 程序员scholar