Latency Spikes: Proving It Was (or Was Not) GC

"The p99 is 3 seconds and the average is 40ms" is one of the most common performance complaints, and GC is the default suspect. It is the cause perhaps half the time. The other half is spent looking in the wrong place, so the first job is attribution.

Attribution first#

-Xlog:gc*:file=gc.log:time,uptime,level,tags
-Xlog:safepoint:file=safepoint.log:time,uptime
-XX:StartFlightRecording=settings=profile,maxage=1h,disk=true

Then line the GC log up against your latency data:

# Slowest requests from the access log
awk '$NF > 1000 {print $4, $NF}' access.log | tail -50
 
# Pauses over 500ms from the GC log
grep -oP '\[\K[\d\-T:.+]+(?=\].*Pause.*\s\d{3,}\.\d+ms)' gc.log

If the two sets of timestamps coincide, you have a GC problem. If they do not — and this is the case people skip — carry on down the tree.

When it is GC#

[10:14:22.481] Pause Young (Normal) (G1 Evacuation Pause) 3100M->2950M(4096M)  892ms
[10:14:24.107] Pause Young (Normal) (G1 Evacuation Pause) 3200M->3010M(4096M) 1104ms

Two things to check before touching flags:

Allocation rate. From the log, eden reclaimed per second. Above roughly 1GB/s per core, GC will dominate no matter which collector you choose. Profile allocation with JFR or async-profiler and fix the top call sites — see Profiling.

Promotion rate. If survivors are being promoted on every young collection, the young generation is too small for objects' actual lifetimes, and old-generation work follows. A larger heap or a longer young-generation residency helps; a smaller pause target makes it worse.

If allocation is already reasonable and pauses still exceed your budget, changing collector is legitimate:

-XX:+UseZGC -XX:+ZGenerational     # sub-millisecond pauses, ~10-15% throughput cost

Coordinated omission#

This one invalidates measurements rather than causing spikes, and it is worth understanding before trusting any tail number.

Plan: one request every 10ms for 10 seconds — 1000 requests.
 
The server stalls for 1 second at t=5s.
 
A CLOSED-model generator (one thread, request-response-request) sends 1 slow
request and simply does not send the ~100 it should have during the stall.
It reports: 999 requests at 10ms, 1 at 1000ms. p99 = 10ms.
 
Reality: a user arriving at t=5.1s waited 900ms. Another at t=5.5s waited
500ms. About 100 requests experienced 500ms+ latency.
Honest p99 ≈ 900ms.

The generator "coordinated" with the system under test, so the requests that would have shown the problem were never issued. The reported p99 is optimistic by nearly two orders of magnitude.

// k6
export const options = {
  scenarios: {
    constant_rate: {
      executor: 'constant-arrival-rate',
      rate: 100, timeUnit: '1s',
      duration: '5m',
      preAllocatedVUs: 200, maxVUs: 1000,   // enough VUs to keep the schedule
    },
  },
};

The rule: use an open model (constant arrival rate) for anything measuring latency. Gatling's constantUsersPerSec, k6's constant-arrival-rate and wrk2 all do this; JMeter and plain wrk are closed-model by default. Watch for a "dropped iterations" warning — that means the generator itself could not keep the schedule, and the numbers are unreliable again.

Safepoint pauses that are not GC#

-Xlog:safepoint:file=safepoint.log:time,uptime

Safepoint "RevokeBias", Time since last: 892ms, Reaching safepoint: 338ms, At safepoint: 2ms

Two separate numbers. At safepoint is the operation itself. Reaching safepoint — time to safepoint, or TTSP — is how long the JVM waited for the last thread to arrive, and it is pure stall during which nothing runs.

A long TTSP is usually one thread in a counted int loop, which the JIT optimises safepoint polls out of, or a long-running array copy or JNI call. The classic fix is changing the loop counter from int to long, which forces the JIT to keep the poll. -XX:+UseCountedLoopSafepoints does the same globally.

Safepoint operations other than GC that stop the world: biased-lock revocation (biased locking is disabled by default from Java 15, removing this class), deoptimisation, class redefinition by an instrumentation agent, thread dumps, and Thread.getAllStackTraces. An APM agent doing continuous instrumentation can generate a surprising number.

CPU throttling#

In a container, this is the most under-diagnosed cause of GC-shaped latency.

rate(container_cpu_cfs_throttled_seconds_total[5m]) > 0

A CPU limit is a quota per 100ms period. Burn it in 30ms and every thread is frozen for 70ms — application threads and GC threads alike. Average CPU usage looks modest because throttled time is not counted as usage, which is exactly why it hides.

The signature is periodic stalls at roughly 100ms granularity, no GC events to match, and a non-zero throttling counter. Details in JVM flags and container limits.

The other usual suspects#

Lock contention. A synchronised block on a hot path serialises requests. JFR's Lock Instances view names the monitor and the total blocked time; a thread dump taken during a spike shows many threads BLOCKED on the same lock.

A slow dependency. p99 of a downstream call bleeds directly into yours. This is the most common non-GC cause, and it is why per-dependency latency metrics are worth the effort.

Connection pool waiting. hikaricp.connections.acquire p99 rising means requests are queuing for a connection. See Connection-pool exhaustion.

Cold code. After a deploy or a scale-up, the JIT has not compiled the hot paths yet and the first few thousand requests run interpreted. A p99 spike that decays over the first two minutes of a pod's life is warm-up, not a bug — and the answer is a warm-up phase before joining the load balancer, not tuning.

Measuring honestly#

Timer timer = Timer.builder("http.server.requests")
        .publishPercentiles(0.5, 0.95, 0.99, 0.999)
        .publishPercentileHistogram()        // enables correct aggregation across instances
        .register(registry);

Two things this fixes. Averages hide tails entirely — a service where 1% of requests take 5 seconds has an average of 90ms and a serious problem. And percentiles cannot be averaged: the mean of per-instance p99s is not the fleet p99. publishPercentileHistogram sends bucket counts so the backend can compute the real quantile.

What gets asked#

"Your p99 is 2 seconds but your average is 50ms — what do you do?" The answer that stands out starts with attribution rather than a fix: get timestamps for the slow requests, check them against the GC log, and only then decide which investigation you are in. Mentioning coordinated omission, or container CPU throttling, tends to end the question — both signal that you have measured this rather than read about it.