JAVA GC日志解析技巧：如何快速判断卡顿类型与根因

大家好！今天我们来聊聊Java GC（Garbage Collection）日志解析。GC是JVM自动内存管理的核心机制，但配置不当或应用代码问题可能导致频繁GC甚至长时间停顿，直接影响系统性能。理解并高效解析GC日志，是诊断和解决这类问题的关键。

本次讲座将着重讲解如何通过分析GC日志，快速判断卡顿的类型，并定位问题的根源。我们将从GC日志的基本格式入手，深入探讨不同GC算法产生的日志差异，并通过实例分析，演示如何利用工具和技巧，快速找出性能瓶颈。

一、GC日志的基本格式与解读

Java GC日志的格式并非一成不变，它取决于JVM版本、GC算法、以及GC日志配置参数。但无论格式如何，GC日志都包含一些核心信息：

时间戳： 记录GC发生的时间。绝对时间或相对时间都有可能。
GC类型： 指示是Minor GC（年轻代GC）、Major GC（老年代GC）或Full GC（全局GC）。
GC前后堆内存使用量： 记录GC前后堆的总容量、已使用容量、以及各分代（年轻代、老年代、元空间/永久代）的使用量。
GC耗时： 记录GC操作的持续时间。
GC原因： 记录触发GC的原因，例如Allocation Failure（分配失败）、System.gc()等。

以下是一个简单的GC日志示例（基于CMS GC）：

2023-10-27T10:00:00.123+0800: 1.234: [GC (Allocation Failure) [ParNew: 123456K->7890K(138240K), 0.0123456 secs] 234567K->12345K(456789K), 0.0124567 secs] [Times: user=0.02 sys=0.00, real=0.01 secs]

2023-10-27T10:00:00.123+0800: 绝对时间戳。
1.234: 相对时间戳（自JVM启动后的秒数）。
GC (Allocation Failure): 指示这是一个GC事件，触发原因是分配失败。
ParNew: 123456K->7890K(138240K), 0.0123456 secs: 使用ParNew收集器进行的年轻代GC。GC前年轻代使用123456K，GC后变为7890K，年轻代总容量为138240K，耗时0.0123456秒。
234567K->12345K(456789K), 0.0124567 secs: 整个堆的GC情况。GC前堆使用234567K，GC后变为12345K，堆总容量为456789K，总耗时0.0124567秒。
Times: user=0.02 sys=0.00, real=0.01 secs: 用户态CPU时间、系统态CPU时间和实际耗时。

二、不同GC算法的日志差异

不同的GC算法在日志格式和输出内容上存在显著差异。了解这些差异，有助于我们更准确地判断GC类型和问题根源。

GC算法	主要特征	日志关键信息
Serial	单线程GC，适用于小内存的单核服务器。	`[GC`, `[Full GC`，通常耗时较长。
ParNew	多线程的年轻代GC，与CMS配合使用。	`[ParNew: ...`
Parallel Scavenge	多线程的年轻代GC，关注吞吐量。	`[PSYoungGen: ...`
Parallel Old	多线程的老年代GC，与Parallel Scavenge配合使用。	`[ParOldGen: ...`
CMS	并发标记清除GC，尽量减少停顿时间。	`[CMS-concurrent-mark:` (并发标记阶段), `[CMS-concurrent-preclean:` (并发预清理阶段), `[CMS-concurrent-abortable-preclean:` (并发可中止预清理阶段), `[CMS-concurrent-sweep:` (并发清除阶段), `[CMS-concurrent-reset:` (并发重置阶段), `[CMS: ...` (停顿阶段，包括初始标记和重新标记)。
G1	分区化的GC，兼顾吞吐量和停顿时间。	`[GC pause (young)`, `[GC pause (mixed)`, `[Full GC (System.gc())`, 包含Region的信息，例如`regions=...`
ZGC	低延迟GC，适用于大内存环境。	`[ZGC pause`, 包含负载信息，例如`Load average: ...`
Shenandoah	低延迟GC，与ZGC类似，但实现方式不同。	`[Shenandoah GC pause`, 包含增量循环阶段的信息，例如`Init Mark`, `Concurrent Marking`, `Final Mark`等。

示例：CMS GC日志分析

2023-10-27T10:01:00.456+0800: 10.456: [GC (Allocation Failure) [ParNew: 138240K->8000K(138240K), 0.015 secs] 245760K->12000K(491520K), 0.015 secs] [Times: user=0.03 sys=0.00, real=0.01 secs]
2023-10-27T10:01:00.471+0800: 10.471: [CMS-concurrent-mark: 0.123/0.123 secs]
2023-10-27T10:01:00.594+0800: 10.594: [CMS-concurrent-preclean: 0.010/0.010 secs]
2023-10-27T10:01:00.604+0800: 10.604: [CMS-concurrent-abortable-preclean: 0.020/0.030 secs]
2023-10-27T10:01:00.634+0800: 10.634: [GC (CMS Final Remark) [YG occupancy: 1864K (138240K)][Rescan (parallel) , 0.008 secs][weak refs processing 0.000 secs][scrub symbol table 0.001 secs][scrub string table 0.000 secs]: 1864K->0K(138240K), 0.010 secs] 26440K->24576K(491520K), 0.010 secs] [Times: user=0.02 sys=0.00, real=0.01 secs]
2023-10-27T10:01:00.644+0800: 10.644: [CMS-concurrent-sweep: 0.030/0.030 secs]
2023-10-27T10:01:00.674+0800: 10.674: [CMS-concurrent-reset: 0.001/0.001 secs]

