How Celery's Default Prefetch Multiplier Buried Login Codes Behind a Bulk Export Job
09:14 UTC. Support tickets start stacking up: users requesting a login code, waiting, and getting locked out before it arrives. PagerDuty pages on a Datadog alert for failed login rate, not on anything in the task queue, because nothing in the task queue is failing. Every OTP send task eventually succeeds. It just doesn't succeed in time.
the scramble
First theory: Twilio is slow. Someone pulls up the Twilio status page and the account's own delivery logs. Both clean, messages going out within a second of the API call that triggers them. Not it.
Second theory: the Redis broker backing Celery is overloaded and OTP tasks are stuck waiting
to even be picked up. redis-cli info on the broker instance shows free memory,
low connected clients, sub-millisecond command latency. The broker isn't struggling either.
Third theory: the OTP task is retrying silently and burning time on backoff. Flower's task
list shows zero retries and zero failures for notifications.send_otp in the last
hour. Whatever is eating six minutes, it isn't inside the task itself.
the hunt
The timestamps are the real clue. Every delayed OTP task shows the same two-second gap between the API call that triggers it and the task showing up as sent in the Celery event log, right up until 09:11 UTC, when that gap jumps to minutes and stays there for every task after it. Something changed all at once, not gradually.
Celery's own inspection commands are what finally surface it. celery -A app inspect
reserved lists every task a worker has already pulled off the broker but hasn't
started executing yet.
-> worker-2: 16 reserved tasks
* exports.generate_csv(report_id=4401)
* exports.generate_csv(report_id=4402)
* exports.generate_csv(report_id=4403)
* exports.generate_csv(report_id=4406)
...
* notifications.send_otp(user_id=88211)
* notifications.send_otp(user_id=88214)
Each of the four workers backing this queue is holding sixteen reserved tasks, and the OTP
tasks are buried at the back of that list behind a wall of
exports.generate_csv entries. Nothing shipped in the last deploy window. The
marketing team's own activity log explains the timing: at 09:10 UTC, someone in growth kicked
off a bulk CSV export covering forty customer segments, and it landed forty
exports.generate_csv tasks on the same default queue that
notifications.send_otp runs on.
the find
Root cause: worker_prefetch_multiplier defaults to 4, meaning each worker
process reserves four times its concurrency in tasks from the broker in a single batch,
before finishing any of them. With concurrency set to 4 per worker, that's 16 tasks reserved
the instant the queue has that many waiting. Those reservations are acknowledged to Redis
immediately on pull, Celery's default is early ack, so once a worker grabs a task it's gone
from the broker. No other worker can pick it up, however idle it is.
When forty export tasks landed in under ten seconds, the four workers on that queue reserved all of them almost immediately, in whatever order Redis happened to deliver. Export tasks run 90 to 150 seconds each doing pandas-heavy CSV generation. Any OTP task reserved behind two or three export tasks on the same worker had to wait for all of them to finish, because a worker's reserved tasks execute in the order its pool processes free up, not by arrival time or priority. The OTP task wasn't failing, retrying, or slow to run. It was sitting behind other tasks that had already claimed the only execution slots it could use.
the fix
The real fix was separating queues by latency class, not tuning the multiplier down everywhere. Login codes get their own queue and their own worker pool, so a burst of exports can never reserve a slot an OTP task needs.
task_routes = {
'notifications.send_otp': {'queue': 'otp'},
'exports.generate_csv': {'queue': 'exports'},
}
task_queues = (
Queue('otp', routing_key='otp'),
Queue('exports', routing_key='exports'),
)[program:worker-otp]
command=celery -A app worker -Q otp --concurrency=2 --prefetch-multiplier=1
[program:worker-exports]
command=celery -A app worker -Q exports --concurrency=4 --prefetch-multiplier=4
The OTP worker runs with prefetch-multiplier=1, so it only ever holds one task
per pool process at a time, no reservation backlog possible. The exports worker keeps the
default multiplier, since throughput matters more than latency there and nothing downstream
cares when a CSV finishes.
The second piece is visibility. This failure mode produces no errors anywhere on its own, so nothing short of measuring queue time directly was ever going to catch it.
avg(last_5m):avg:celery.otp.oldest_task_age{queue:otp} > 10
That gauge comes from a task_prerun / task_postrun signal pair that
stamps each OTP task's time-in-queue before it starts running. Ten seconds is generous for a
queue that normally clears in under two.
the aftermath
- Celery's early-ack default means a reserved task is gone from the broker the moment a worker pulls it, whether or not any other worker sits idle. Prefetch limits create head-of-line blocking per worker, not per queue.
- A queue shared by latency-sensitive and throughput-oriented tasks will eventually let the slow kind block the fast kind, regardless of average load, the moment a burst lands unevenly across workers.
- This incident produced zero failed tasks. Monitoring that only watches task success and failure rate cannot catch it. Time-in-queue has to be measured directly.
- Separating queues by latency class, not by business domain, is what actually isolates this. Exports and notifications were already different Celery tasks, they just needed to stop sharing a queue.
Nothing here was broken in the sense a test suite would catch. Every task ran, every task succeeded, and the queue still cost real users their login attempts for six minutes because the thing that was slow was invisible to every metric that measures success instead of time.