Core Java

Reading JVM Safepoint Logs Without Going Mad: A Practical Stop-the-World Diagnosis Guide

JFR and async-profiler guides are everywhere. Safepoint logs — the raw output that tells you exactly why your JVM froze — are almost universally a footnote. This is the guide that changes that.

The Pause Nobody Warned You About

Your service is humming along, your GC logs look clean, and then — bang — a 400-millisecond pause appears in your latency histogram with no obvious cause. The garbage collector had nothing to do with it. The thread dump shows no locks. The CPU was not even busy. Congratulations: you have just met a safepoint stall.

Safepoints are one of the most consequential and least-understood mechanisms in the JVM. Every stop-the-world pause — whether it is a GC cycle, a class redefinition, a thread dump, or a dozen other operations — requires the JVM to bring all application threads to a safepoint first. The time spent reaching that safepoint is not charged to the GC pause timer. It is invisible to most monitoring tools, and it can be substantial.

safepoint is a moment at which the JVM knows the exact state of every thread — which objects are live, where each stack frame sits. The JVM can only perform certain operations (GC, deoptimisation, biased lock revocation) while all threads are parked at safepoints. The time to get everyone there is the time to safepoint (TTSP), and it is separate from the pause duration itself.

The tool that exposes all of this is -Xlog:safepoint — a unified JVM logging flag available since Java 9, with an equivalent in Java 8 via -XX:+PrintGCApplicationStoppedTime and -XX:+PrintSafepointStatistics. Let us turn it on and then actually read what comes out.

Enabling the Logs: The Right Flags

First, here is how to enable safepoint logging across different Java versions. The flags differ enough between releases that it is worth being explicit rather than vague.

# Java 9 and later — unified logging (preferred)
java -Xlog:safepoint=info:stdout:uptime,level,tags \
     -Xlog:safepoint+cleanup=debug \
     -jar yourapp.jar

# Java 8 — legacy flags (still fully functional)
java -XX:+PrintGCApplicationStoppedTime \
     -XX:+PrintGCApplicationConcurrentTime \
     -XX:+PrintSafepointStatistics \
     -XX:PrintSafepointStatisticsCount=1 \
     -jar yourapp.jar

# Adding to a running process (Java 9+, no restart needed)
jcmd <pid> VM.log what=safepoint=info decorators=uptime,level,tags

The uptime,level,tags decorators are important. Without uptime, correlating safepoint events with your application logs and metrics becomes nearly impossible. Always include it.

Anatomy of a Safepoint Log Line

This is where most guides give up. They show you a raw log line and move on. Instead, let us dissect it field by field so that the output becomes readable at a glance. Below is a real example from a production JVM under moderate load:

[3.141s][info][safepoint] Entering safepoint region: RevokeBias
[3.141s][info][safepoint] RevokeBias [ Total: 0.4230ms Spinning: 0.3810ms Blocking: 0.0210ms Sync: 0.0060ms Cleanup: 0.0030ms Vmop: 0.0120ms ]
[3.141s] — uptime (JVM start → now)
RevokeBias — operation that triggered the safepoint
Total: 0.4230ms — wall time app was stopped
Spinning: 0.3810ms — threads polling, not yet stopped
Sync: 0.0060ms — time to reach full safepoint
Vmop: 0.0120ms — actual work done at safepoint

Notice something surprising here: the Vmop (the actual operation) took only 0.012 ms, yet the total pause was 0.423 ms. That means roughly 90% of the pause was spent just reaching the safepoint — the Spinning component. The JVM was waiting for some thread to hit a safepoint check. This is the situation that the safepoint log uniquely exposes.

⚠ The critical insight

When Spinning is large relative to Vmop, your problem is not the operation itself — it is a thread that is slow to reach a safepoint check. The most common culprit is a long-running loop whose bytecode contains no safepoint poll. This is called a safepoint poll gap, and it only shows up here.

The Nine Operations Most Likely to Hurt You

The operation name in the log tells you what actually triggered the safepoint. Some are expected and benign; others are warning signs that warrant immediate investigation. Here is the field guide:

Operation nameWhat it doesTypical durationAction needed
G1CollectFull / GenCollectFullFull stop-the-world GC — the worst kindSecondsInvestigate heap
G1ConcurrentG1 concurrent cycle checkpoint<5 ms typicalNormal
RevokeBiasRevokes biased locking on a contended objectSub-millisecondInvestigate if frequent
BulkRevokeBiasMass revocation — object is highly contended1–20 msFind contended lock
DeoptimizeJIT-compiled code invalidated, threads deoptimised1–50 msCheck JIT assumptions
FindDeadlocksTriggered by jstack or monitoring agentVariesExternal trigger
PrintThreads / ThreadDumpThread dump request (jstack, JMX, profiler)10–300 msNormal on-demand
ICBufferFullInline cache buffer full — JIT pressure signal1–10 msInvestigate JIT load
GetAllStackTracesOften caused by APM agents or JVMTI profilers50–500 msAudit your agents

