GC日志中实际停顿时间怎么看
在java垃圾回收（gc）日志中，查看实际停顿时间（stop-the-world, stw）主要关注日志中带有 [gc pause (young) 或 [full gc (ergonomics) 等标记的行。这些行末尾通常会显示一个以毫秒为单位的数值，例如 0.0156s 或 15.6 ms，这就是该次gc导致的实际应用停顿时间。
JDK 8与JDK 17的日志格式差异
JDK 8及更早版本使用默认的 -XX:+PrintGCDetails 输出格式，而 JDK 9 引入的 -Xlog:gc* 统一日志框架提供了更结构化、易解析的日志格式。两者在停顿时间的展示位置和语法上存在显著差异，理解这些差异有助于快速定位问题。
import java.util.ArrayList;
import java.util.List;
public class GcLogExample {
public static void main(String[] args) {
// 模拟内存分配触发Young GC
List<byte[]> list = new ArrayList<>();
for (int i = 0; i < 100000; i++) {
list.add(new byte[1024 * 10]); // 10KB per object
}
// 模拟触发Full GC
System.gc();
}
}运行上述代码时，如果使用JDK 8并添加参数 -XX:+PrintGCDetails -XX:+PrintGCDateStamps，你会看到类似如下的日志片段：
立即学习“Java免费学习笔记（深入）”；
[GC (Allocation Failure) [PSYoungGen: 15360K->0K(19456K)] 15360K->10240K(62976K), 0.0023456 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
其中 0.0023456 secs 即为实际停顿时间。而在JDK 17中，使用 -Xlog:gc*:file=gc.log:time,uptime,level,tags 参数，日志格式如下：
[0.123s][info][gc,task] Using G1 [0.567s][info][gc,start] GC(0) Pause Young (Normal) (G1 Evacuation Pause) [0.582s][info][gc,stop_why,cause] GC(0) Pause Young (Normal) (G1 Evacuation Pause) Reason: Metaspace allocation [0.583s][info][gc,heap,coops] Heap region sizes: HS=1M, ES=1M, RS=1M [0.583s][info][gc,phase] GC(0) Phase 1: Scan Remembered Sets [0.583s][info][gc,phase] GC(0) Phase 2: Update RSet [0.583s][info][gc,phase] GC(0) Phase 3: Evacuation Pause [0.583s][info][gc,end] GC(0) Pause Young (Normal) (G1 Evacuation Pause) 15.6ms
在JDK 17的日志中，停顿时间出现在最后一行 15.6ms，这比JDK 8的格式更加直观和易于通过脚本解析。
// JDK 17 示例：使用 JFR 记录 GC 事件
import jdk.jfr.consumer.RecordedEvent;
import jdk.jfr.consumer.RecordingFile;
import java.nio.file.Paths;
import java.util.stream.StreamSupport;
public class JfrGcAnalyzer {
public static void main(String[] args) throws Exception {
try (Stream<RecordedEvent> events = RecordingFile.readAllEvents(Paths.get("flight-recorder.jfr"))) {
events.filter(e -> e.getEventType().getName().equals("jdk.G1GarbageCollection"))
.forEach(e -> {
double duration = e.getDouble("duration");
System.out.println("GC Duration: " + duration + " ms");
});
}
}
}除了直接查看GC日志，还可以使用JDK自带的 jcmd 工具来实时监控GC情况。例如，执行 jcmd <pid> VM.flags | grep GC</pid> 可以查看当前的GC配置。此外，jstat -gcutil <pid> 1000</pid> 命令可以每秒打印一次GC统计信息，包括各代的使用率和GC次数，虽然不直接显示停顿时间，但可以帮助判断GC频率是否过高。
基于程序中某个输入、条件或结果的具体问题
在实际开发中，如果程序出现性能瓶颈，往往是因为某次GC导致的停顿时间过长。例如，当堆内存设置不合理，或者对象生命周期分布不均时，可能会频繁触发Full GC，导致应用长时间不可用。通过分析GC日志中的停顿时间，可以针对性地调整JVM参数，如增加堆内存大小、调整新生代比例、选择合适的GC算法等，从而优化应用性能。
