The cache that never hit once

I published Origin Trace a month ago. Weeks later I went back to measure the live demo before showing it to someone, and found it had been broken the whole time. Tracing the phrase "the world's happiest animal" in the quokka article took over two minutes and ended in a timeout, returning nothing. Nobody had complained. I had not noticed either.

What followed was less about fixing a cache and more about understanding why I did not know.

What the metrics said

Origin Trace already emitted a metrics event at the end of every trace, with per-stage timing, network calls and cache behaviour. I only had to read it:

stages:   listing 9.3s · search 18.2s · genealogy 36.5s
network:  7 requests · 3.8s accumulated · 45 revisions
cache:    46 reads + 46 writes · 0 hits · 394.7s accumulated

Every cache read missed or timed out, fell into a silent error handler, and still paid about four seconds of waiting before giving up. Then it wrote the result back, paying another four. Forty-five times.

The 92 operations break down like this: 45 content reads and 45 content writes, one per revision, plus one read and one write for the article's revision listing. That is why the count lands on 46 and not 45.

The cache was not cold. It was dead, and expensive.

The mistake that only shows up in the arithmetic

Here is the comparison that stopped me. The Wikipedia API hands back revisions in batches: in this run, six calls brought 45 revisions and added up to 3.8 seconds of waiting. Redis, in that state, spent 4,290 milliseconds to hand back one.

394.7 seconds of accumulated waiting. Zero hits.

Two caveats about those numbers, because they change what you can claim.

First: the per-operation cost of the dead Redis is modelled, not clocked. The instance is reproduced as a ladder of five attempts with exponential backoff, which is what the client did before giving up. That works out to 4,289.55ms per operation, and it runs with npm run engine:bench -- --mode dead.

Second: the accumulated seconds are the sum of each operation's wait, not the user's wall clock. Some of those operations run in parallel, so nobody sat in front of the screen for 394 seconds. That number measures the size of the waste, not the length of the wait. Which is why I do not divide one by the other: the two quantities count different things.

And it gets worse, because this is not only a dead-infrastructure problem. Looking at the design carefully, I realised it would be wrong even with a healthy Redis.

I was storing one revision per key. But the network layer already fetched in batches: six calls brought back 45 revisions. The cache, storing item by item, needed 45 round trips to avoid 6. It was undoing the very optimisation that existed beneath it.

I was caching the cheap input instead of the expensive answer.

The part that bothered me more

The cache had been failing for weeks and the system kept returning results. That was deliberate: the error handler degraded to "not in cache" and carried on against Wikipedia. The trace still finished, only fifteen times slower.

The problem is how that degradation was written. The error was logged once, and from then on every subsequent failure was swallowed in silence. The code protected the user from the error and hid the problem from me.

That is what struck me hardest, because it contradicts the project's own thesis. Origin Trace exists to argue that a claim needs evidence, that a system should show what it proved and admit what it did not. And there it was, asserting a health it had never checked.

Everyone who writes software has written that catch. It looks like responsibility: do not let a secondary failure bring down the main operation. But silence is not resilience. Resilience is continuing to work and saying that you are degraded.

The fix was not fixing the cache

It was making the system not depend on it.

Fail fast, and visibly. A circuit breaker with states, consecutive-failure counts and an outcome taxonomy: hit, error, timeout, bypass. After two failures it opens and stops trying. The cost of a dead Redis went from 394 seconds per trace to about one second, which is the two attempts hitting the 500ms ceiling before the circuit opens. If the instance refuses the connection instead of hanging, both failures return immediately and the toll lands in the milliseconds. And the cache state now appears in the metrics, where it can be seen.

A time budget with an honest partial result. Instead of blowing up and returning nothing, the engine now has a ceiling and hands back the tightest bound it managed to prove, marking what it could not. This was not a concession: it is the engine applying to itself the rule it applies to Wikipedia. An honest partial beats a silent timeout.

Cache the answer, not the input. The key became the whole trace, including the article's latest revision, so the cache invalidates itself when the text changes.

The numbers

The table below changes one variable. Same code, same day, same broken cache: what goes in and out is the circuit breaker. That is what isolates the effect of the fix from a faster network day.

Worth recording what this table does not reproduce. When I found the problem, Quokka did not return a truncated result: it blew up and returned nothing. That failure mode stopped existing along with the time-budget fix, so today's engine can no longer reproduce it. The bench reproduces the cost of the dead cache, not the engine's old behaviour.

The epilogue: I revived the instance

When I finished the diagnosis above, Redis was still dead. Zero hits, the circuit opening on every run, and the entire speedup coming from removing the cost of the cache, not from caching anything. I found that out by checking whether the result cache worked, and it had never been exercised.

That left a three-way decision. Revive the instance, and the result cache starts to matter. Remove the dependency, since the system had proved it did not need it. Or keep a cache that only exists to be bypassed, which was the worst of the three.

I revived it. And only with Redis up can you measure what the new design is worth:

wall:      261ms total
network:   1 request · 233ms
cache:     result 1 read · 1 hit · 25ms
           content 0 reads · list 0 reads
breaker:   closed · 0 trips · 0 errors · 0 timeouts

A repeated trace now costs one network call, purely to check whether the article changed, and one cache read. The content and list caches record zero reads, because the result cache short-circuits both.

That is exactly the inversion that was missing. It used to be 45 round trips to avoid 6. Now it is 1 to avoid all of them.

What changed was not Redis. It was what I ask of it.

What I take from it

Writing the silent error handler was easier than writing the visible one, and it cost me weeks of a broken demo I had published myself. The lesson is not "do not use fallbacks". It is that every fallback has to surface somewhere: in a metric, in a state, on a health page. If degrading is silent, you do not have resilience. You have a failure you have not found yet.

And looking back, what saved the diagnosis was not intuition. It was that Origin Trace already emitted per-stage metrics. Without them I would have blamed Wikipedia, which was the obvious suspect and had been answering the whole time.

The numbers in this piece were measured on 2026-09-08 and are reproducible with the repository's bench:

npm run engine:bench -- --mode dead        # broken cache, no breaker
npm run engine:bench -- --mode fixed-dead  # broken cache, with breaker
npm run engine:bench -- --mode fixed-live  # healthy cache
npm run engine:bench -- --mode result-hit  # warm path

Wall-clock times depend on the network and the state of the article that day, so expect them to move. The operation, revision and batch counts do not.