Our in-process cache made p99 latency worse: an optimization we had to roll back

Our pricing service answers "what does this product cost for this customer?" thousands of times per second. Each request read price rules from Redis. A profile showed the Redis round trips were a large share of each request's time, so we added an in-process cache: a Caffeine cache in the JVM holding up to two million price rule entries, with a 10 minute expiry.

The load test before release looked great:

                 before     after
mean latency     4.1 ms     1.9 ms
p50              3.6 ms     1.2 ms
p99             11.8 ms     9.7 ms
throughput      6,200/s    9,800/s

We shipped it. A week later, the checkout team asked why their calls to us had started timing out. Their client timeout was 50 ms. Our production dashboard told a different story from the load test:

                 before     after (production, 7 days)
mean latency     4.3 ms     2.2 ms
p50              3.7 ms     1.3 ms
p99             14.0 ms    31.5 ms
p99.9           22.0 ms   148.0 ms

The typical request was faster. The slowest requests were far slower, and the slowest 0.1 percent were now beyond the checkout team's timeout.

GC logs

Tail latency spikes in a JVM service that do not correlate with traffic are often garbage collection. We had unified GC logging enabled:

-Xlog:gc*:file=/var/log/app/gc.log:time,uptime,level,tags:filecount=5,filesize=20m

Before the change, pauses were short and frequent:

[2026-10-08T10:14:02.118+0000][512.004s][info][gc] GC(1841) Pause Young (Normal) (G1 Evacuation Pause) 1410M->402M(4096M) 6.214ms

After:

[2026-10-16T10:14:07.882+0000][611.771s][info][gc] GC(2210) Pause Young (Normal) (G1 Evacuation Pause) 3488M->2950M(4096M) 41.902ms
[2026-10-16T10:15:31.405+0000][695.294s][info][gc] GC(2231) Pause Young (Mixed) (G1 Evacuation Pause) 3602M->2871M(4096M) 118.337ms
[2026-10-16T10:15:52.019+0000][715.908s][info][gc] GC(2236) Pause Young (Concurrent Start) (G1 Humongous Allocation) 3870M->3011M(4096M) 63.115ms

Live data after collection went from about 400 MB to nearly 3 GB, in a 4 GB heap. Young pauses grew from 6 ms to 40 ms, and mixed collections, which now had to clean up old-generation regions full of expired cache entries, took over 100 ms. Every request that happened to be in flight during a pause waited for it.

Why the cache made GC work harder

G1, the default collector, divides the heap into regions and collects young regions frequently. The cost of a young collection depends mostly on how much live data it has to copy and how many references from old regions into young ones it must scan.

A large on-heap cache affects both:

• More live data. Two million entries, each a key object, a value object with several fields, and Caffeine's own bookkeeping, added up to about 2.5 GB of objects that survive every collection.
• Constant churn of long-lived objects. Entries live for up to 10 minutes, long enough to be promoted to the old generation, and then expire. That creates a steady stream of dead objects in old regions, which mixed collections must reclaim.
• Less headroom. With 3 GB live in a 4 GB heap, the young generation had less space, so collections ran more often, and G1 sometimes had to start concurrent cycles early.

None of this shows up in average latency. Pauses affect a small fraction of requests, so they barely move the mean, while the cache's speedup applies to almost every request. Mean went down, tail went up.

Why the load test missed it

Three differences between the test and production:

1. Duration. The load test ran for five minutes. The cache was still filling, live data stayed small, and no mixed collections happened. Production reached steady state after about 20 minutes.
2. Key distribution. The test replayed a sample of 50,000 distinct customer and product pairs. Production had over three million. The cache in the test was a fraction of its production size.
3. What we looked at. We compared mean and p99 over the whole run. p99.9 and the maximum, and GC pause times, were not part of the report.

Environment

1. Roll back first

We reverted to the Redis-only path the same day. Checkout timeouts returned to their previous level within an hour. Rolling back first, and investigating second, was the right call: the old version had a known, acceptable tail.

2. Size the cache from data, not from hope

We measured the actual access pattern from a day of production logs. The distribution was steep: the top 150,000 keys accounted for 91 percent of requests. Caching two million keys bought very little over caching the hot set, at the cost of most of the heap.

The second version used a much smaller cache:

Cache<PriceKey, PriceRule> cache = Caffeine.newBuilder()
    .maximumSize(200_000)
    .expireAfterWrite(Duration.ofMinutes(2))
    .recordStats()
    .build();

• 200,000 entries, about 250 MB on heap.
• 2 minute expiry, so most entries die young, in the young generation, which is cheap to collect, instead of being promoted and expiring in old regions.
• recordStats() exported as metrics, so we can see the hit rate rather than guess.

The hit rate settled at 86 percent, versus 93 percent for the large cache. Most of the benefit, a fraction of the cost.

3. Give the collector a target and some room

We raised the heap from 4 GB to 6 GB (the containers had memory to spare) and kept G1's default pause target of 200 ms, but checked actual pauses rather than relying on the target. We also tried ZGC, which keeps pauses under a millisecond regardless of heap size by doing most work concurrently. ZGC (generational by default since JDK 23, available with -XX:+UseZGC -XX:+ZGenerational on JDK 21) gave the best tail latency in our test, at the cost of about 8 percent more CPU. We kept G1 with the smaller cache, because it met the target without the extra CPU; ZGC is our next step if the cache needs to grow.

4. Consider off-heap when the cache must be big

For workloads that genuinely need gigabytes of cached data, keeping it out of the Java heap (in Redis on the same host, or an off-heap cache library) avoids GC entirely, at the cost of serialisation. We did not need that here.

1. A longer, realistic load test. The test now runs for 60 minutes, starts with a 20 minute warm-up excluded from results, and replays a full day's key distribution:

                 Redis only   large cache   small cache
mean latency     4.2 ms       2.0 ms        2.4 ms
p99             13.6 ms      29.8 ms       10.9 ms
p99.9           21.4 ms     141.0 ms       17.2 ms
max GC pause     9 ms        122 ms        14 ms

The large cache's regression appears in this test, which is the point: it reproduces what production did.

2. GC pause metrics on the dashboard. We export pause durations from the JVM's GarbageCollectorMXBean via Micrometer (jvm_gc_pause_seconds) and show the max per minute next to p99.9 latency. The two lines track each other, which makes GC-related regressions obvious.

3. Production, after the second release: p99 at 11 ms, p99.9 at 18 ms, checkout timeouts at their historical baseline, Redis load down by 85 percent.

4. Release rule. Performance changes now ship behind a flag, enabled for one instance first, with p99.9 and GC pause compared against the other instances for a day before rolling out.

Takeaways

• Judge optimizations by tail latency (p99, p99.9, max), not by the mean.
• A large on-heap cache increases live data and GC pause times. Size it from the real access distribution.
• Prefer short expiries so cached objects die young.
• Load tests must reach steady state, use realistic key distributions and report GC pauses.

References: Java 21 G1 garbage collector tuning, Java unified logging, ZGC, Caffeine.