skip to content

A JVM service normally shows 15 ms garbage-collection pauses but occasionally stops for nearly a second. Working only from GC logs, how do you find out what causes the outliers?

level: seniorimportance: must knowfreq 50%

answer

  1. Percentiles + pause-vs-time first, never the mean
  2. Outlier's own line: scope + cause
  3. To-space exhausted / humongous / System.gc() / Metadata
  4. gc+phases: Object Copy vs Ref Proc vs Other
  5. Real ≫ User+Sys = starved host; safepoint = not-a-GC stall

basics

~20 s

Sort collections by duration, then read the outliers' lines: their scope and cause, whether To-space exhausted or a Full GC preceded them, the phase breakdown from gc+phases, the gc+cpu User/Sys/Real split, and safepoint timings. Cause first, then flags.

solid answer

~60 s

Work top-down, from the log, in this order. 1. **Build the distribution.** Load the log into a GC-log analyser (or a script) and look at pause percentiles and a pause-versus-time plot, not the average. Ask: are the outliers periodic, correlated with traffic, or one-off? 2. **Classify each outlier by its line.** `Pause Full` on a concurrent collector is one story; a long `Pause Young` is another. Read the cause: `To-space exhausted`, `G1 Humongous Allocation`, `System.gc()`, `Metadata GC Threshold`. 3. **Break the pause down** with `-Xlog:gc+phases=debug`. A long *Object Copy* means an unusual amount survived; a long *Ref Proc* means weak/soft/phantom reference processing; a large *Other* points at bookkeeping such as evacuation-failure handling. 4. **Check whether it was the JVM at all** with `-Xlog:gc+cpu`: `Real` far exceeding `User+Sys` means CPU starvation, swapping, a noisy neighbour, or a blocking write of the GC log itself. 5. **Check the stop, not just the collection**, with `-Xlog:safepoint`: long *time to safepoint* means a thread would not yield, and the collector is a bystander. Only after the cause is named do you touch flags.

code

text · 9 lines
text
[812.401s][info][gc          ] GC(944) Pause Young (Normal) (G1 Evacuation Pause) 3901M->3840M(4096M) 96.115ms
[812.401s][info][gc          ] GC(944) To-space exhausted
[812.502s][info][gc          ] GC(945) Pause Full (G1 Compaction Pause) (G1 Evacuation Pause) 3840M->2705M(4096M) 871.744ms
[812.502s][info][gc,cpu      ] GC(945) User=3.10s Sys=0.05s Real=0.87s

// Reading: the young collection reclaimed almost nothing and ran out of
// to-space, so G1 fell back to a stop-the-world compaction. Real is well
// below User (parallel workers), so the host was fine - this is a real
// collector problem: allocation/promotion outran the concurrent cycle.

go deeper

for a junior

Know that outliers are investigated by finding the slow collections in the log and reading their cause, and that Full GC lines are the first thing to look for.

for a middle

Add the phase breakdown and the specific causes — to-space exhausted, humongous allocation, System.gc() — and what each implies.

for a senior

Run the whole ladder: distribution, cause, phases, CPU accounting, safepoints; name the cause with evidence before proposing any change.

for a principal

Turn it into a standing capability — GC logs shipped and retained fleet-wide, pause percentiles as an SLI with Full GCs alerted on — so tail-latency investigations start from data rather than from a reproduction attempt.

