← Back to lab

One 2,700-Product Import Sent Cold Queries to 30 Minutes. The Cache Hid It.

A 2,700-product import tripled one category and cold catalog queries hit 30 minutes — three stacked Postgres plan bugs, and the response cache hid all of it.

One 2,700-Product Import Sent Cold Queries to 30 Minutes. The Cache Hid It.

A routine vendor feed import — about 2,700 products — roughly tripled the size of one category in a price-comparison catalog I run on Postgres. Cold queries on the public catalog went from ~4 seconds to 30+ minutes. Popular pages stayed instant, because the HTTP cache answered them.

That's what made it nasty. The API looked healthy from the outside. The first real signal was the database: load average 26, and 25 concurrent copies of the same list/search query running until someone cancelled them by hand. Every cache miss was a landmine; only cold and long-tail requests stepped on one.

Worth sitting on that shape for a second, because it's the part that generalizes. A response cache doesn't just hide latency — it hides the queries that would reveal your real p99. Load test after the fix showed 8 parallel cold requests finishing in ~1.3 s each; before the fix, the same pattern is what took the box down. If your benchmarks only ever hit warm entries, you have no benchmark. From now on, any "is it fast" check on this stack gets a cache-busted cold pass or it doesn't count.

Diagnosis: read the plan, not the uptime

Rule from this incident: EXPLAIN the plan, never ANALYZE on production. The plan alone showed three bugs stacked on top of each other. Any one of them alone would have been survivable. Together they turned a 4-second query into a half-hour one.

Bug 1: a correlated `EXISTS` embedded 13× per statement.

The list query builds its response from a stack of aggregates over the variants×offers join, each with a FILTER clause restricting which vendors count as a public offer source. That predicate was built as a correlated subquery, simplified:

-- emitted once per aggregate FILTER — 13 copies per list statement
EXISTS (
  SELECT 1
  FROM vendors v
  JOIN feed_configs fc ON fc.vendor_id = v.id
  WHERE v.id = o.vendor_id AND fc.is_active
)

Correlated means Postgres can't hoist it — it re-runs the vendors/feed_configs scan per row of the variants×offers join, and the list query references it 13 times per statement. Millions of sequential-scan executions per request. The fix was the semantically equivalent, uncorrelated form:

-- one evaluation per query, hashed subplan
o.vendor_id IN (
  SELECT v.id
  FROM vendors v
  JOIN feed_configs fc ON fc.vendor_id = v.id
  WHERE fc.is_active
)

That predicate is shared by 54 call sites across the public API, so one change fixed every endpoint at once.

Bug 2: an `OR` that defeated cardinality estimation.

Category filtering joined a subtree with:

ON d.id = root.id OR d.path LIKE root.path || ' > %'

The OR blinds the planner's cardinality estimate. It never drove the products table from the category index; instead it hashed the entire 363k-row variants×offers join and filtered afterwards. The fix moved the subtree resolution into application code — the subtree is tiny — and passed plain IDs:

mp.category_id = ANY($1::int[])

IDs are resolved up front and TTL-cached for 60 seconds, with the SQL subtree kept as a fallback. The planner started driving the category index again.

Bug 3: planner stats gone stale after the bulk import.

product_variants claimed 840k rows where 17k were live; offers claimed 341k against 216k actual. The import had churned enough rows, recently enough, that the planner was working with fiction in both directions — one table wildly overestimated, the other underestimated. Autovacuum would have gotten there eventually, but "eventually" is measured in its own thresholds, which are themselves computed from the stale live-tuple counts. ANALYZE plus VACUUM on the hot tables brought n_live_tup back in line and restarted that loop honestly.

Stack the three and you get the shape of the outage: a planner working from wrong row counts (bug 3) picks a hash of the full 363k-row join because the OR join gave it no usable estimate (bug 2), and then pays for it per-row, 13 times over, through a correlated subquery (bug 1). The import itself — 2.7k products on a catalog of hundreds of thousands — was just the finger that tipped it over.

The belt-and-suspenders layer

Fixing the plans wasn't the end. Two structural changes so the next bad plan is an event, not an outage:

  • `statement_timeout` of 30 s on all list/facets/search queries. A future pathological plan now degrades to a fast 500 instead of 25 half-hour backends piling up.
  • A partial index on master_products(category_id) WHERE merged_into_id IS NULL, plus dropping 2 of 3 duplicate indexes on product_variants(master_product_id) — the duplicates were pure write overhead. The index went on production with CREATE INDEX CONCURRENTLY first; the recorded migration is a lock-free no-op there.

Before / after

Cache-busted cold calls, identical payloads:

QueryBeforeAfter
by-category, limit=14.26 s, hang under load0.66 s
by-category, limit=1004.13 s0.69 s
8 parallel cold, limit=100pile-upall ~1.3 s
facets (category)—0.44 s
search, fuzzy pass (SQL only)~7.6 s~5.3 s

Load average went 26 → ~1. pg_stat_activity showed no queries over 60 s afterwards.

What I'd change

The statement_timeout should have existed from day one — it costs nothing and converts this class of incident from "discover via load average" to "see a 500 in the logs". And bulk import jobs should end with an explicit ANALYZE of every table they touched in bulk; waiting for autovacuum to catch up after a big import means the planner serves fiction in the meantime. The reltuples vs n_live_tup drift is now my canary: when those diverge by an order of magnitude after a load, the plans are about to lie to me.