mail-staging-listthreads-slow-report.md19.6 KBView on GitHub # `mail.listThreads` is unacceptably slow on mail-staging — root-cause report
**Date:** 2026-07-27
**Env:** `cedar-staging`
**Owning service:** `api` (tRPC `mail.listThreads`)
**Status:** Root cause proven from traces. Awaiting decision on fix direction (Phase 3 gate).
---
## Symptom & impact
Loading the thread list in mail-staging is slow. Telemetry over the last 6h (page-1 loads only):
| metric | value |
|---|---|
| p50 | **427 ms** |
| p95 | **11,860 ms** |
| p99 / max | **15,889 ms** |
So the *typical* load is fine (~0.4s) but a large fraction stall for **5–16 seconds**. For the two active
staging users, jesse (`ZepBiImpQq5…`) hit **5 of 7 loads over 3s** in one session (max 11.9s).
## One-paragraph root cause
`mail.listThreads` runs an inline **freshness reconcile** (`checkSync`) concurrently with the mirror read
on *every* page-1 load. In the common case both sides agree, the DB read is ~330 ms, and the response is
fast. But when `checkSync` decides the page is **divergent** it does two expensive things *on the response's
critical path*: (1) it re-hydrates the divergent threads from Gmail inline — an **uncapped** loop of
`fetchAndStoreThreadFromProvider` calls (each a `threads.get` + S3 read/write + mirror upsert), and (2) the
`listThreadsFromDb` mirror query itself balloons from ~330 ms to **~10 s**. The DB query is not intrinsically
10s — it degrades under **concurrency**: the frontend fans out several `listThreads` calls at once (one per
inbox tab/category), each spawns 2–3 copies of an `O(total-inbox-threads)` CTE plus reconcile *writes* to the
same `crm_email_threads` table, and Postgres saturates so every query stalls together. Divergence is the
trigger, and once it fires it returns `headChanged: true`, which makes the client trim its cached pages and
refetch — feeding more concurrent load back in. Net: divergent loads cost **db(~10s) + reconcile(~5–10s)**.
## Evidence
**Latency split by divergence** (`mail.checkSync` structured logs, 6h):
| | count | avg db read | p95 db read | avg reconcile | p95 reconcile |
|---|---|---|---|---|---|
| **not divergent** | 38 | 331 ms | 1,443 ms | 0 | 0 |
| **divergent** | 6 | 2,430 ms | **10,096 ms** | 6,707 ms | **10,082 ms** |
Every slow `listThreads` row carries `headChanged: true` (= divergent); every fast one is `false`.
**The worst single trace — `trace_id = ebc8c37ac61ef96a55840af08ebf163a`** (user `ZQLxbHFaT…`, `label:INBOX`, 15.9s):
`mail.checkSync` log for that trace:
```
dbLatencyMs: 10096 // listThreadsFromDb (mirror read SQL) alone
gmailLatencyMs: 198 // Gmail threads.list — fast
draftsLatencyMs: 187
mirrorLookupLatencyMs: 31
reconcileLatencyMs: 5211 // inline re-hydration of 24 threads
reconciledThreadIdsCount: 24
inGmailClassifications: { gmailFresher: 22, newToMirror: 2, inSync: 1 }
```
The OTel span tree confirms the shape: two ~10.1s `db.with` spans (the concurrent `listThreadsFromDb`
executions — one for the page read, one inside `checkSync`), and **only after they finish**, a burst of
**24 `sync.syncThreadFromProvider` spans** (2.8–5.2s each) with their `gmail.users.threads.get`
(up to 4.1s), `s3.readThread/storeThread`, and `mirror.upsertEmailThread` (2.3s) children.
Here `gmailFresher: 22` means Gmail's `historyId` was "newer" than the mirror for **22 of 25 threads** —
i.e. that user's mirror is *systematically* stale (a Pub/Sub freshness gap), so a manual load re-hydrates
almost the whole page.
**The concurrency collision (user jesse):** five slow loads clustered in two bursts —
`17:51:57–59` (`github`, `INBOX`, `Agent drafts` → 10.0s / 11.9s / 11.9s) and `17:52:45`
(two `INBOX` variants → 4.7s / 4.9s). These are near-simultaneous tab loads. Each reconciled only **1–5**
threads (small reconcile) yet the **DB read** ballooned to 10s+ — proving the DB slowness is driven by
*concurrent heavy queries + reconcile writes hitting Postgres at once*, not by the reconcile size.
## Step-by-step code walkthrough
1. **[route-list-threads.ts:184-205](apps/server/src/services/mail/list/route-list-threads.ts#L184-L205)** —
page-1 runs `Promise.all([reconcilePage (=checkSync), readFromMirror])`. Both hit Postgres; `checkSync`
*also* runs its own `listThreadsFromDb`. So a single request issues **2 concurrent copies** of the heavy CTE.
Snapshot: two `db.with` spans, 10.13s and 10.09s, same request.
2. **[route-list-threads.ts:211](apps/server/src/services/mail/list/route-list-threads.ts#L211)** —
`result = divergent ? await readFromMirror() : firstRead`. On divergence it issues a **3rd** heavy CTE read.
3. **[list-threads-from-db.ts:159-210](apps/server/src/services/mail/list/list-threads-from-db.ts#L159-L210)** —
`buildSelect` materializes a CTE `t_labeled` that LEFT-JOINs `crm_thread_labels` + `crm_email_labels` and
`array_agg`s labels for **every** thread matching the label filter, `GROUP BY thread_id`, and only then
applies `WHERE <predicate> ORDER BY latest_message_at DESC LIMIT 26` in the outer query. Cost scales with
**total inbox size**, not page size — so it's cheap when the DB is idle (~330ms) and catastrophic under
contention (~10s). Snapshot: `dbLatencyMs: 10096` for a 25-row page.
4. **[check-sync.ts:342-376](apps/server/src/services/mail/list/check-sync.ts#L342-L376)** —
`allToReconcile = [...toHydrateIds, ...draftNewToReconcile, ...ghostsInline]`. `ghostsInline` is capped at
`MAX_GHOSTS_INLINE = 10`, but **`toHydrateIds` (the `gmailFresher` + `newToMirror` set) is uncapped**. All
22 fresher threads are hydrated inline via `Promise.allSettled(fetchAndStoreThreadFromProvider…)`.
Snapshot: `reconciledThreadIdsCount: 24`, `reconcileLatencyMs: 5211`.
5. **[route-list-threads.ts:217](apps/server/src/services/mail/list/route-list-threads.ts#L217)** —
`headChanged = cursor ? false : divergent`. Returned to the client, which trims cached pages back to
page 1 and refetches → more concurrent loads → more DB contention → the loop sustains itself.
## Blast radius
- Any inbox load where `checkSync` reports divergence — worst for **users whose mirror is stale** (Pub/Sub
gap makes the whole page `gmailFresher`) and whenever **multiple tabs load at once**.
- The uncapped inline reconcile also issues 20+ Gmail `threads.get` calls per bad load — quota pressure.
- Not data-corrupting: hydration re-asserts Gmail state. Purely a latency / load problem.
- Staging has few users, so one churning user dominates the percentiles; on prod the same mechanics apply
per-user but are diluted in aggregate — the tail is still real for the affected user.
## The fix hierarchy — and why "cap the reconcile" is only a band-aid
The goal is a **<300ms p99** mirror read. There is exactly one fix that gets there; the rest reduce how
often the slow path fires but leave the read itself slow. Ranked by how deep they cut:
**THE deepest proper fix — make the read O(page size) via a co-located ordering index.**
Today no index yields "threads carrying label L, ordered by `latest_message_at`" (the label lives in
`crm_thread_labels`, the sort key on `crm_email_threads` — two tables, no shared index). So every read is
forced to materialise + label-aggregate the *entire* label set (1,233 rows for a 26-row page) before it can
sort. Co-locate the sort key with the label membership — carry `latest_message_at` on `crm_thread_labels`
with a composite index `(connection_id, label_id, latest_message_at DESC, thread_id DESC)` — and the page
becomes a single index range scan: `WHERE connection_id=X AND label_id='INBOX' ORDER BY latest_message_at
DESC LIMIT 26`. Labels are then aggregated for only those 26 threads, and `crm_email_labels` is joined only
when the query filters by a label *name*. Result: a few hundred buffer touches instead of 27,388 — cheap
enough that even 15 concurrent tab loads stay in cache. **This is the only option that makes the read itself
fast; everything below just fires it less often.**
Cost/tradeoff: a new column + backfill (1.6M rows) and one extra maintenance write — when a thread's
`latest_message_at` changes (new message), its ~4 join rows must be updated. That write amplification is why
the join table is deliberately diff-only today ([email-threads.ts:328](apps/server/src/services/crm/email-threads.ts#L328)),
so the maintenance must be a single targeted `UPDATE … WHERE thread_id=? AND connection_id=?`, not a
delete/reinsert.
**Band-aids (do NOT reach 300ms on their own):**
- **Cap the inline reconcile** (the former "A"): bound `toHydrateIds`/ghost hydration so a divergent load
can't fetch 24 threads inline. This only shrinks `reconcileLatencyMs`; the *read* still costs 27k buffers
and still collapses under concurrent tabs. It's a band-aid because it treats the symptom (a big reconcile)
not the cause (an O(inbox) read run 2–3× under a stampede). Worth doing, but it is not the fix.
- **Run the read once per request** (not 2–3×): removes a 2–3× multiplier but leaves each read O(inbox).
- **Reconcile off the critical path** (fire-and-forget `checkSync`): stops the reconcile from ever blocking
the response, but a cold O(inbox) read is *still* >300ms under load. Also a real behavior change (divergence
surfaces to the client asynchronously).
- **Fix divergence at the source** (see the corrected D section below): the non-converging ghost loop keeps
`divergent:true` firing on most loads. Fixing it makes the slow path rare — but a rare 10s load is still a
10s load. Necessary for correctness and load, not sufficient for p99.
**Bottom line:** the co-located ordering index is the deepest proper fix and the only one that hits the
<300ms-p99 target. The ghost-loop fix (D) is the necessary correctness companion so the fast read isn't
needlessly re-run. The caps are optional insurance.
## Implementation status (co-located ordering index — the deepest proper fix)
Built on this branch (read path stays on the old query until the flag is flipped):
- **Schema** — `crm_thread_labels.latest_message_at` + index `idx_crm_thread_labels_label_latest
(connection_id, label_id, latest_message_at DESC, thread_id DESC)`
([crm-schema.ts](apps/server/src/db/crm-schema.ts)).
- **Migration** — idempotent, batched backfill + `CREATE INDEX CONCURRENTLY`
([crm_thread_labels_latest_message_at.sql](apps/server/src/db/migrations/crm_thread_labels_latest_message_at.sql)).
- **Write-path maintenance** — `setThreadMirror` propagates a thread's `latest_message_at` to its label rows
only when it actually moved (`IS DISTINCT FROM` guard — no write amplification on no-op re-syncs);
`patchEmailThreadLabels` stamps newly-added label rows ([email-threads.ts](apps/server/src/services/crm/email-threads.ts)).
- **Fast read** — `buildFastSelect` reads the page straight off the index (single label, trivial predicate),
aggregates labels for only the returned page, and skips the `crm_email_labels` name join; falls back to the
existing aggregate query for multi-label / predicate-bearing queries
([list-threads-from-db.ts](apps/server/src/services/mail/list/list-threads-from-db.ts)). Gated on
`LIST_THREADS_COLOCATED_ORDER`.
- **Tests** — 22 in `list-threads-from-db.test.ts` (7 new fast-path: eligibility, pagination parity, cursor,
fall-throughs, flag-off), 160 green across the list dir; full typecheck clean.
**Benchmark — PROVEN on the real DB (minimal-footprint: column + one connection backfilled + partial index):**
| query (jesse, `label:INBOX`, warm) | buffers | time |
|---|---|---|
| current aggregate query | 27,388 | ~50 ms |
| **fast path (co-located index)** | **308** | **~1.4 ms** |
**89× fewer buffers, ~35× faster.** Plan is O(page): `Index Only Scan → Limit 26` (99 buffers) pulls the page
straight off the index, then 26 pkey lookups + label aggregation for only those 26. A 15-tab stampede is
~4,600 buffer touches vs ~411,000 — stays in cache. Comfortably beats the 300ms-p99 target. (The benchmark
partial index was dropped afterward; the DB currently holds only the added nullable column + one connection's
backfill — unused by the running app, flag off.)
Note: the target DB is prod-scale (170 users / 190 connections, PG 17.6). All applied ops were non-blocking —
`ADD COLUMN` nullable (metadata-only, `lock_timeout` guarded), and `CREATE INDEX CONCURRENTLY`.
**Full rollout (deliberate, ideally off-peak — each step non-blocking):**
1. Batched full backfill of 1.69M rows (`crm_thread_labels_latest_message_at.sql` — 10k/batch, `SKIP LOCKED`).
2. Build the real `idx_crm_thread_labels_label_latest` `CONCURRENTLY`.
3. Deploy the write-path maintenance (keeps the column fresh) + the gated read.
4. Flip `LIST_THREADS_COLOCATED_ORDER=true`, watch `dbLatencyMs` p95/p99.
5. Follow-up: extend the fast path to predicate-bearing queries (over-fetch + keyset).
## Deep dive: why the mirror READ is structurally O(inbox), not O(page)
Real example — jesse (`ZepBiImpQq5…`, connection `2bcbb2fa…`), query `label:INBOX`, page size 25.
Real scale on staging: **362,714** total threads, **1,619,196** thread-label rows; this connection has
**5,387** threads, **1,233** of them in INBOX.
`EXPLAIN (ANALYZE, BUFFERS)` of the exact SQL `buildSelect` emits (warm cache, 3 runs): **~50ms, 27,388
shared buffers hit** to return 26 rows. The plan, bottom-up:
1. `Bitmap Index Scan idx_crm_thread_labels_label (connection_id,label_id)` → the **1,233** INBOX thread_ids. (fast, ~1,148 buffers)
2. `Nested Loop` into `crm_email_threads` pkey, **1,233 loops** → the 1,233 thread rows. (4,936 buffers)
3. `Nested Loop Left Join` into `crm_thread_labels tl` — pulls **every** label row for those threads → **5,294** rows. (5,424 buffers)
4. `Nested Loop Left Join` into `crm_email_labels el` for display names — **5,294 loops** → **15,879 buffers (58% of the whole query)**.
5. `GroupAggregate` back to **1,233** rows, building the `label_ids` / `label_names` arrays for every inbox thread.
6. `Sort` (top-N heapsort) by `latest_message_at DESC` → keep **26**.
7. `Limit 26`.
The shape of the cost: to hand back **26** rows the database first fully builds and label-aggregates
**all 1,233** inbox threads and does **5,294** label-name lookups. **Work scales with inbox size, not page
size.** The `ORDER BY latest_message_at DESC LIMIT 26` cannot be pushed down because the `GROUP BY thread_id`
aggregation must complete first (steps 3–5 happen before step 6).
**Root structural gap:** there is *no index that yields "INBOX threads for this user ordered by
`latest_message_at`."* The label lives in the separate `crm_thread_labels` join table, and its only useful
index is `(connection_id, label_id)` — no timestamp. So any query is forced into one of two O(data) shapes:
- **Current:** materialise + aggregate the whole label set, then sort (27,388 buffers, ~50ms warm).
- **"Page-first" (scan `idx_crm_email_threads_user_latest` backward, probe membership):** measured
~44–385ms and ~10,000 buffers here, because INBOX is sparse among the most-recent threads so it walks past
hundreds of archived/sent threads to collect 26 INBOX ones. Also not O(page).
**Two concrete inefficiencies quantified:**
- **58% of the query is wasted on label display-names.** Dropping the `crm_email_labels el` join takes the
query from **27,388 → 11,499 buffers**. That join only matters when the filter references a *user label by
name* (e.g. `label:"Cedar/Agent drafts"`); for `label:INBOX`, `is:starred`, etc. it is pure overhead.
- **Labels are aggregated for all 1,233 threads** when only the 26 returned need their label arrays.
**Why warm is 50ms but p99 is ~10s:** 27,388 buffers × 8KB ≈ **224 MB of buffer touches per single call**.
[route-list-threads.ts:184](apps/server/src/services/mail/list/route-list-threads.ts#L184) runs it 2–3× per
request, and the client fans out ~5 tabs at once → **10–15 concurrent copies**, each touching 224 MB and
CPU-aggregating 1,233 threads. That blows the shared-buffer cache, the 27k hits turn into disk `read`s, CPU
saturates, and every copy stretches to seconds (the same run went from `read=14` warm to `read=2155` when
cold). The buffer footprint per call is the real enemy — not the warm latency.
**What a <300ms-p99 read structurally requires** (stated as the target shape, not a patch):
- A read that is **O(page size)**: fetch the 26 thread_ids for the label ordered by `latest_message_at`
from a **single co-located index** — i.e. denormalise `latest_message_at` (and the cheap flags) into
`crm_thread_labels`, or add a partial/covering index, so `WHERE connection_id=X AND label_id='INBOX'
ORDER BY latest_message_at DESC LIMIT 26` is answered by one index range scan.
- **Aggregate labels for only those 26** threads (steps 3–5 shrink from 1,233 → 26).
- **Join `crm_email_labels` only when the query filters by a label name** (skip the 58% for the common case).
- **Run the read once per request** (not 2–3×), so concurrency is bounded.
At O(page size) each call would touch a few hundred buffers instead of 27,000, so even 15 concurrent tab
loads stay entirely in cache and finish in single-digit ms — comfortably under the 300ms p99 target.
## D investigation (corrected) — Pub/Sub push WORKS; the real bug is a non-converging ghost loop
**Correction to an earlier note in this report:** I previously wrote that sync was a "10-minute polling cron,
not push." That was wrong — it was inferred from one low-traffic connection during a quiet window where only
the periodic safety-net sync ran. Broader data shows **Pub/Sub push is working**:
- 24h on staging: **597 `pubsub.gmail_notification`** received, **496 `[GOOGLE] Sent to thread queue`** enqueued.
- Per connection: jesse `2bcbb2fa` = **436** push enqueues, `ecffb0c4` = **60**.
- The consumer keeps up: jesse **580 `mail_sync.enqueued` → 506 `run_start` → 506 `run_complete`**, zero
errors (the 580→506 gap is the intended "already pending" dedup). History staleness is essentially absent —
in the worst 6h window, `gmailFresher = 8`, `newToMirror = 6`.
So push, the queue, and the incremental sync are all healthy. **D-as-"broken-Pub/Sub" is disproven.**
**What actually drives divergence — a false-ghost loop.** Divergence is *not* rare: it swung to **65.6%
(168/256 loads)** on 07-29 evening. In that window the divergence is almost entirely **ghosts**
(`ghostsTotal = 323`, vs `gmailFresher = 8`). A ghost = a thread the mirror lists as INBOX that Gmail's `q:`
search does not return, so `checkSync` thinks it left the inbox and reconciles it.
The recurrence pattern is the proof it never converges:
- `caf60397…` (`label:INBOX`): **exactly `ghostTotal: 1` on every load**, every ~2–3 min, 19:10 → 20:05+.
- `2bcbb2fa…` (`label:INBOX -(…)`): **exactly `ghostTotal: 4` on every load**, for hours.
If these were real archives, reconciling once would drop the INBOX label in the mirror and they'd stop
appearing. Instead the **same count recurs forever** → `fetchAndStoreThreadFromProvider` hydrates the thread,
Gmail says it *is* still in INBOX, nothing changes, and the next load re-flags the identical "ghost." Each
such load returns `divergent: true` → `headChanged` → the client trims+refetches → the slow reconcile+re-read
path fires again. This is a **correctness bug in divergence detection** (Gmail `q:` persistently omitting
threads that are genuinely in the mirror's INBOX — likely the `q:` vs `labelIds` window/consistency mismatch
documented in [check-sync.ts:82-87](apps/server/src/services/mail/list/check-sync.ts#L82-L87)), independent
of DB read speed.
**Conclusion on D:** push/sync are fine. The divergence — and therefore how often the slow path runs — is a
`checkSync` ghost loop that never converges. Fixing it (stop re-flagging the same non-actionable ghosts every
load) is the correctness+load fix; it makes the slow read *rare*. It does **not** make the read *fast* — that
still requires the co-located ordering index above.