The p99.9 That Only Spiked While We Were Scaling Up


If you’ve ever had a p50 and p99 that stay flat and boring while your p99.9 quietly jumps, and it only happens for a few minutes right after autoscaling adds a node, this is for you. It’s one of those failures that hides in exactly the percentile nobody’s dashboard defaults to, and correlates with the one event nobody thinks of as a request.

I wanted to reproduce this locally because the first time I met it I chased the wrong thing for most of a day. A checkout service on a Redis cluster, healthy averages, and every time the fleet scaled out the 99.9th percentile spiked and healed itself a few minutes later. Average latency never twitched. If you were only watching p50 you’d swear nothing happened.

The shape that didn’t reproduce is the useful negative here: a read-only workload against the same trigger, same fresh-replica full sync, same everything except the primary never writes. p99.9 barely moved, 9.894ms steady against 10.494ms during the sync, because copy-on-write only costs you anything when the parent writes to a page the child still holds a reference to. Read-only traffic never dirties a page, so there’s nothing to copy. That shape is in the repo under attempts/read-only-control/ instead of deleted, because a version of this post where every workload spiked would be a lie by omission.

The full harness, the deterministic workload, and every raw capture are on GitHub. I ran this on my Mac, Docker Desktop, not a Linux box I actually control, and that turned out to be exactly the constraint the second half of this post is about: the standard fix for the dramatic version of this bug needs root on the host kernel, and Docker Desktop won’t give you that, so I could only measure the part of the mechanism that doesn’t need it. Redis 7.4.0, jemalloc 5.3.0.

The problem

A p50 and p99 that never move while p99.9 rises during a replica’s full sync, invisible to any SLO written against the percentiles everyone actually watches, and easy to misdiagnose as the fork itself when the fork call is cheap. The textbook explanation is Transparent Huge Pages turning ordinary copy-on-write faults into ones 512 times larger, and the textbook fix needs host-kernel access most people running on a managed box, or a Mac, don’t have. Below is what’s actually measurable without that access, and what happened when I went looking for the huge-page story and it wasn’t there.

The full sync moves one percentile, not both

p50 (ms)

steady11.22
disk sync11.50
diskless sync11.35

p99.9 (ms)

steady46.30
disk sync54.48
diskless sync44.20
Same primary, same write load, three scenarios. p50 doesn't move by anything worth mentioning. p99.9 rises about 8ms during a disk-based full sync and sits back at baseline, even slightly under it, once the sync is diskless. Measured on Redis 7.4.0, n=705-1708 samples per scenario, results in benchmarks/redis-thp/results/.

What the numbers actually were

800,000 keys, 400 bytes each, seeded so the run is reproducible (used_memory_human after load: 394.72M). Write load stayed on throughout: one probe connection issuing sequential SETs and timing true round-trip latency (about 68 ops/sec on that connection alone), plus six bulk-writer connections pipelining batches of 80 to keep real additional write pressure on the primary, independent of the probe’s own pacing.

Steady state, no replica attached, n=1708 samples:

p50    11.220ms
p99    36.187ms
p99.9  46.300ms

Then a fresh replica attaches and pulls a full sync over disk (repl-diskless-sync no), same write load running the whole time, n=721:

p50    11.502ms
p99    43.091ms
p99.9  54.479ms

p50 moved 0.28ms. p99 moved about 7ms. p99.9 moved about 8.2ms, a 1.18x lift over steady. That’s real and it’s reproducible, and I’m not going to dress it up as more than it is: it’s nowhere near the “quietly jumps to 400ms” shape the production incident that sent me down this hole actually had.

The trail that pointed at fork, and Redis’s own tooling shrugged

The classic story blames fork(). A new replica syncs by asking the primary to BGSAVE, which forks a child to write the snapshot while the parent keeps serving, and forking a process with a large heap is a well-known Redis latency source. So I measured it, INFO stats, latest_fork_usec:

disk_sync      1707 usec  (1.707ms)
diskless_sync  2030 usec  (2.030ms)