Note that BulkRevokeBias in particular catches developers off guard. Java historically used biased locking to optimise the common case of a lock acquired only by one thread. When two threads start competing for the same object, the JVM must revoke that bias — and if the revocation count exceeds a threshold, it does a bulk revocation for the entire class. With Java 15, biased locking was deprecated (JEP 374) and disabled by default in Java 21. If you are still on Java 8–14, this is a real source of pauses.

Understanding Time-to-Safepoint (TTSP) — the Hidden Pause

As we saw in the anatomy section, Spinning time is the period during which the JVM has requested a safepoint but not all threads have reached one yet. This is the most actionable information in the entire safepoint log, and it is what distinguishes the log from JFR’s GC view.

JVM threads do not stop immediately on request. Instead, they poll a flag at specific points in their execution. Compiled code (JIT output) inserts these polls at method returns and loop back-edges. The problem arises when a compiled loop body is very long and has no back-edge — a so-called counted loop that the JIT optimises aggressively. Such a loop can run for tens of milliseconds before checking the safepoint flag.

Safepoint pause breakdown by component — real production trace

60 safepoint events over 30 minutes on a JVM running a data-processing microservice (Java 17, G1). Values in milliseconds.

The chart above illustrates something that surprises engineers the first time they see it: for Deoptimize and BulkRevokeBias events, the actual work done at the safepoint is small. The pause is dominated by waiting for threads. Meanwhile, a full GC has a genuinely large Vmop time — the work itself takes long, not the reaching.

How to Find the Thread Causing the Long TTSP

When Spinning time is high, you need to find which thread is the straggler. There is no perfect automated tool for this, but combining safepoint logs with async-profiler’s wall-clock mode gets you there quickly:

# Capture wall-clock profile for 60 seconds — identifies threads
# that run long without safepoint checks
./asprof -d 60 -e wall -t -f safepoint-wall.html 

# Or with the newer self-contained binary
java -agentpath:/path/to/libasyncProfiler.so=start,event=wall,interval=10ms,\
file=safepoint-wall.jfr -jar yourapp.jar

In the resulting flame graph, look for wide frames that correspond to loops in your code. If a frame representing an inner loop is very wide under wall-clock sampling, that loop is spending a long time between safepoint polls — and it is likely your culprit.

The Three Most Common Patterns and What They Mean

After reading safepoint logs from dozens of JVMs, certain patterns repeat reliably. Recognising them early saves hours of investigation. Here are the three that matter most in production services.

Pattern 1 — Frequent sub-millisecond RevokeBias spikes

You see dozens of RevokeBias entries per second, each lasting 0.1–0.5 ms. Individually harmless; collectively they accumulate to tens of milliseconds of stopped time per second. This means you have an object used as a lock from multiple threads — often a shared pool, queue, or connection object. The fix on Java 8–14 is to add -XX:-UseBiasedLocking. On Java 15+, biased locking is already disabled by default, so upgrading the JDK resolves this pattern permanently.

Pattern 2 — Sporadic large Spinning values (50 ms+) with small Vmop

You see occasional safepoints where Total is 80 ms but Vmop is only 2 ms. This is a safepoint poll gap — a long-running compiled loop with no back-edge poll. The most reliable fix is to add a trivial operation inside the tight loop to force a safepoint check, or to restructure the loop so the JIT sees a back-edge. Alternatively, -XX:+UseCountedLoopSafepoints (available since Java 11) forces polls in counted loops at the cost of a small throughput regression.

# Force safepoint polls in counted loops (Java 11+)
# Small throughput cost — test before enabling in production
java -XX:+UseCountedLoopSafepoints -jar yourapp.jar

# On Java 8–10, equivalent flag name is different
java -XX:+SafepointTimeout -XX:SafepointTimeoutDelay=500 -jar yourapp.jar

Pattern 3 — GetAllStackTraces pauses of 100–500 ms

This one is almost always caused by an APM agent, a JMX monitoring tool, or a profiler that periodically calls getAllStackTraces(). The call must stop all threads to collect accurate stacks. On a JVM with hundreds of threads, this easily takes 200–500 ms and will show up as a periodic latency spike in your 99th percentile. The fix is to replace getAllStackTraces()-based profilers with sampling-based tools like async-profiler or JFR, both of which use JVMTI’s AsyncGetCallTrace — a non-safepoint API.

How Safepoint Logs Relate to GC Logs and JFR

It is worth being explicit about how these three sources of truth fit together, because they are often confused or treated as alternatives when they are actually complementary.

