On September 9th, the author dashboard and newsletter archives were slow or unavailable from about 18:35 to 20:35 UTC; during that time email sending and other background work (subscriber imports, analytics, automations) were delayed. No data was lost, and all emails went out (eventually).
What happened?
On September 9th, our database's connection pool was saturated by the combination of two things:
- A particularly large broadcast from one of our largest authors who hadn't sent in a while
- An internal admin page which targeted the primary database connection instead of the replica
Neither of these was a problem on its own. Together, they taxed the connection pool in front of our database: we never ran out of connections, but almost every web request spent its time waiting in line for one instead of doing work. (More on why below.) The result was a system that was slow across the board.
The large broadcast
Every email Buttondown sends is broken into batches and processed by a fleet of background workers. Each newsletter has a per-minute sending cap; when a batch would exceed it, the worker rejects the batch and re-queues it to try again in a few minutes. This cap is based on a number of things, including the most recent time the author has sent (which we use to gauge "how likely is it that Gmail et al will rate-limit our sending?").
At 13:05 UTC, a particularly large broadcast started sending. This was not problematic, and we sent it out for several hours without issue and within SLA.
At 18:15 UTC that stopped being true. Throughput in our overall asynchronous job system dropped to around 20% of where it was earlier that day. This was due to a viciously naive mechanic:
- When lacking other heuristics, we prioritize executing background jobs that have earlier SLAs.
- When we re-queue a batch that exceeds the sending cap, we re-queue it with its original deadline (since it still needs to go out at the same time as the rest.)
- Every poller would, upon looking at the queue for work, identify these redriven batches as the most important and starve the other jobs (even as all we did with these redriven batches is mark them as needing to be retried later.)
As the backlog grew, the worker fleet scaled up to its maximum of 40 instances, and that is what took down the web app. The author dashboard, public archives, and API started slowing down at about 18:35 UTC, twenty minutes after the queue jammed. By 18:50 UTC the slowest 1% of requests were taking 28 seconds; our frontend's 30-second timeout was being hit routinely.
The internal admin tool
The database itself was fine — it was executing our web queries in 16 milliseconds. The problem was the connection pool in front of it. Our web servers, our background workers, and our internal admin tool all connect to the database as the same user, through the same pooler. With 40 workers running, the workers held enough of the pool that web requests spent most of their time waiting for a connection. During the worst half hour, web requests spent about 10,900 seconds waiting on the database while the database spent about 290 seconds actually running their queries.
At 19:00 UTC, the problem worsened due to an internal admin tool which also queries the database. That page ran two heavy aggregate queries over our event table on every load, auto-refreshes every 60 seconds without waiting for the previous refresh to finish, and — contrary to what we believed — was pointed at the primary database rather than a read replica. One of the two queries reads about 3.2 million rows to return 25, because it filters with a JSON operator that doesn't match the operator its index was built for. Between 19:00 and 19:30 UTC that one page accounted for 78% of all time spent on our primary database.
Mitigation
Ultimately, we were able to mitigate and then resolve by:
- Temporarily pausing the specific email which kicked off the scaling.
- Killing (and then enforcing via traffic control) the queries coming from the internal admin tool.
Once we did that, the queue drained out and the web app recovered quickly.
Who was affected?
- The dashboard and archives were fully unavailable for many users from roughly 19:18 to 19:21 UTC, and degraded (slow or intermittently timing out) from about 18:35 to 20:35 UTC. Archives on custom domains were also affected, since they're served by the same application.
- 748 requests took longer than 10 seconds in that window; the preceding hour had one.
- New subscriber signups fell by 79% in the 19:00–19:15 UTC quarter-hour compared to the same window the day before, and by 69% at 20:00–20:15 UTC. API request volume fell by 38–52% in the same windows. We don't have a way to count signups that were abandoned rather than delayed.
- 27 newsletters had sends delayed. One was the large send itself (94% of the delayed batches); 26 others were simply queued behind it. The longest delay was 170 minutes for an 18,000-subscriber newsletter. Median send time for the day went from 0.4 minutes to 95 minutes at the 90th percentile.
- The 22 emails held by the cached flag went to 20,601 recipients and were delayed by 32–170 minutes. All were delivered.
- Around 7,000 recipients of the large send were caught in batches we force-failed during recovery and did not receive it.
- Webhook processing, open and click tracking, and analytics lagged by up to 110 minutes; this is where most of the 410,000 missed deadlines landed.
- A second, smaller backlog (peak 60,000, deadlines missed by 4–17 minutes) occurred from 22:00 to 22:45 UTC as the resumed large send generated delivery events while we still had the worker fleet scaled down. We did not notice this at the time.
How did we detect the issue?
A team member noticed a Cloudflare error while working on something unrelated at 19:12 UTC, 37 minutes after web latency had degraded and 57 minutes after the queue had jammed. Reports from authors that drafts weren't sending arrived at 19:55 UTC.
We had a latency dashboard that would have shown the problem, but no alert attached to it. Our queue-depth monitoring updates every 5–10 minutes and also had no alert on backlog size.
Timeline
| Time (UTC) | Event |
|---|---|
| 18:15 | Background-job throughput collapses from ~4,800 to ~370 completions per minute. No alert fires. |
| 18:35 | Web latency begins degrading as the worker fleet ramps to 40 instances and holds most of the shared connection pool. |
| 19:00 | An internal admin page starts issuing heavy aggregate queries against the primary database every 60 seconds. |
| 19:12 | A team member notices a Cloudflare error while working on something unrelated. |
| 19:17 | Team member paged. Status page incident opened at 19:18 as "App and Archives are down." |
| 19:19 | Worker fleet scaled from 40 to 10 to relieve the database. Web latency roughly halves over the next ten minutes; in hindsight this was the single most effective action of the hour. |
| 19:24 | Admin-tool queries identified in the database's query insights. A rate limit is placed on the admin tool, the tool is restarted, and the running query is cancelled by 19:29. Web latency improves further. |
| 19:32 | Status page updated to "mitigated." This was premature: the queue was still growing and web latency was still 5–10× normal. |
| 19:55 | Authors report stuck drafts. Backlog measured at 220,000 and rising; root cause of the queue jam identified by 20:02. |
| 20:08 | The large send is paused. This has no measurable effect on the queue. |
| 20:16 | Outgoing-email flag turned on as a belt-and-braces measure (see above for what this caused). |
| 20:19 | The queued batches for the large send are marked as failed directly in the database, and the worker fleet is restarted at 20:26. Throughput returns immediately: 388,000 jobs complete in the next 15 minutes. |
| 20:35 | Web latency back to normal. Backlog back to normal by 20:40. |
| 20:42 | First reports of the "account disabled" emails. |
| 20:44 | Large send resumed; outgoing-email flag turned off at 20:46. |
| 21:16 | Worker fleet scaled down, then restarted a second time at 21:22 to clear the cached flag value, releasing the 22 held emails. |
| 22:17 | Status page incident resolved. (The 22:00–22:45 recurrence was underway at the time and went unnoticed.) |
| 23:03 | Errored emails moved back to drafts; affected authors contacted. |
How will we prevent this from happening again?
There's a lot of obvious object-level work to be done here that at the time of this writing is either shipped or in review:
- We've fixed the job-scheduling bugs that let re-queued batches starve the rest of the queue, which is what made this get worse instead of better on its own.
- We've put better safeguards around the internal admin tools that tend to run slow queries, so they always run against a replica that can't compete with author traffic.
But, as always, the most interesting (and, perhaps, damning) work is in the detection and incident response itself:
- We've added monitoring on the connection pooler itself, so we hear about it when wait time gets high rather than when the database gets unhealthy — which, in this incident, it never did.
- We're improving our latency alerting so that a 5–10× regression pages someone as soon as it starts, instead of waiting for a team member to stumble onto a Cloudflare error thirty-seven minutes later.
- We've reworked a lot of our dashboards to be more useful in exactly this kind of incident, so the next person on call can get from "the app is slow" to the specific query responsible in minutes.
We last wrote about database connections in March, when we ran out of them entirely. This incident is a close cousin: the database itself was healthy insofar as it kept up with workload, but we once again failed to reckon with the long tail of database sadness.