Why the email phase took twenty hours

The engine from the architecture post imported a customer's 400,000 records in a few hours. Then it started on email: 30,788 deals had mail attached, one task per deal, and the phase ran for twenty hours.

This post is about how I found out why, mostly by being wrong four times in a row, and about what the right measurement revealed once I made it. The fixes are in the next post; this one is the diagnosis, because the diagnosis is the part I would do differently.

The shape of an email task

Each email task did the same thing:

1. one listing call — every message attached to the deal, 500 per page;
2. for each message, one fetch for its body, because the listing carries subject, sender and snippet but not the body;
3. for each message, one write.

So a deal with N messages was 1 + N round-trips to the source API, made one after another, followed by N writes. Keep that shape in mind; it explains everything below.

Four wrong theories

The phase started at about sixty deals a minute and sank to twenty within the first hour. Here is what I thought, in order, and how each was wrong.

"Another run is competing." A second person had started a dry run on a different tenant at about the time the rate dropped. Dry runs make the same listing calls, and the two runs share one queue lane. Plausible. I measured it: the dry run finished, and the rate did not recover. When I later put a dry run beside a live one on purpose, the live one did not slow at all. The coincidence was real; the cause was not.

"The pool is starved." The queue's lane has a few threads and the planner keeps a bounded number of tasks enqueued per run. If the enqueues lagged, threads would idle. I looked at the queue: unfinished 1, running 1, waiting 0. So the pool was below width — but it turned out that was a different bug, and fixing it later (below) brought the rate from 32 to 60 a minute at the same payload, not from 20 to 60.

"The burst window is full." The source API allows a fixed number of requests per two-second window, and the engine leases slots against it. I read the budget row: it said the window was full. Then I read it again and realised I had read the wrong row — a test fixture from a spec that had run on the same account key. The real account was using about one request per second of an eighty-per-window allowance. Zero 429s in the whole run.

"Queue priority is skewing the lane." The lane runs tasks oldest-first; maybe another queue's jobs were taking the threads. They were not; the lane is dedicated.

Four theories, four rounds of looking at infrastructure. None of them looked at the work.

The query that answered

Every task keeps a small stats hash: how many rows it saw, imported, skipped, failed. For an email task, imported is the number of messages the deal had. So the question "why did tasks get slower" can be asked directly of the tasks:

SELECT
  CASE WHEN (stats->>'imported')::int >= 3 THEN '3+'
       ELSE stats->>'imported' END                   AS messages,
  count(*)                                           AS tasks,
  round(avg(extract(epoch FROM finished_at - started_at))::numeric, 2) AS avg_seconds
FROM migration_tasks
WHERE migration_id = $1 AND kind = 'emails' AND status = 'succeeded'
GROUP BY 1
ORDER BY 1;

messages | tasks  | avg_seconds
---------+--------+------------
 1       | 11,204 |  1.64
 2       |  4,910 |  2.89
 3+      |  3,382 |  8.69

That was the whole answer. Task time scaled with the deal's own mail. The step from one message to two is 1.25 seconds — one body fetch plus its write. The run had not slowed down; it had moved into a stretch of deals with more mail. The last 2,000 deals averaged 4.4 messages each; one deal held 1,564.

The measurement had been available the whole time, from a table I had designed myself, and I spent an evening on infrastructure theories before asking it. Group the duration by the task's own payload before you blame anything outside the task.

What the numbers said the levers were

Once the model was "a deal costs 0.3 s to list, 0.2 s of engine overhead, and 1.15 s per message, all serial", the levers ranked themselves:

• The API round-trips are 85% of the time, so the phase is latency-bound. More threads help linearly; fetching a deal's bodies concurrently helps most on rich deals, which were the slow ones.
• Postgres was at 11% CPU. Cutting writes would not make the phase faster. It would make more concurrency safe, which is a different and better reason to do it.
• Nothing about the source's limits was in play. The account used about one request per second of a forty-per-second window and never saw a 429.

That ordering — make the per-deal work cheaper for the database first, then add concurrency — is what the next post implements.

The write ledger of one deal

Cutting writes needed a count, so I traced one four-message deal through the code path. This is what one task wrote, before any change:

For N = 4 that is about 26 statements, 17 commits, and 6 writes on two single hot rows — the budget row and the run row. Across the phase, roughly 680,000 statements and 460,000 commits, of which 154,000 were the budget row being rewritten with a number the next response would overwrite anyway.

None of it was slow individually. All of it was contention waiting to happen the moment the lane widened.

The pool that decayed to one

The "starved pool" theory was wrong about the twenty-hour phase but right about a bug, and it's a good one.

The planner kept a bounded number of a run's tasks enqueued and refilled when a task finished. The first version refilled by enqueueing exactly one successor — one in, one out:

# before
def top_up!(migration)
  enqueue_pending!(migration, limit: 1)
end

enqueue_pending! takes the first limit tasks that are still pending. But a task that is queued and not yet claimed is still pending. So when two tasks finish close together, both enqueue the same next task; one claims it, the other claims-or-exits doing nothing. Two finished, one useful successor. The depth halves each round and decays geometrically to one — which is exactly what the queue showed: running 1, waiting 0, against a four-deep pool and a two-thread lane. One thread idle for hours.

The reaper restored the depth on its five-minute cron, and it decayed again within seconds. The fix is to refill to the deficit, as the reaper already did:

# after
def top_up!(migration)
  deficit = MAX_INFLIGHT - MigrationTask.where(migration_id: migration.id, status: "running").count
  enqueue_pending!(migration, limit: deficit) if deficit.positive?
end

Over-enqueueing on a race is harmless because the job claims-or-exits. The guard for this one is a spec that finishes two tasks and asserts the pool is back at width, not at width-minus-one; it fails against the old line.

Two smaller things the trace exposed

The run log rewrote itself per failed row. The run keeps a capped array of the last 200 log entries in a JSON column, appended by a SQL statement that trims to the cap. Appending rewrites the whole value — about 30 KB — and the failure path called it once per failed row. A run with 234,856 failures rewrote a 30 KB value 234,856 times. It is now buffered per task and appended once, and flushed early if a task fails more than the cap.

"Nothing in the log" is not "nothing happened." The 200-entry cap meant that a phase's failures scrolled out before I looked. The true per-entity failure count was always on the stats rollup; the log was a sample. I stopped treating it as a record.

The rule

Before blaming contention, throttling, priority or another tenant, group the task's duration by the task's own payload. If the number moves with the payload, the work got heavier, and every infrastructure theory is a distraction. If it does not, then look outside. That one query would have saved me an evening; it has since been the first thing I run.

The fixes — parallel bodies inside a job, the budget row off the hot path, ten deals per task, and what that does to Ruby threads, the GVL and the connection pool — are the next post.