Post

The 8-Second Query That Was Actually Five Doomed Retries

A harmless race condition met a well-meaning retry policy and became an 8-second latency spike. Here's how I traced it, and the one-line fix.

The 8-Second Query That Was Actually Five Doomed Retries

A dashboard panel caught my eye: the p95 response time for one endpoint was spiking to ~8 seconds, a handful of times a day. Everything else on that endpoint sat comfortably under 100ms.

The strange part? Every one of those slow requests returned HTTP 200. Nothing was failing. It was just… slow, occasionally, for reasons nobody could explain.

This post is the story of chasing that 8 seconds down to its root — and the surprisingly small fix at the end.


Clue #1: The spikes were suspiciously identical

The first thing I did was pull the raw durations of the slow requests instead of trusting the aggregated p95. Here’s roughly what I saw:

1
2
3
4
5
6
7
8
8419ms
8299ms
8261ms
8260ms
8258ms
8249ms
8249ms
...

Look at how tightly clustered those numbers are. They’re all within ~200ms of 8.2 seconds.

That’s the tell. Real load is noisy — if the slowness came from a busy database, a slow network hop, or CPU contention, you’d see a spread: 2s, 5s, 11s, 800ms. When latency clusters this tightly around a constant, you’re not looking at load. You’re looking at a fixed delay baked into the code path — a timeout, a sleep, or a retry schedule.

So the question changed from “why is the database slow?” to “what in my code takes exactly 8.2 seconds?”


Clue #2: The time wasn’t where I expected

I grabbed one slow request and pulled every log line for it, in order, with per-statement timing. The endpoint’s actual job — its main query and response — took about 30 milliseconds. The other 8.2 seconds was spent before that, inside what looked like a routine “find or create this record” step in an authentication middleware.

Here’s the trace, cleaned up:

1
2
3
4
5
6
7
8
9
10
12.839  START TRANSACTION
12.841  SELECT ... WHERE unique_col = X   -> no row found
12.855  INSERT ...                         (14ms)
14.044  INSERT ...                         (6ms)   <- ~1.19s later
15.545  INSERT ...                         (1ms)   <- ~1.50s later
17.797  INSERT ...                         (1ms)   <- ~2.25s later
21.175  INSERT ...                         (1ms)   <- ~3.38s later
21.177  SELECT ... WHERE unique_col = X   -> found it
21.178  COMMIT
21.215  Done — 8419ms

Two things jumped out:

  1. There are five INSERT statements for what should be a single insert.
  2. Each INSERT itself finishes in 1–14ms. Nothing is blocked waiting on a lock. The time is entirely in the gaps between the inserts — and those gaps grow: ~1.2s, ~1.5s, ~2.25s, ~3.4s.

Growing gaps between identical operations is the fingerprint of exponential backoff. Something was retrying that INSERT five times, sleeping a little longer each time, before finally giving up and reading the row instead.


The code: an innocent-looking findOrCreate

The middleware provisions a local record for a user the first time it sees them. In Sequelize (a popular Node.js ORM), that’s a one-liner:

1
2
3
4
const [user] = await User.findOrCreate({
  where: { external_id: id },
  defaults: { name, email, external_id: id },
});

findOrCreate does exactly what it says: SELECT by the where clause, and if nothing is found, INSERT the defaults. Simple. So why five inserts?


The root cause: a race + a retry policy that couldn’t tell the difference

Here’s what was actually happening.

When a brand-new user first arrives, the client fires several requests at once (a typical bootstrap: fetch status, fetch a token, fetch some config) — all carrying the same new user id. Each request independently reaches that findOrCreate.

Now the classic race plays out:

  1. Two requests run the SELECT at nearly the same time. Both see no row.
  2. Both proceed to INSERT.
  3. One transaction commits first and wins — the row now exists.
  4. The other request’s INSERT violates the unique constraint on the column and the database rejects it with a duplicate-key error (ER_DUP_ENTRY in MySQL, surfaced by Sequelize as a UniqueConstraintError).

This race is completely normal and expected — it’s why the unique constraint exists. And findOrCreate already handles it correctly: on a unique-constraint error it catches the exception and does a second SELECT to return the row the winner just created.

But there was a retry policy sitting underneath. Sequelize lets you configure automatic query retries (via the retry option, powered by retry-as-promised), typically added to survive transient failures like deadlocks or dropped connections. Sequelize even ships a sensible, conservative default — retry on exactly one known-transient error:

1
2
// Sequelize's built-in default
retry: { max: 5, match: ["SQLITE_BUSY: database is locked"] }

So how did a duplicate-key error — which isn’t in that list — get retried? This is the part that surprised me, and it comes down to two behaviors combining.

First, the config had overridden retry to tune the backoff, without specifying match:

1
2
3
4
5
6
7
// somewhere in the DB config
retry: {
  max: 5,
  backoffBase: 1000,
  backoffExponent: 1.5,
  // note: no `match` key
}

Sequelize merges options with a shallow spread, so this custom block doesn’t extend the default — it replaces it wholesale. The curated match: ["SQLITE_BUSY"] is silently gone. You can watch it happen:

1
2
3
4
5
new Sequelize(db, { dialect: "mysql" }).options.retry;
//=> { max: 5, match: ["SQLITE_BUSY: database is locked"] }