Cheap, both arms. Whatever’s costing the 8ms isn’t the fork call itself, that’s over in about two milliseconds regardless of which sync mode you use.

I also asked Redis to tell on itself:

=== LATENCY DOCTOR ===
Dave, no latency spike was observed during the lifetime of this Redis instance, not in
the slightest bit. I honestly think you ought to sit down calmly, take a stress pill,
and think things over.

=== LATENCY HISTORY fork ===
[]

That’s the actual output, unedited, from every arm, including the one with the measured 8ms lift. LATENCY DOCTOR’s default threshold is tuned for the dramatic version of this bug, hundreds of milliseconds, not single digits. If you’re relying on Redis’s own latency monitor to flag this for you at this scale, it won’t, and you have to go look at your own percentiles directly to see it at all.

The huge-page story, and the honest finding that it wasn’t the story here

The textbook mechanism for why this gets dramatic is Transparent Huge Pages. Copy-on-write is what makes the fork cheap in the first place, the parent and child share physical pages until one of them writes, and the cost is deferred to the first write after the fork, one page fault at a time. With normal 4KB pages that fault copies 4KB. With THP backing the heap, the shared unit is a 2MB page, so the same single write can trigger copying 2MB instead of 4, roughly 512 times the work, and that’s the mechanism behind a fork that measures in milliseconds turning into a tail that measures in hundreds of them.

I went looking for that in this harness, and it genuinely wasn’t there. /proc/1/smaps_rollup at the peak of every scenario, disk_sync, diskless_sync, and the read-only control alike, all reported the same line:

AnonHugePages:         0 kB

Zero, every time, after loading roughly 400MB and idling well past khugepaged’s scan interval. The container’s own view of /sys/kernel/mm/transparent_hugepage/enabled reports [always] madvise never, which looks like THP is on, but whatever’s promoting pages elsewhere in Docker Desktop’s LinuxKit VM (its own /proc/meminfo showed other processes accumulating huge pages over the same window) never reached this jemalloc-backed heap. THP was not backing Redis’s memory in this environment, at all, for the entire run.

That’s plausibly why the 8ms is 8ms and not 400ms: what’s left once you take huge-page amplification out of the picture is plain 4KB-page copy-on-write under write pressure, plus whatever the disk_sync child pays for actually writing the RDB file to disk before the transfer starts. Both are real costs, neither is multiplied by 512. This harness can’t cleanly separate those two from each other, disk I/O and ordinary copy-on-write both disappear together the moment you switch to diskless_sync, but it can tell you which lever to pull regardless of which one it is.

What you do when you can’t touch the host

  • repl-diskless-sync yes. This is the actionable one, and it doesn’t care whether THP is in play. Instead of forking, writing the RDB to disk, and then transferring the file, the primary streams the snapshot straight to the replica’s socket. In this harness that meant a shorter-lived fork (1.088s vs 1.129s), a faster sync (1.519s vs 1.950s attach-to-link-up), and a p99.9 that landed statistically flat against the steady baseline instead of 8ms above it. You don’t need root to set this. It’s a Redis config value.
  • Don’t trust LATENCY DOCTOR to catch this for you. It’s tuned for the dramatic version. Put p99.9 on a dashboard next to your scale-out events and look for the correlation yourself, because the built-in tooling will tell you, cheerfully, that nothing happened.
  • If you can check AnonHugePages, check it before you blame THP. It’s one read of /proc/<pid>/smaps_rollup. If it comes back zero, you’re chasing the wrong 512x, and the honest next step is plain fork-and-disk-I/O cost, not a kernel setting.

The takeaway

I went in expecting to measure the classic story and instead measured the boring one. Forking is cheap everywhere. The tail lift is real, but modest, because nothing here was amplifying it. And Redis never once flagged it on its own, I had to go pull the percentiles myself to see it at all. If you’re on bare metal or a Linux box you actually own, go check AnonHugePages yourself, you might be looking at the 512x version I couldn’t reproduce here. If you’re not, repl-diskless-sync yes doesn’t ask what your kernel is doing before it helps.

Want to get blog posts over email?

Enter your email address and get notified when there's a new post!

Comments