## Start with the distribution, not the incident A single 900 ms pause tells you little; its position in the distribution tells you a lot. Feed the log to a GC-log analysis tool — the open-source viewers and the hosted log parsers all do the same core job: parse unified-logging lines and plot pause duration over time, pause percentiles, heap occupancy before/after, allocation and promotion rates, and a throughput percentage (share of wall-clock time not spent in stop-the-world collection). What you want from it: - **Percentiles.** p50 15 ms with p99.9 at 900 ms is a tail problem — a different investigation from "all pauses grew to 200 ms". - **Shape over time.** Periodic spikes (hourly, on the minute) suggest something scheduled: `System.gc()` from a distributed-GC timer, a cache refresh, a batch job. Traffic-correlated spikes suggest allocation or promotion outrunning the collector. One-off spikes suggest the environment. - **Occupancy trend.** If the used-after floor climbs toward the ceiling before each outlier, you are watching a heap that is too small for the live set, and pause outliers are the symptom rather than the disease. ## Classify the outlier from its own line Read the scope and cause of each slow collection: - **`Pause Full` under G1/ZGC/Shenandoah** — a fallback. Look immediately before it. `To-space exhausted` means evacuation failed: G1 had no free region to copy survivors into, so it fell back to stop-the-world compaction. Usual drivers are a burst of promotion, humongous allocations fragmenting the free list, or a concurrent cycle that started too late. - **`G1 Humongous Allocation` as the cause** — the application is allocating objects at least half a region in size (large byte arrays, big buffers, oversized collections). These bypass eden, land in contiguous humongous regions, and both fragment the heap and force collections. The fix is usually in the code or in the region size, not in the pause target. - **`System.gc()`** — someone forced a full collection. Correlate the timestamps; a tidy hourly cadence is the classic distributed-GC heartbeat. - **`Metadata GC Threshold`** — the pressure is in class metadata, common in applications that generate classes or redeploy repeatedly. - **A long `Pause Young` with nothing special about the cause** — the collection set simply contained a lot of live data, which points back at survival and promotion. ## Break the pause into phases `-Xlog:gc+phases=debug` splits a G1 pause into its parts. The ones that actually explain outliers: - **Object Copy** dominating — an unusual amount survived this collection. Correlate with the tenuring distribution and promotion rate. - **Ext Root Scanning / Root Region Scan** dominating — many roots, often a very large number of threads or a huge set of JNI global references. - **Reference Processing** dominating — heavy use of weak, soft or phantom references, or a large finalizer-like queue. Enabling parallel reference processing helps, but the real answer is often fewer references. - **Termination / GC Worker Other / "Other"** large — worker imbalance or, in the evacuation-failure case, the expensive repair path. ## Ask whether the JVM was even running `-Xlog:gc+cpu` prints `User`, `Sys` and `Real` per collection. When `Real` is far larger than `User + Sys`, the collector was ready but the *machine* was not: the container was CPU-throttled by its quota, pages were being swapped in, another tenant saturated the host, or the synchronous write of the GC log itself blocked on a slow or contended disk. This single check saves an enormous amount of misdirected tuning, because no GC flag fixes a starved host. In containers specifically, check the CPU quota and the throttling counters alongside the log — a JVM with many GC threads inside a small quota produces exactly this signature. ## Ask whether it was a collection at all Stop-the-world time is: time for all threads to *reach* a safepoint, plus time *at* the safepoint. `-Xlog:safepoint` separates them. Long time-to-safepoint means one thread would not yield — historically long counted loops without a poll, or a thread blocked in a slow operation while others waited. And several safepoint operations are not collections at all (deoptimisation, heap inspection, thread dumps, class redefinition by an agent); they stop the world and never appear under the `gc` tags. If the application reports a stall and no collection sits at that timestamp, this is where the answer is. ## Converge on a cause before touching flags The order matters because each layer invalidates the fixes suggested by the layer above. Enlarging the heap because of `To-space exhausted` is reasonable; enlarging it because Real ≫ User+Sys is useless and may make the throttling worse. A defensible answer ends with a named cause, the log evidence for it, and a change aimed at that cause — reduce the humongous allocations, start the concurrent cycle earlier, give the collector headroom, remove the `System.gc()` call, raise the container's CPU quota — rather than with a list of flags tried at random.

  • The `gc+cpu` line for a long pause reads `User=0.09s Sys=0.01s Real=0.85s`. What does that tell you?
    The collector only consumed about 0.1 s of CPU, yet the world was stopped for 0.85 s — so the JVM was not doing the work, it was waiting. Typical causes are container CPU throttling, an oversubscribed host, swapping, or a blocking write of the GC log to slow storage. The investigation moves to host and container metrics; no collector flag fixes it.
  • How would humongous allocations show up, and what would you do about them?
    You would see the cause `G1 Humongous Allocation` on collections and humongous region counts in `gc+heap` output, often alongside evacuation failures because contiguous free regions are scarce. Options are to reduce the object size in application code — chunk large arrays or buffers, avoid oversized collections — or to increase `-XX:G1HeapRegionSize` so those objects are no longer humongous, with the code fix being the more durable one.
  • What throughput number would you quote from a GC log, and how is it computed?
    GC throughput is the share of wall-clock time the application was not stopped: total time minus the sum of stop-the-world pauses, over total time, across a steady-state window. Concurrent phases are excluded because they overlap with application execution, though they do consume CPU. Analysers report it directly, and it is the right headline number for a throughput-oriented service, while percentiles are the right one for a latency-oriented service.

saying these in an interview costs you the question

  • Reasoning from average pause time when the complaint is a tail-latency outlier.
  • Reaching for flags before naming a cause from the log.
  • Assuming every long stop is a collection, ignoring safepoint operations and time-to-safepoint.
  • Ignoring the User/Sys/Real split and tuning the collector when the host or container quota is the constraint.
  • Counting concurrent phase durations as pause time and concluding pauses are far worse than they are.

context

resolving links…