What a Safepoint Actually Stops

The GC log said 2.275 ms. The safepoint log, same run and same collection, said 29.6 ms.

The difference is not rounding and not measurement overhead. It is the time the application threads took to stop, and the collector cannot report it: by the time G1 begins work, the waiting is already over. Every pause figure read out of a GC log excludes it.

All measurements below are from JDK 26.0.2.1 (Homebrew build), macOS 26.6.2, Apple M4 Pro, twelve cores.

Three costs in one line

A safepoint is the state in which the JVM knows the exact state of every Java thread — every stack parsable, every reference locatable. Operations that rewrite the heap or patch compiled code need it. Threads reach it by executing a poll, an instruction the JIT plants at method returns and non-counted loop back-edges, which traps when the VM has requested a stop.

-Xlog:safepoint bills the whole sequence separately:

[3.221s][info][safepoint] Safepoint "PrintThreads", Time since last: 3214483208 ns,
  Reaching safepoint: 4584 ns, At safepoint: 176041 ns, Leaving safepoint: 209 ns,
  Total: 180834 ns, Threads: 0 runnable, 11 total

Reaching safepoint is the wait for the slowest thread to hit a poll. At safepoint is the operation itself. Leaving is the release. Only the middle figure belongs to the subsystem that requested the stop; Total is what the application experienced. The operation name is worth reading too — PrintThreads above is a jcmd Thread.print, which on JDK 26 is still a global safepoint rather than a per-thread handshake.

The collector reports the middle number

Run the two logs together and the accounting becomes explicit. This is one process, one event, two lines:

[1.774s][info][gc] GC(2) Pause Full (System.gc()) 2059M->2057M(6144M) 2.275ms
[1.774s][info][safepoint] Safepoint "G1CollectFull", ...
  Reaching safepoint: 27314917 ns, At safepoint: 2294583 ns,
  Leaving safepoint: 2625 ns, Total: 29612125 ns, Threads: 1 runnable, 11 total

2.275ms and At safepoint: 2294583 ns are the same measurement. The collector is not lying; it is answering a narrower question than the one being asked of it. Thirteen times the reported pause went missing between the two lines, and tuning the collector would have addressed the 2 ms. This is the specific case underneath what the pause numbers hide: a collector comparison conducted on collector-reported pauses compares the halves of the stall neither collector controls.

The poll is a property of the compiled loop

A thread that never executes a poll never stops. The classic case is a counted loop — int induction variable, trip count known at compile time — which C2 historically compiled without a back-edge poll, on the reasoning that the loop would end. Loop strip mining, added in JDK 10, splits such a loop into an outer loop over strips of LoopStripMiningIter iterations and puts the poll in the outer one.

Disabling it is instructive. A worker thread running a two-billion-iteration accumulation, while another thread calls System.gc():

A 1.4 ms collection, and every thread in the process stopped for 1.2 seconds to permit it.

The reason this is not merely a historical curiosity is that strip mining is collector-conditional, and the condition is not documented anywhere a reader would look:

$ java -XX:+UseG1GC -XX:+PrintFlagsFinal -version | grep CountedLoopSafepoints
     bool UseCountedLoopSafepoints = true    {C2 product} {default}

$ java -XX:+UseSerialGC -XX:+PrintFlagsFinal -version | grep CountedLoopSafepoints
     bool UseCountedLoopSafepoints = false   {C2 product} {default}

True under G1, ZGC and Shenandoah; false, with LoopStripMiningIter at 0, under SerialGC and ParallelGC. And a JVM that sees one processor selects SerialGC by ergonomics — the shape of a great many containers:

$ java -XX:ActiveProcessorCount=1 -Xmx1g -Xlog:safepoint Ttsp
[3.152s][info][safepoint] Safepoint "SerialGCCollect", Time since last: 309858417 ns,
  Reaching safepoint: 1253929625 ns, At safepoint: 1088125 ns,
  Leaving safepoint: 1333 ns, Total: 1255019083 ns, Threads: 1 runnable, 11 total

