Found while verifying #167 against the load harness. Not caused by #167 — it reproduces on every build tested, including main-era ones.
Summary
redis-storm.mjs pause (a 6 s CLIENT PAUSE on an isolated replica's Redis) is bimodal. Most runs recover in ~4.5 s. Some runs instead block for ~59.4 s, and those runs account for ~86% 5xx instead of ~55%.
In every bad run the tail is 12 PUTs returning 204 at ~59.4 s, released together immediately after redis_circuit_closed role:"control" — 12 requests, one per worker, and ~59.4 s ≈ REDIS_EXEC_LOCK_LEASE_MS (default 60000).
Something orphans an exec lock lease during the stall, and every waiter blocks until it expires on its own rather than being released when Redis recovers.
Measured
16 runs on one session, 8 per build (a circuit-breaker fix was under test; it is irrelevant to this issue — both columns show the same bimodality):
| build |
bad runs |
good-mode 5xx / max |
bad-mode 5xx / max |
| baseline |
2 / 8 |
~55% / ~4.3 s |
87.5% / 59,488 ms · 85.9% / 59,613 ms |
| with breaker fix |
1 / 8 |
~55% / ~4.4 s |
86.7% / 59,387 ms |
What it is NOT
Ruled out with evidence, so nobody re-treads this:
- Not the data-plane circuit breaker. Bad runs occur both with the data breaker open (baseline run B6) and closed (F7); good runs occur both ways. Zero correlation.
- Not
commandTimeout accumulation. A 2 s commandTimeout cannot compound to 59 s across 12 requests released simultaneously.
- Not event-loop blocking.
event_loop_lag stays flat at 20 ms (its floor) throughout the bad runs.
- Not the blob-cache read path.
redis_blob_get_error / redis_blob_mget_error are 0 across every storm run ever recorded — bystander reads are served from the in-process contentCache.
Why it matters
This is the difference between a 6-second Redis hiccup costing ~55% of in-flight requests for ~4 s, and costing ~86% for a full minute. The acquire timeout (REDIS_EXEC_LOCK_ACQUIRE_TIMEOUT_MS, now 75 s after #173) is deliberately longer than the lease so a crashed holder can be reaped — which is correct, and is exactly why the waiters sit there rather than failing fast.
The open question is why the lease is not released when the stalled holder resumes. Candidates worth checking: a holder whose renewal fails during the pause and never re-establishes; a release path that consults the circuit breaker and is skipped while it is open; or a holder that completes but whose release command was dropped with the stall.
rw_lock_writer_release_error does appear in the logs, but only once or twice per run — far too few to account for 12 blocked requests, which is itself a signal that the release path is being skipped silently rather than failing loudly.
Reproduction
./scripts/loadtest/up.sh
node scripts/loadtest/scenarios/redis-storm.mjs pause
Run it at least 4 times — a single run proves nothing in either direction. Watch for max in the latency line: ~4.5 s is the good mode, ~59.4 s is the bad one.
Fix verified when
redis-storm.mjs pause is no longer bimodal: no run shows a ~59 s tail, and the 5xx rate is stable across at least 8 consecutive runs.
Provenance
Surfaced while verifying the #167 role split. An initial hypothesis that the M7 circuit-breaker refactor caused it was disproven — see the analysis on #185.
Found while verifying #167 against the load harness. Not caused by #167 — it reproduces on every build tested, including
main-era ones.Summary
redis-storm.mjs pause(a 6 sCLIENT PAUSEon an isolated replica's Redis) is bimodal. Most runs recover in ~4.5 s. Some runs instead block for ~59.4 s, and those runs account for ~86% 5xx instead of ~55%.In every bad run the tail is 12 PUTs returning
204at ~59.4 s, released together immediately afterredis_circuit_closed role:"control"— 12 requests, one per worker, and ~59.4 s ≈REDIS_EXEC_LOCK_LEASE_MS(default 60000).Something orphans an exec lock lease during the stall, and every waiter blocks until it expires on its own rather than being released when Redis recovers.
Measured
16 runs on one session, 8 per build (a circuit-breaker fix was under test; it is irrelevant to this issue — both columns show the same bimodality):
What it is NOT
Ruled out with evidence, so nobody re-treads this:
commandTimeoutaccumulation. A 2 scommandTimeoutcannot compound to 59 s across 12 requests released simultaneously.event_loop_lagstays flat at 20 ms (its floor) throughout the bad runs.redis_blob_get_error/redis_blob_mget_errorare 0 across every storm run ever recorded — bystander reads are served from the in-processcontentCache.Why it matters
This is the difference between a 6-second Redis hiccup costing ~55% of in-flight requests for ~4 s, and costing ~86% for a full minute. The acquire timeout (
REDIS_EXEC_LOCK_ACQUIRE_TIMEOUT_MS, now 75 s after #173) is deliberately longer than the lease so a crashed holder can be reaped — which is correct, and is exactly why the waiters sit there rather than failing fast.The open question is why the lease is not released when the stalled holder resumes. Candidates worth checking: a holder whose renewal fails during the pause and never re-establishes; a release path that consults the circuit breaker and is skipped while it is open; or a holder that completes but whose release command was dropped with the stall.
rw_lock_writer_release_errordoes appear in the logs, but only once or twice per run — far too few to account for 12 blocked requests, which is itself a signal that the release path is being skipped silently rather than failing loudly.Reproduction
Run it at least 4 times — a single run proves nothing in either direction. Watch for
maxin the latency line: ~4.5 s is the good mode, ~59.4 s is the bad one.Fix verified when
redis-storm.mjs pauseis no longer bimodal: no run shows a ~59 s tail, and the 5xx rate is stable across at least 8 consecutive runs.Provenance
Surfaced while verifying the #167 role split. An initial hypothesis that the M7 circuit-breaker refactor caused it was disproven — see the analysis on #185.