new Sequelize(db, { dialect: "mysql", retry: { max: 5, backoffBase: 1000 } }).options.retry;
//=> { max: 5, backoffBase: 1000 }   // <-- no `match` anymore

Second — and this is the real trap — an empty or absent match does not mean “retry nothing.” In retry-as-promised it means the opposite:

1
2
// retry-as-promised
shouldRetry = options.match.length === 0 || options.match.some(m => matches(m, err));

match.length === 0 short-circuits to true. No filter means retry on every error. Leaving match off is the most aggressive setting, not the safest.

Put together: the backoff override wiped the default allowlist, the now-empty match meant “retry everything,” and so the losing INSERT’s duplicate-key error was treated as retryable. The retry layer re-ran the identical INSERT, with backoff, five times — even though nobody ever listed that error as retryable.

Here’s the thing that makes this a bug and not just slow: a duplicate-key error is permanent. The winning row is already committed. Re-running the exact same INSERT will fail the exact same way, every single time, forever. There is no version of “try again” that succeeds. The retry policy was spending 8 seconds sleeping between attempts that were mathematically guaranteed to fail — and only after exhausting all five did the error finally reach findOrCreate’s catch block, which did the one thing that actually works: read the row.

The delays match the config precisely:

Retry backoffBase * backoffExponent^(n-1) Delay
1 1000 × 1.5⁰ 1000ms
2 1000 × 1.5¹ 1500ms
3 1000 × 1.5² 2250ms
4 1000 × 1.5³ 3375ms
  total ~8.1s

There’s the 8.2 seconds.


An overlooked side effect: connection starvation

The latency was the visible symptom, but there’s a nastier one hiding underneath.

That whole 8.2s happens inside an open transaction, which holds a connection checked out from the pool the entire time. Connection pools are small (5, 10, maybe 20 per instance). If a burst of new users arrives together, several connections can each be pinned for 8 seconds doing nothing but sleeping between doomed retries. Exhaust the pool and now unrelated requests start queuing for a connection — so one user’s harmless race can quietly degrade latency for everyone on that instance.

Non-blocking I/O saves the event loop here (the backoff is a setTimeout, not a busy-wait, so the CPU is free) — but the connection is still held. “It’s async so it’s fine” doesn’t cover resources held across the await.


The fix

The correct recovery for a findOrCreate race is not “retry the insert” — it’s “read the row someone else just created.” That logic already exists in findOrCreate’s catch block. All I had to do was stop the retry layer from getting in its way:

1
2
3
4
5
6
7
8
const [user] = await User.findOrCreate({
  where: { external_id: id },
  defaults: { name, email, external_id: id },
  // A duplicate-key error here is the *expected* outcome of a race, not a
  // transient fault. Don't retry it — fall straight through to the built-in
  // findOne fallback instead of burning the backoff budget on a doomed INSERT.
  retry: { max: 0 },
});

I verified the effect with a tiny standalone script using the same libraries — stubbing a create that always throws a UniqueConstraintError, then timing it under the old policy versus the fix:

1
2
BEFORE (retry max:5)   attempts=5   elapsed=8130.6ms
AFTER  (retry max:0)   attempts=1   elapsed=0.1ms

~8,130ms → ~0.1ms per losing request. Same outcome (the error still propagates to the read fallback) — just without the pointless sleeping.

Should you keep one retry?

Tempting, but no. A single retry (max: 1) still costs a full ~1s backoff sleep and still fails, because the duplicate is permanent. One retry of a non-retryable error is pure waste. The value of retries lives entirely with transient errors — which brings me to the deeper fix.

The deeper fix

Disabling retry at this one call site is the fast, local patch. The real root cause is broader: the retry policy had no match allowlist at all, so it was retrying every error. The proper fix is to give it an explicit match listing only genuinely-retryable failures — deadlocks, lock-wait timeouts, connection resets — and never deterministic ones like unique-constraint violations. That fixes every findOrCreate and create in the codebase at once, not just the one I happened to be looking at. (I also reported the silent default-wiping behavior upstream, since “override backoff, accidentally retry everything” is a sharp edge worth flagging.)


Lessons worth stealing

  1. Tightly-clustered latency is a fixed delay, not load. If your slow requests all land within a few percent of the same number, stop looking at load graphs and start looking for a timeout, sleep, or retry schedule in the code.

  2. Measure where the time goes before theorizing about why. Per-statement timing turned “the database is slow” into “we sleep for 8 seconds between five inserts” in about two minutes. The second statement basically fixes itself.

  3. Not every error is retryable, and check what “no filter” means. Retries are for transient failures. Retrying a deterministic error — a duplicate key, a validation failure, a 400 — can never succeed; it just multiplies the cost of failing. And know your retry library’s default: in more than one of them, an empty match list means “retry everything,” not “retry nothing.” The safe posture is an explicit allowlist of transient errors — deny by default.

  4. A findOrCreate race is normal — handle it by reading, not re-writing. The unique constraint is doing its job when it rejects the second insert. The right response is to go fetch the row the winner created, which most ORMs already do for you.

  5. Watch what you hold across an await. The event loop being free doesn’t mean nothing is blocked. A connection, a lock, or a transaction pinned for 8 seconds is a scalability bug even when CPU usage looks perfect.

The final diff was one line. Finding which line took a lot longer — and that’s almost always the shape of a good debugging story.

This post is licensed under CC BY 4.0 by the author.