An endpoint has a median latency of 12 milliseconds and a p99 of 340. Tracing shows the slow requests spending their time in no particular place: the spans inside them add up to about 15 milliseconds and the request took 340.
The missing 325 milliseconds is not in any span because the thread was not running. It was stopped, along with every other application thread, while the garbage collector did its work.
Nothing in the application is slow. The application was paused.
The signature is that everything slows at once
A stop the world pause halts every application thread at a safepoint. It does not matter what a thread was doing or which endpoint it was serving.
That produces a distinctive pattern: unrelated endpoints slow simultaneously for the same brief window, then recover together. A health check that does nothing takes 200 milliseconds. A cache hit that never touches the network takes 200 milliseconds. If your slow requests have nothing in common except their timestamps, stop looking at the code.
flowchart TB
A["Request A: 8ms of work"] --> P["Stop the world pause<br/>320ms, all threads halted"]
B["Request B: 3ms of work"] --> P
C["Health check: 0.2ms of work"] --> P
P --> R["All resume. All report<br/>320ms of unexplained latency."]
style P stroke:#ef4444,stroke-width:3px,color:#fff
Confirming it takes GC logs and a timestamp comparison:
-Xlog:gc*:file=/var/log/gc.log:time,uptime,level,tags:filecount=5,filesize=100MThat is the Java 9 and later syntax. Line up the pause timestamps against the slow request timestamps and the question is answered in a minute. It is worth having this on permanently, because the overhead is negligible and the alternative is not being able to answer this during an incident.
Allocation rate is the lever, not heap size
The instinct when GC is implicated is to give the JVM more memory. That is often the wrong direction and it is worth understanding why.
Generational collectors work on the observation that most objects die young. New allocations go into the young generation, which is collected frequently. A young collection copies the objects that survived and discards the rest, so its cost scales with how much survived, not with how much was allocated.
Two things follow.
How often you collect is determined by how fast you fill the young generation, which is your allocation rate.
How long each collection takes is determined by how many objects are still alive, which is your retention.
A service allocating 2GB per second with a 512MB young generation triggers a young collection roughly four times a second. Enlarging the heap makes those collections less frequent and gives each one more to look at.
For throughput that is a good trade. For tail latency it can be actively bad, because the tail is defined by the longest pauses and you have just made them longer while making them rarer. Rarer long pauses still land on somebody’s request.
Reducing allocation improves both terms at once, which is why it is the first thing to look at.
Where the garbage comes from
Allocation profiling answers this directly, and Java Flight Recorder is built in and cheap enough to leave running.
java -XX:StartFlightRecording=duration=120s,filename=alloc.jfr \
-XX:FlightRecorderOptions=stackdepth=128 -jar service.jarOpen the recording and sort by allocation. The offenders are consistent across services:
Logging that formats messages which are then discarded by the level filter. log.debug("state: " + expensiveToString()) builds the string before the call, every time, regardless of whether debug is enabled. Parameterised logging avoids it.
Boxing in hot loops. A Map<Long, Long> counter allocates a Long per increment past the small value cache, which at high request rates is a lot of short lived garbage. A primitive map from Eclipse Collections or fastutil removes it.
Reading a whole response into memory when it is going to be streamed anyway.
Defensive copying inside frequently called methods, where the copy exists to protect against a mutation that never happens.
Serialising large objects with fields that are never read, which allocates the whole graph to produce output nobody uses.
None of these are exotic. They are ordinary code that is fine at low volume and becomes an allocation problem at high volume, which is why they survive review.
Choosing a collector by what you care about
| Collector | Pause behaviour | Reasonable for |
|---|---|---|
| Parallel | long pauses, best throughput | batch jobs, offline processing |
| G1 | targets a pause goal, default since Java 9 | most services |
| ZGC | sub-millisecond, largely heap size independent | latency sensitive, large heaps |
| Shenandoah | sub-millisecond, concurrent compaction | same as ZGC, different tradeoffs |
G1 is a reasonable default and -XX:MaxGCPauseMillis is a goal rather than a guarantee, which is a distinction worth internalising. Setting it to 10 does not produce 10 millisecond pauses; it makes G1 choose smaller collection sets to try to get there, and if it cannot, it will exceed it.
ZGC is the one I would reach for when the tail is the thing being optimised. It does concurrent marking and relocation, keeping pauses in the sub-millisecond range mostly independent of heap size, and it pays for that with some throughput and extra memory. For a service where p99 is a product requirement rather than a curiosity, that is usually a good exchange.
Switching collectors is a one flag change and it is worth measuring rather than reasoning about, because the answer depends on allocation patterns that are hard to predict from the outside.
The interaction with everything else
A GC pause is invisible to most of your instrumentation, and it interacts with systems that assume progress.
A pause longer than a health check timeout gets a perfectly healthy pod restarted, at the moment it was under enough load to be collecting. A pause during a pub/sub message delivery loses the message, because nothing retries a fire and forget broadcast. A pause while holding a database connection extends the holding time, which feeds directly into the pool sizing arithmetic.
This is the part that makes GC worth understanding even if you never tune it. The pause is not confined to the process. It leaks into every timeout, every heartbeat, and every assumption about liveness that anything else makes about you.
What I would do first
Turn on GC logging permanently, because the cost is near zero and its absence during an incident is expensive.
Compare pause timestamps to slow request timestamps before touching any flag. That one comparison either confirms or eliminates GC in a couple of minutes.
If confirmed, profile allocation rather than raising the heap. The change that removes garbage helps frequency and duration together, while the change that adds memory trades one for the other.
Then consider the collector, because on a modern JVM with a latency sensitive workload the default is not always the right choice and changing it is a single flag.
// SPONSORSHIP
If this research saved you time or improved your architecture, consider sponsoring my work on GitHub. All sponsorships go directly toward infrastructure and further technical research.
[ Become a Sponsor ]