No flags, no tuning, no bug: 1.255 seconds of stopped threads to perform a 1.088 ms collection.

The same copy, written two ways

Strip mining covers loops the compiler can see. It does not cover work handed to an intrinsic. Two programs copy one gibibyte between byte arrays in a loop; one calls System.arraycopy, the other writes the element loop out by hand. Same bytes, same collector, all defaults:

The intrinsic expands to a machine-code stub with no poll in it, so the request waits for the copy to finish. Several hundred times the latency to reach a safepoint, for the version most reviewers would call the correct one. Anything that spends milliseconds inside a single intrinsic — a large copy, a large fill, a compress or a checksum — buys the same trade.

The event built for this, and what it cannot see

JDK 25 added jdk.SafepointLatency under JEP 518, which reworked JFR’s sampler to walk stacks at safepoints without inheriting safepoint bias. The event records, per thread and with a stack trace, how long that thread took to arrive:

$ java -XX:StartFlightRecording:jdk.SafepointLatency#enabled=true,filename=r.jfr Ttsp
$ jfr print --events jdk.SafepointLatency r.jfr
jdk.SafepointLatency {
  startTime = 16:04:46.640 (2026-08-31)
  duration = 1.62 s
  threadState = "_thread_in_Java"
  eventThread = "worker" (javaThreadId = 33)
  stackTrace = [
    Ttsp.burn(int) line: 6
    ...
  ]
}

That is the counted-loop stall, named, with the offending method attached. It is also the whole of what the event will do for you. Across three recordings the event count matched the jdk.ExecutionSample count exactly — 104, 107, 112 — because a latency event is emitted when a sample request is serviced. On the System.arraycopy program, which produced the stalls in the table above, both counts were zero. JEP 518 flags the reason in its own Future Work: inside a method with an intrinsic implementation “it may be impossible to parse the stack”.

So the worst stall on this machine is the one the instrument built to find stalls does not record, and -Xlog:safepoint reports it for free. Two more defaults are worth knowing before trusting a recording: jdk.SafepointLatency is disabled in default.jfc, and jdk.SafepointBegin carries a 10 ms threshold, so a 9.5 ms stop leaves no trace at all.

Naming the thread

When the log says the wait is long, one flag says who caused it:

$ java -XX:+SafepointTimeout -XX:SafepointTimeoutDelay=500 ...
# SafepointSynchronize::begin: Timed out while spinning to reach a safepoint.
# SafepointSynchronize::begin: Threads which did not reach the safepoint:
# "worker" #26 [33027] daemon prio=5 os_prio=31 cpu=2278.92ms elapsed=2.28s
#   tid=0x0000000a3ecf3800 nid=33027 runnable  [0x0000000000000000]

SafepointTimeoutDelay is in milliseconds and the flag is a product option, so it can be left on in production; it prints only when a safepoint request exceeds the delay.

What to do with this

Three steps, in order, on a service you already run.

1. Add -Xlog:safepoint beside the GC log and compare Total against the collector’s pause. A large Reaching safepoint with a small At safepoint is not a GC problem, and no collector flag will move it.
2. Check UseCountedLoopSafepoints on the collector you actually got, not the one you meant to configure. Under SerialGC or ParallelGC, -XX:+UseCountedLoopSafepoints -XX:LoopStripMiningIter=1000 restores the poll.
3. Turn on -XX:+SafepointTimeout with a delay near the tail latency being chased, and read the thread names.

The same mechanism explains the older argument about profilers. A sampler that can only capture a stack at a safepoint sees a distribution shaped by where the polls are, not by where the time went, which is how two profilers disagree about the same hot method. JEP 518 narrowed that gap for JFR rather than closing it, and the arraycopy result above is what the remaining part looks like from the outside.