4. CMS GC 日志解读：GC 日志格式、关键参数、如何开启 GC 日志、日志分析工具介绍
在《数据库迁移版本变更引发的 CMS GC 异常排查》案例中，CMS GC 日志是定位问题的第一手证据。本章将系统讲解 CMS GC 日志的格式、关键参数含义、开启方式以及主流分析工具，帮助你在实战中快速从日志中提取有效信息。
4.1 如何开启 CMS GC 日志
JVM 提供了一组标准参数用于输出 GC 详细日志。以下是在 JDK 8 环境下开启 CMS GC 日志的推荐配置：
-XX:+UseConcMarkSweepGC
-XX:+PrintGCDetails
-XX:+PrintGCDateStamps
-XX:+PrintGCTimeStamps
-XX:+PrintHeapAtGC
-Xloggc:/path/to/gc.log
-XX:+PrintTenuringDistribution
-XX:+PrintReferenceGC
-XX:+PrintAdaptiveSizePolicy
参数说明：
-XX:+PrintGCDetails：输出 GC 前后堆内存详细使用情况，包括年轻代、老年代、元空间。-XX:+PrintGCDateStamps：输出 GC 发生的绝对时间戳（如 2025-03-15T10:30:00.123+0800），便于与业务日志关联。-XX:+PrintGCTimeStamps：输出 JVM 启动后的相对时间（秒），用于分析 GC 频率。-XX:+PrintHeapAtGC：在每次 GC 前后输出完整的堆布局，对排查内存碎片化非常关键。-XX:+PrintTenuringDistribution：输出对象年龄分布，帮助判断晋升阈值是否合理。-XX:+PrintReferenceGC：输出软引用、弱引用、虚引用处理情况，CMS 并发周期中会处理这些引用。
4.2 CMS GC 日志格式详解
CMS 的 GC 日志分为 年轻代 GC（ParNew） 和 老年代 GC（CMS） 两大类。下面通过一个典型日志片段逐行解读。
4.2.1 ParNew 年轻代 GC 日志
2025-03-15T10:30:00.123+0800: 1234.567: [GC (Allocation Failure) 2025-03-15T10:30:00.123+0800: 1234.567: [ParNew: 524288K->65536K(589824K), 0.0456789 secs] 1048576K->589824K(2031616K), 0.0467890 secs] [Times: user=0.12 sys=0.01, real=0.05 secs]| 日志片段 | 含义 |
|---|---|
2025-03-15T10:30:00.123+0800 |
GC 发生的绝对时间 |
1234.567 |
JVM 启动后的相对时间（秒） |
GC (Allocation Failure) |
GC 原因：年轻代分配失败 |
ParNew: 524288K->65536K(589824K) |
年轻代使用量：GC 前 524288K → GC 后 65536K，总容量 589824K |
0.0456789 secs |
年轻代 GC 耗时 |
1048576K->589824K(2031616K) |
堆总使用量：GC 前 1048576K → GC 后 589824K，总堆容量 2031616K |
Times: user=0.12 sys=0.01, real=0.05 secs |
用户态 CPU 时间、内核态 CPU 时间、实际挂钟时间 |
4.2.2 CMS 老年代 GC 日志
CMS 的 GC 日志包含多个阶段，每个阶段都有独立的耗时记录。以下是一个完整的 CMS 并发周期日志：
2025-03-15T10:35:00.456+0800: 1834.567: [GC (CMS Initial Mark) [1 CMS-initial-mark: 1048576K(1572864K)] 1179648K(2031616K), 0.0123456 secs] [Times: user=0.02 sys=0.00, real=0.01 secs]
2025-03-15T10:35:00.469+0800: 1834.580: [CMS-concurrent-mark-start]
2025-03-15T10:35:00.789+0800: 1834.900: [CMS-concurrent-mark: 0.320 secs]
2025-03-15T10:35:00.790+0800: 1834.901: [CMS-concurrent-preclean-start]
2025-03-15T10:35:00.810+0800: 1834.921: [CMS-concurrent-preclean: 0.020 secs]
2025-03-15T10:35:00.811+0800: 1834.922: [CMS-concurrent-abortable-preclean-start]
2025-03-15T10:35:01.200+0800: 1835.311: [CMS-concurrent-abortable-preclean: 0.389 secs]
2025-03-15T10:35:01.201+0800: 1835.312: [GC (CMS Final Remark) [YG occupancy: 327680K(589824K)] [Rescan (parallel) , 0.0234567 secs] [weak refs processing, 0.0012345 secs] [class unloading, 0.0034567 secs] [scrub symbol table, 0.0005678 secs] [scrub string table, 0.0006789 secs] [1 CMS-remark: 1048576K(1572864K)] 1376256K(2031616K), 0.0298765 secs] [Times: user=0.08 sys=0.01, real=0.03 secs]
2025-03-15T10:35:01.231+0800: 1835.342: [CMS-concurrent-sweep-start]
2025-03-15T10:35:01.450+0800: 1835.561: [CMS-concurrent-sweep: 0.219 secs]
2025-03-15T10:35:01.451+0800: 1835.562: [CMS-concurrent-reset-start]
2025-03-15T10:35:01.460+0800: 1835.571: [CMS-concurrent-reset: 0.009 secs]
CMS 各阶段关键解读：
- Initial Mark（初始标记）：STW 暂停，标记 GC Roots 直接引用的对象。耗时通常很短（毫秒级）。
- Concurrent Mark（并发标记）：与应用线程并发执行，遍历对象图。日志中显示耗时 0.320 秒。
- Concurrent Preclean（并发预清理）：处理并发标记期间发生变化的对象，减少 Final Remark 的负担。
- Concurrent Abortable Preclean（可中断预清理）：等待年轻代 GC 发生，以降低 Final Remark 时的年轻代大小。
- Final Remark（最终标记）：STW 暂停，处理并发阶段遗漏的引用。日志中展示了 Rescan、weak refs processing、class unloading 等子阶段耗时。
- Concurrent Sweep（并发清除）：回收死亡对象占用的内存空间。
- Concurrent Reset（并发重置）：重置 CMS 内部数据结构，为下一次 GC 做准备。
4.3 CMS GC 日志中的关键指标
在排查 CMS GC 异常时，以下指标需要重点关注：
| 指标 | 正常范围 | 异常信号 |
|---|---|---|
| Initial Mark 暂停时间 | < 50ms | > 100ms 可能表示 GC Roots 扫描压力大 |
| Final Remark 暂停时间 | < 200ms | > 500ms 可能表示年轻代过大或引用处理慢 |
| Concurrent Mode Failure | 不应出现 | 出现则触发 Serial Old 后备 GC，暂停时间可达秒级 |
| 晋升失败（Promotion Failed） | 不应出现 | 老年代碎片化严重，导致对象无法晋升 |
| 老年代占用率（CMS 触发前） | < 70% | > 80% 可能触发频率过高或内存泄漏 |
| 并发阶段耗时 | 与 CPU 核数相关 | 单次并发标记 > 5 秒可能 CPU 竞争激烈 |
4.4 CMS GC 日志分析工具介绍
手动分析海量 GC 日志效率低下，推荐使用以下工具进行自动化分析：
| 工具名称 | 类型 | 核心功能 | 适用场景 |
|---|---|---|---|
| GCeasy | 在线 Web | 自动识别 GC 问题、生成报告、推荐 JVM 参数 | 快速诊断，适合非生产环境 |
| GCViewer | 桌面工具 | 可视化 GC 日志，展示吞吐量、暂停时间、堆使用趋势 | 深度分析，支持自定义图表 |
| GCEasy (IBM) | 在线 Web | 支持 CMS/G1/ZGC 多种 GC 算法，提供性能评分 | 多算法对比分析 |
| jstat | 命令行 | 实时查看 GC 统计信息，无需日志文件 | 线上快速排查 |
| jcmd | 命令行 | 动态开启/关闭 GC 日志，查看 GC 原因 | 生产环境动态诊断 |
实战建议：在数据库迁移场景中，建议同时使用 GCViewer 查看堆使用趋势图，配合 GCeasy 的自动问题检测功能。如果发现 Concurrent Mode Failure，立即检查老年代碎片率和 CMS 触发阈值（-XX:CMSInitiatingOccupancyFraction）。
4.5 CMS GC 日志分析流程（SVG 图）
以下流程图展示了从原始日志到问题定位的完整分析路径：
4.6 实战案例：从日志中识别 CMS 异常
以下是一个数据库迁移过程中出现的典型异常日志片段：
2025-03-15T11:00:00.789+0800: 3600.900: [GC (CMS Initial Mark) [1 CMS-initial-mark: 1572864K(1572864K)] 1835008K(2031616K), 0.0890123 secs]
2025-03-15T11:00:01.200+0800: 3601.311: [GC (CMS Final Remark) [YG occupancy: 524288K(589824K)] [Rescan (parallel) , 0.1234567 secs] ... [1 CMS-remark: 1572864K(1572864K)] 2097152K(2031616K), 0.1456789 secs]
2025-03-15T11:00:01.500+0800: 3601.611: [Full GC (Allocation Failure) 2025-03-15T11:00:01.500+0800: 3601.611: [CMS: 1572864K->1572864K(1572864K), 5.2345678 secs] 2097152K->2097152K(2031616K), [Metaspace: 256000K->256000K(262144K)], 5.2456789 secs]
异常信号解读：
- CMS Initial Mark 耗时 89ms：明显偏高，正常应在 10-30ms 之间，说明 GC Roots 扫描压力大。
- Final Remark 耗时 145ms：偏高，年轻代占用 524288K（约 512MB），Rescan 阶段耗时 123ms。
- Full GC (Allocation Failure)：触发了 Serial Old 后备 GC，耗时 5.2 秒，这是 CMS 退化为串行 GC 的典型表现。
- CMS 前后老年代占用均为 1572864K：说明 CMS 并发周期未能回收任何内存，所有对象都是存活的，导致 Concurrent Mode Failure。
排查方向：结合数据库迁移场景，怀疑是连接池配置过大导致大量长连接对象长期存活，或者新版本 ORM 框架产生了大量临时对象晋升到老年代。建议检查
-XX:CMSInitiatingOccupancyFraction 是否设置过低（默认 68%），以及老年代碎片化程度。