GC日志中real时间包含SafePoint等待(TTSP)和GC实际工作时间;差值大说明TTSP高,需结合PrintSafepointStatistics或-Xlog:safepoint定位线程卡点原因。

GC 日志里本身不直接显示 SafePoint 耗时,但会间接暴露它——关键看“停顿时间”是否远超 GC 实际工作时间。真正反映 SafePoint 延迟的,是线程到达安全点所花的时间(TTSP),这部分常被误认为是 GC 本身慢了。
看 PrintGCApplicationStoppedTime 输出的两段耗时
启用 -XX:+PrintGCApplicationStoppedTime 后,每次 STW 会打印类似:
注意两个数值:
- 前一个(0.0585911s):整个应用线程被停止的总时长,即从第一个线程挂起到最后一个线程恢复的时间
- 后一个(0.0001795s):真正用于“停止线程”的开销,极短,说明线程响应很快
两者差值(≈0.0584s)基本就是所有线程等待进入 SafePoint 的时间总和,也就是 TTSP 主导的延迟。如果这个差值大(比如几十毫秒甚至秒级),说明有线程迟迟无法到达 SafePoint。
结合 PrintSafepointStatistics 定位原因
仅看 GC 日志不够,必须搭配 SafePoint 统计日志才能归因。加参数:
-XX:+PrintSafepointStatistics -XX:PrintSafepointStatisticsCount=1每触发一次 SafePoint 就输出一行,重点关注:
-
safepoint reason:如
RevokeBias(偏向锁撤销)、ParallelGCFailedAllocation(GC 触发)、ThreadDump等 - time:从触发到全部线程就绪的总耗时(含 block + vmop)
- vmop:JVM 实际执行的操作(如 GC 标记),它只在所有线程就绪后才开始
- threads 和 nonvoluntary:等待线程数、非自愿阻塞线程数,高值提示有线程卡住
例如看到大量 reason=RevokeBias 且 time > 10ms,大概率是偏向锁批量撤销拖慢了 GC 启动。
JDK 9+ 用 -Xlog:safepoint* 更清晰
推荐统一日志框架,格式更规范,支持过滤和输出控制:
-
-Xlog:safepoint*:uptime,tags:带时间戳和标签,方便对齐 GC 日志 -
-Xlog:safepoint=info:file=safepoint.log:单独写入文件,避免混杂 -
-Xlog:safepoint*=warning:只记录耗时超阈值(默认 10ms)的安全点事件
输出中 time_since_last_safepoint 和 time_to_reach_safepoint 可直接定位长延迟来源。
别把 GC 日志里的 pause 当成 SafePoint 耗时
GC 日志中常见的 [Times: user=0.02, sys=0.00, real=0.023s] 中的 real 是整个 GC 操作的 STW 时间,包含两部分:
- 线程到达 SafePoint 的等待时间(TTSP,SafePoint 开销)
- JVM 执行 GC 工作的实际时间(如标记、清理)
也就是说:real ≈ TTSP + GC work。如果 GC work 很短(如 Young GC 本应 2–5ms),但 real 达到 50ms,那多出来的 45ms 几乎全是 SafePoint 延迟。