分析：

首先看到[ParNew: ...，表明发生了年轻代GC。
接着是CMS的并发阶段：[CMS-concurrent-mark: ..., [CMS-concurrent-preclean: ..., [CMS-concurrent-abortable-preclean: ..., [CMS-concurrent-sweep: ..., [CMS-concurrent-reset: ...。这些阶段是并发执行的，不会导致应用停顿。
[GC (CMS Final Remark) ...表明CMS进入最终标记阶段，这是一个Stop-The-World (STW)事件，需要暂停应用。

示例：G1 GC日志分析

2023-10-27T10:02:00.789+0800: 20.789: [GC pause (young) (normal) (to-space exhausted) , 0.0123456 secs]
   [Eden: 64M(64M)->0B(64M) Survivors: 0B->8192K Heap: 256M(256M)->10M(256M)]
   [Times: user=0.02 sys=0.00, real=0.01 secs]
2023-10-27T10:02:00.801+0800: 20.801: [GC pause (mixed) (normal) , 0.0234567 secs]
   [Eden: 0B(64M)->0B(64M) Survivors: 8192K->8192K Heap: 10M(256M)->5M(256M)]
   [Old: 2M->1M(192M)]
   [Times: user=0.04 sys=0.00, real=0.02 secs]

分析：

[GC pause (young) ...表明发生了年轻代GC，触发原因是to-space exhausted，说明Survivor空间不足。
[GC pause (mixed) ...表明发生了混合GC，既清理年轻代，也清理部分老年代Region。

三、快速判断卡顿类型

通过GC日志，我们可以快速判断卡顿的类型，主要分为以下几种：

频繁的Minor GC：
- 现象： GC日志中[ParNew: ... (CMS) 或 [PSYoungGen: ... (Parallel Scavenge) 或 [GC pause (young) ... (G1) 等年轻代GC日志非常频繁。
- 原因： 对象创建速率过快，导致年轻代很快被填满。
- 诊断方向： 检查代码中是否存在大量临时对象的创建，例如循环中创建大量对象，或不必要的对象复制。
长时间的Major GC/Full GC：
- 现象： GC日志中 [CMS: ... (CMS) 或 [ParOldGen: ... (Parallel Old) 或 [Full GC ... (Serial/G1) 等老年代GC日志耗时较长。
- 原因： 老年代空间不足，或者发生了System.gc()。
- 诊断方向： 检查是否存在内存泄漏，导致老年代对象不断增长；检查是否显式调用了System.gc()（应尽量避免）。
CMS并发阶段耗时过长：
- 现象： CMS的并发标记、并发预清理等阶段耗时较长，导致后续的Full GC更加频繁。
- 原因： 老年代对象数量过多，导致并发阶段扫描时间过长；或者CMS的触发阈值设置不合理。
- 诊断方向： 检查老年代对象数量，调整CMS相关参数，例如-XX:CMSInitiatingOccupancyFraction。
G1混合GC停顿时间过长：
- 现象： [GC pause (mixed) ... 停顿时间超过预期。
- 原因： G1选择的需要回收的Region过多，导致停顿时间过长；或者G1的回收速率跟不上对象产生速率。
- 诊断方向： 调整G1相关参数，例如-XX:MaxGCPauseMillis、-XX:G1MixedGCLiveThresholdPercent。

四、定位卡顿根因

确定了卡顿类型后，我们需要进一步定位问题的根源。以下是一些常用的方法和工具：

JConsole/VisualVM：
- 功能： 可视化监控JVM的内存使用情况、GC活动、线程状态等。
- 用途： 实时观察堆内存各分代的增长趋势，以及GC的频率和耗时。
Jmap：
- 功能： 生成堆转储快照（Heap Dump）。
- 用途： 分析堆中对象的分布情况，找出占用内存最多的对象，以及对象之间的引用关系，帮助定位内存泄漏。
```
jmap -dump:format=b,file=heapdump.bin <pid>
```
MAT (Memory Analyzer Tool)：
- 功能： 分析Heap Dump文件。
- 用途： 提供强大的对象查询、引用分析、泄漏检测等功能，帮助定位内存泄漏。
JProfiler/YourKit：
- 功能： 商业的Java性能分析工具，提供更全面的性能分析功能，包括CPU使用率、内存分配、线程阻塞等。
- 用途： 详细分析代码的性能瓶颈，例如找出耗时的方法调用、频繁的对象创建等。
代码审查：
- 功能： 人工检查代码。
- 用途： 检查是否存在内存泄漏、不合理的对象创建、锁竞争等问题。

实例分析：内存泄漏

假设我们通过JConsole发现老年代持续增长，最终导致Full GC频繁发生。我们可以使用Jmap生成Heap Dump，然后使用MAT分析：

生成Heap Dump： jmap -dump:format=b,file=heapdump.bin <pid>
使用MAT打开heapdump.bin。
在MAT中，可以使用"Leak Suspects"报告来查找潜在的内存泄漏。 MAT会自动分析对象之间的引用关系，找出可疑的泄漏点。
如果"Leak Suspects"报告没有明确的线索，可以使用OQL (Object Query Language) 来查询占用内存最多的对象。 例如：
```
SELECT * FROM java.lang.Object s WHERE s.class.name LIKE "%MyObject%"
```
这个查询会找出所有类名包含"MyObject"的对象。
通过分析这些对象的引用链，可以找到导致它们无法被回收的原因。 可能是某个静态变量持有这些对象的引用，或者某个长生命周期的对象持有这些对象的引用。
修改代码，移除这些不必要的引用，即可解决内存泄漏问题。

实例分析：频繁的Minor GC

假设我们发现Minor GC非常频繁，通过JConsole观察到年轻代Eden区很快就被填满。

使用JProfiler/YourKit等工具，监控应用的内存分配情况。
找出创建对象最多的方法。 通常是循环内部创建大量临时对象，或者使用了不必要的对象复制。
优化代码，减少对象的创建。 例如使用对象池来复用对象，或者使用StringBuilder代替String的"+"操作。
如果确实需要创建大量对象，可以考虑增大年轻代的大小，减少Minor GC的频率。 但是需要注意，年轻代过大会增加Full GC的耗时。

五、GC日志分析工具

除了手动分析GC日志，还可以使用一些GC日志分析工具，它们可以自动解析GC日志，并生成报告，帮助我们更快速地找到问题。

GCeasy: 在线GC日志分析工具，支持多种GC算法的日志格式，提供可视化报告和性能建议。
HP Jmeter: 提供GC分析插件，可以与Jmeter集成，在性能测试过程中分析GC情况。
GCHisto: 命令行GC日志分析工具，可以生成GC统计信息和图表。

六、优化建议

在分析GC日志的基础上，我们可以采取一些措施来优化GC性能：

合理设置堆大小： 堆太小会导致频繁GC，堆太大则会增加Full GC的耗时。需要根据应用的实际情况进行调整。
选择合适的GC算法： 根据应用的特点选择合适的GC算法。例如，对延迟敏感的应用可以选择CMS或G1，对吞吐量要求高的应用可以选择Parallel Scavenge。
调整GC相关参数： 根据GC日志的分析结果，调整GC的相关参数，例如年轻代大小、老年代触发阈值、G1的回收速率等。
优化代码： 避免内存泄漏、减少对象创建、使用对象池等。
避免显式调用System.gc()： System.gc()会触发Full GC，通常会导致应用长时间停顿。

七、GC日志配置

开启GC日志是进行GC分析的前提。以下是一些常用的GC日志配置参数：

-verbose:gc：启用GC日志输出。
-XX:+PrintGCDetails：打印GC详细信息。
-XX:+PrintGCTimeStamps：打印GC时间戳。
-XX:+PrintGCDateStamps：打印GC日期时间戳。
-Xloggc:<file>：将GC日志输出到指定文件。
-XX:+UseGCLogFileRotation：启用GC日志文件滚动。
-XX:NumberOfGCLogFiles=<n>：设置GC日志文件数量。
-XX:GCLogFileSize=<size>：设置GC日志文件大小。
-XX:+HeapDumpOnOutOfMemoryError：在发生OOM时生成Heap Dump。
-XX:HeapDumpPath=<path>：设置Heap Dump文件路径。
-Xlog:gc*:file=<file>： JDK9及以上版本使用，更灵活的GC日志配置。

如何持续优化

持续优化，需要监控告警，需要将GC日志分析纳入日常监控体系，设置合理的阈值，例如：

Minor GC频率： 如果Minor GC频率过高，需要及时报警。
Full GC频率： 如果Full GC频率超过阈值，需要及时报警。
GC停顿时间： 如果GC停顿时间超过阈值，需要及时报警。

通过监控和告警，可以及时发现GC问题，并采取相应的措施进行优化。

希望今天的分享能帮助大家更好地理解和分析Java GC日志，快速定位卡顿原因，提升系统性能。

总结：关键在于理解和实践

理解GC日志的格式和含义是基础，实践分析不同GC算法的日志是提升技能的关键。工具的使用可以辅助分析，但代码审查和优化才是最终的解决之道。记住，持续的监控和优化，才能保证系统的稳定运行。

JAVA GC日志解析技巧：如何快速判断卡顿类型与根因

发表回复 取消回复

发表回复取消回复