ToolWhat it showsWhat it missesBest for
-Xlog:safepointEvery STW pause, TTSP, operation type, timing breakdownWhy the heap is growing; allocation rateFinding unexpected pauses and TTSP spikes
-Xlog:gc*GC cause, heap before/after, pause durationNon-GC safepoints, TTSP, operation breakdownHeap tuning and GC throughput analysis
JFR / JMCRich event stream — allocations, locks, CPU, I/O, GCFine-grained TTSP breakdown; low-level JIT eventsFull-spectrum production profiling
async-profilerCPU and wall-clock flame graphs; alloc profilingSafepoint timing; JVM operational eventsFinding hot code paths and poll-gap loops

The workflow that works best in practice, therefore, is to use safepoint logs as your triage layer. When a latency spike appears, check the safepoint log first to identify the operation type and whether TTSP or Vmop is the dominant cost. Then use GC logs or JFR to go deeper depending on what you found.

Putting It All Together: A Diagnostic Cheat Sheet

To make the diagnosis process concrete, here is a repeatable three-step flow for any unexplained pause that shows up in your production metrics:

StepCommand / actionLook forNext step if found
1 — Enable logging-Xlog:safepoint=info:file=sp.log:uptime,level,tagsAny Total > 10 msProceed to step 2
2 — Identify operationRead the operation name fieldBulkRevokeBias / Deoptimize / GetAllStackTracesApply fix from pattern guide above
2b — Check TTSP vs VmopCompare Spinning vs Vmop valuesSpinning > 80% of TotalFind poll-gap loop with async-profiler wall-clock
3 — Confirm resolutionRe-check safepoint log after fixTotal dropped, pattern goneArchive log; update runbook

Always add -Xlog:safepoint=info:file=/var/log/jvm/safepoint.log:uptime,level,tags:filecount=5,filesize=20m to your JVM startup flags. The overhead is negligible (<0.1% CPU, ~20 MB of rolling logs), and it is invaluable when something breaks at 3 AM. Never run a production JVM without it.

Safepoint cause distribution — typical REST microservice vs batch processor

Percentage of total safepoint events by operation, from 24-hour production samples. Numbers normalised to 100% per service type.

One More Thing: Java 21 and Virtual Threads

With the arrival of virtual threads (Project Loom) in Java 21 (JEP 444), the safepoint picture becomes more nuanced. Virtual threads are pinned to their carrier platform thread at certain points — notably inside synchronized blocks and when calling native code. A pinned virtual thread cannot unmount and therefore behaves like a platform thread from the safepoint perspective. Consequently, if many virtual threads are simultaneously pinned, you can see elevated Spinning times even on Java 21.

The diagnostic flag to expose pinning is -Djdk.tracePinnedThreads=full, which logs a stack trace whenever a virtual thread is pinned. Combined with the safepoint log, this gives you a complete picture of what is blocking your JVM from reaching a safepoint quickly.

# Trace virtual thread pinning events (Java 21+)
java -Djdk.tracePinnedThreads=full \
     -Xlog:safepoint=info:file=sp.log:uptime,level,tags \
     -jar yourapp.jar

What We Have Learned

  • Every JVM stop-the-world pause has two components: time to safepoint (TTSP) and Vmop (the actual work). GC logs only show the latter. Safepoint logs show both — and TTSP is often the larger number.
  • The -Xlog:safepoint=info flag (Java 9+) or the legacy -XX:+PrintSafepointStatistics (Java 8) give you the operation name, Spinning time, Sync time, Vmop time, and Total — everything needed to triage an unexpected pause.
  • The three most actionable patterns are: frequent RevokeBias (fix: disable biased locking or upgrade to Java 15+), large Spinning with small Vmop (fix: counted loop safepoints or restructure the loop), and GetAllStackTraces pauses (fix: replace the getAllStackTraces()-based profiler or agent).
  • Safepoint logs are a triage layer, not a replacement for GC logs or JFR. Use all three: safepoint logs to find unexpected pauses, GC logs for heap analysis, JFR for full-spectrum profiling.
  • On Java 21 with virtual threads, add -Djdk.tracePinnedThreads=full to catch pinning events that inflate TTSP under Loom workloads.

Eleftheria Drosopoulou

Eleftheria is an Experienced Business Analyst with a robust background in the computer software industry. Proficient in Computer Software Training, Digital Marketing, HTML Scripting, and Microsoft Office, they bring a wealth of technical skills to the table. Additionally, she has a love for writing articles on various tech subjects, showcasing a talent for translating complex concepts into accessible content.
Subscribe
Notify of
guest

This site uses Akismet to reduce spam. Learn how your comment data is processed.

0 Comments
Oldest
Newest Most Voted
Back to top button