Rails + PostgreSQL Performance Audit Playbook

gistfile1.txt

# Rails + PostgreSQL Performance Audit Playbook

A field-tested method for finding what's actually burning your database CPU, built for a
Rails monolith on managed PostgreSQL (Cloud SQL / RDS / etc.). It assumes no APM — just
`pg_stat_statements`, `pg_stat_activity`, and discipline. It pairs well with an LLM: point
one at this file plus your query results and let it do the attribution; the queries below
are ordered so a human can run them and paste results back.

## The core idea

Your cloud console's query dashboard will not tell you what's wrong. Ground truth lives in
two places: `pg_stat_statements` (cumulative, per-normalized-query) and `pg_stat_activity`
(live, per-backend). The method is: establish the measurement window (A), read the chronic
top consumers (B/C), check what's happening right now (D–G), and when "chronic" and "now"
disagree, measure a delta window (H). Then map each expensive query family back to code and
fix the mechanism, not the symptom.

## Why your cloud console lies

- **Fingerprint fragmentation.** Postgres 15 and earlier fingerprint every `IN (...)` list
  length separately, and Rails' `where(id: array)` produces every length. One logical query
  shatters into hundreds of rows (we measured 1,000+ shapes for a single table's lookups) —
  no single row looks scary while their sum saturates the box. PG16's list-squashing helps
  but doesn't cover everything. Query C below is the antidote.
- **Short retention.** Console per-query views typically keep ~7 days — you cannot
  time-slice a regression older than that. Fingerprint "birth-dating" (below) substitutes.
- **Utility statements are invisible.** `REFRESH MATERIALIZED VIEW`, `CREATE INDEX`,
  `VACUUM` get one queryid per object name (or aren't tracked at all, depending on
  `pg_stat_statements.track_utility`) and never aggregate into a family. A materialized-view
  refresh can be your single biggest CPU consumer and appear NOWHERE in the top-N.
- **Only finished statements are recorded.** A query that has been running for 12 hours
  contributes zero to `pg_stat_statements` until it completes. Long-running work is only
  visible in `pg_stat_activity`.
- **Duration includes lock waits.** In `pg_stat_activity`, a backend blocked on a lock still
  shows `state = 'active'` with a growing duration. Always read `wait_event_type`: NULL =
  genuinely on CPU; `Lock` = a victim queuing behind someone else. A huge duration can be
  either the culprit or the queue behind it.

## The queries (run in this order, on the primary)

### A — measurement window (always first)

```sql
SELECT stats_reset, now() - stats_reset AS window FROM pg_stat_statements_info;
```

If the window is months long, B/C describe *chronic* load, which may not be today's problem.
Compute average busy backends: `sum(total_exec_time)/1000 / extract(epoch from window)` and
compare with current CPU (N cores pegged ≈ N busy backends). A large gap means today's mix
differs from the chronic top-N → rely on H. If the window is only days old, B/C haven't seen
a full weekly cycle yet — same conclusion.

### B — top consumers with % share

```sql
SELECT
  round((100 * total_exec_time / sum(total_exec_time) OVER ())::numeric, 1) AS pct,
  calls,
  round(mean_exec_time::numeric, 2)              AS mean_ms,
  round(total_exec_time::numeric / 1000, 1)      AS total_s,
  rows,
  left(regexp_replace(query, '\s+', ' ', 'g'), 130) AS query
FROM pg_stat_statements
ORDER BY total_exec_time DESC
LIMIT 25;
```

### C — fragmentation detector (collapse by prefix)

```sql
SELECT
  left(regexp_replace(query, '\s+', ' ', 'g'), 60) AS prefix,
  count(*)                                   AS shapes,
  sum(calls)                                 AS calls,
  round(sum(total_exec_time)::numeric/1000, 1) AS total_s
FROM pg_stat_statements
GROUP BY 1
ORDER BY total_s DESC
LIMIT 25;
```

High `shapes` + high `total_s` = IN-list fragmentation; that family is invisible in your
console's per-query view.

### D — live wait profile (run 3–4× over ~30s)

```sql
SELECT state, wait_event_type, wait_event, count(*)
FROM pg_stat_activity
WHERE backend_type = 'client backend'
GROUP BY 1,2,3 ORDER BY count(*) DESC;
```

`active` + NULL wait_event = on CPU. Many of those on an N-vCPU box = CPU-bound queries
(not IO or locks).

### E — maintenance and materialized views in flight

```sql
SELECT pid, wait_event_type, wait_event, now()-query_start AS dur, left(query,80) AS q
FROM pg_stat_activity
WHERE pid <> pg_backend_pid()
  AND (query ILIKE 'autovacuum:%' OR query ILIKE '%VACUUM%' OR query ILIKE '%ANALYZE%'
       OR query ILIKE '%MATERIALIZED VIEW%');
```

The `MATERIALIZED VIEW` match exists because of the utility-statement blind spot above —
this is the only place a runaway refresh shows up.

### F — dead-tuple / vacuum pressure

```sql
SELECT relname, n_live_tup, n_dead_tup,
       round(100*n_dead_tup::numeric/nullif(n_live_tup,0),1) AS dead_pct,
       last_autovacuum, autovacuum_count
FROM pg_stat_user_tables
ORDER BY n_dead_tup DESC LIMIT 15;
```

An outlier `autovacuum_count` on one table = write churn. The classic Rails cause is a sync
job rewriting rows to the same values (no-op writes still create dead tuples).

### G — live sampler (run 4–5×, ~15s apart)

```sql
SELECT now() - query_start AS dur, wait_event_type, wait_event,
       left(regexp_replace(query, '\s+', ' ', 'g'), 130) AS q
FROM pg_stat_activity
WHERE state = 'active' AND pid <> pg_backend_pid()
ORDER BY dur DESC;
```

Whatever keeps reappearing is what's on CPU *right now*. Ignore your replica's
`START_REPLICATION` row. Remember: NULL wait columns = working; `Lock` = queued victim.

### H — snapshot diff (gold standard for "what burns CPU today")

Same session/tab, the temp table must survive between steps:

```sql
-- Step 1: run now
CREATE TEMP TABLE pss_snap AS
SELECT userid, dbid, queryid, calls, total_exec_time
FROM pg_stat_statements;
```

Wait ~10 minutes (leave the tab open), then:

```sql
-- Step 2: exec-seconds consumed in the window, per query
SELECT round((p.total_exec_time - COALESCE(s.total_exec_time, 0))::numeric / 1000, 1) AS exec_s_10min,
       p.calls - COALESCE(s.calls, 0) AS calls_10min,
       left(regexp_replace(p.query, '\s+', ' ', 'g'), 120) AS q
FROM pg_stat_statements p
LEFT JOIN pss_snap s USING (userid, dbid, queryid)
WHERE p.total_exec_time - COALESCE(s.total_exec_time, 0) > 1000
ORDER BY 1 DESC
LIMIT 30;
```

Sanity check: 10 min × N saturated cores ≈ N×600 exec-seconds total. If the top-30 sums to
~80–90% of that, the list explains the load. Anything new-today shows here even if invisible
in the cumulative totals. This diff is also independent of when stats were last reset.

### I — targeted drill-down (template)

```sql
SELECT calls, round(mean_exec_time::numeric,1) AS mean_ms,
       round(total_exec_time::numeric/1000,1) AS total_s,
       left(regexp_replace(query,'\s+',' ','g'),120) AS q
FROM pg_stat_statements
WHERE query LIKE '%<table_or_keyword>%'
ORDER BY total_exec_time DESC LIMIT 10;
```

## Automate the capture (optional but worth it)

Wire your cloud provider's "high DB CPU" alert to a webhook endpoint in your app that
enqueues a job running queries A–G read-only, writes them to one text file, uploads it to
object storage, and posts the link to Slack. Whoever is on call downloads the file and
pastes it plus this playbook into an LLM. Two bonuses: the dump is timestamped evidence from
*during* the incident, and **two dumps N minutes apart are a free query-H** — subtract the
`total_s` columns to get exec-seconds burned per family in the window, no temp table needed.
Guard the endpoint with an access key; keep every query read-only.

## Incident-time attribution without APM

1. **Two dumps = a delta.** As above. Families with huge chronic totals but ~0 Δ are
   historical — fixes holding, not today's problem. Don't be fooled by a scary lifetime
   `mean_ms`.
2. **A request-log table = your poor-man's APM.** If you don't have one, build it: one row
   per request with controller/action, db_duration, query counts, IP, user agent, referer,
   indexed on time. It answers "which endpoint is burning the DB *right now*" and
   "bot or organic?" (dozens of distinct residential IPs ≈ organic; one UA walking your
   sitemap at dawn ≈ crawler). Query it on the replica so you don't load the pegged primary.
3. **Web vs background jobs.** `application_name` distinguishes your web server from your
   job workers:

```sql
SELECT application_name,
       count(*) FILTER (WHERE state='active' AND wait_event IS NULL) AS on_cpu
FROM pg_stat_activity WHERE backend_type='client backend'
GROUP BY 1 ORDER BY on_cpu DESC NULLS LAST;
```

4. **CPU spikes at a fixed minute past the hour = cron.** Find the crontab, note the minute
   it fires and the queue it lands on, and remember your graph's sampling grid can shift the
   apparent spike a few minutes later. The suspect list for an every-hour spike is closed:
   only jobs scheduled every hour can be on it.

## Interpretation heuristics

- **Fingerprint birth-dating:** `calls ÷ expected-rate` estimates when a query shape first
  appeared. High total_s with few calls relative to the stats window = recent regression →
  check `git log` around the inferred birth date.
- **rows/call ratio:** thousands of rows per call = a pluck/materialization that belongs in
  SQL (`MIN/MAX`, `COUNT FILTER`, `width_bucket`) or a cache.
- **0 rows over millions of calls = a guard-clause bug.** The recurring Rails pattern: bot
  traffic yields a nil user/visitor/session, and a `find_by(visitor: nil, ...)` runs forever
  matching nothing. Guard before querying.
- **Mean creep:** if a known query's mean rises across audits without a plan change, that's
  box saturation stretching everything — a victim, not a culprit. Attribution rule: a 9×
  mean rise with a 20× call-rate rise is a new traffic source; a 9× mean rise with flat
  calls is contention.
- **`t0_r0`/`t1_r0` column aliases** in a fingerprint = Rails `eager_load` /
  `includes`+`references`. Check the call sites for `group_by`, `.sample`, `.drop`, `[n]`
  on relations — each forces full materialization of the join.
- **Query → code mapping sequence:** grep distinctive SQL fragments, then scopes; check the
  schema dump for indexes (`grep 'ON public.<table>'`); fan out one investigation per query
  family, each returning file:line + mechanism + fix.
- **Never trust a dev schema dump for extension types.** If your dev DBs are built by
  restoring a prod dump, extension-provided types (e.g. pgvector's `vector`) can degrade to
  TEXT and their indexes silently vanish — and a schema file regenerated from that DB lies
  to you. Verify column types and indexes against the production catalog
  (`pg_attribute`/`pg_index`), never the checked-in structure file. Same for storage
  parameters (autovacuum flags, fillfactor).

## Recurring root-cause patterns (what we actually keep finding)

Every one of these came out of a real audit; check your codebase for each:

- **Cache keys derived from `relation.cache_key`** (a hash of the full SQL with binds
  inlined): any per-user/per-filter value in the relation fragments the key space → ~0% hit
  rate → the cache exists but caches nothing, and the DB eats every render.
- **Aggressively short cache-store timeouts** (e.g. Redis `read_timeout: 0.2`): latency
  spikes count as misses, so cache degradation becomes a DB recompute stampede — a feedback
  loop that turns a wobble into an incident.
- **No-op sync writes:** integration jobs writing `synced_at`/status columns even when
  nothing changed. Millions of dead tuples, autovacuum churn, WAL volume — for zero
  information. Skip-if-unchanged guards are one line.
- **`counter_cache` with an index on the counter column itself:** every increment becomes a
  non-HOT update (new index tuples + heap copy), and concurrent increments serialize on row
  locks. Usually an `EXISTS` probe replaces the counter entirely.
- **`after_touch` recalculation storms:** a parent recalculating aggregates by loading all
  children on every touch, amplified by batch jobs touching thousands of parents. Replace
  with one set-based UPDATE and `no_touching` around bulk paths.
- **Materialized view refreshes with no guard rails:** refresh lists living in database
  tables (invisible to code review), refreshed hourly with no `statement_timeout`, no
  overlap guard, and non-`CONCURRENTLY` (ACCESS EXCLUSIVE lock — the next run queues behind
  a stuck one forever). Give every refresh a per-object advisory lock (skip, don't queue),
  a generous timeout, and version the view definitions in git. And check the refresh *order*
  against the dependency chain — pipelines refreshed most-derived-first serve data that's
  hours stale by design.
- **Catch-all routes running expensive lookups before 404ing:** a wildcard route segment
  (`get ":slug"`) that derives an expensive "is this valid" set on every request pays full
  price for every crawler probe and dead link. Do the cheap unique-index lookup first;
  compute the expensive validation only when the record exists.
- **Unindexed lookups inside cron loops:** a scheduled job iterating an external dataset
  (spreadsheet, API export) doing one `find_by` per row against an unindexed column. It's
  invisible at low volume and becomes a nightly CPU plateau as the dataset grows. Batch-load
  with one `where(col: ids)` + hash lookup — and mind case-insensitive column types
  (citext): a SQL match is case-insensitive, a Ruby hash key is not.
- **Bot traffic amplifying all of the above.** Check your request logs before blaming code:
  sanctioned crawlers (search engines, AI bots you allowlisted) walking sitemaps and tag
  pages at dawn produce load spikes that vanish during human peak hours. Edge-block or
  challenge what you don't want; cache or cheapen what you do.
- **The biggest systemic lever is usually replica routing.** If your app has a same-sized
  read replica idling at 15% while the primary serves 100% of reads, Rails' multi-DB
  `connected_to(role: :reading)` around stateless public pages is worth more than any single
  query fix.

## Verifying a fix without breaking production

- Restore a recent prod dump locally. For each fix, reconstruct the OLD expression from
  `git show <baseline-sha>:<file>` and compare against the NEW code on real data — compare
  **ordered id arrays**, not booleans ("returns something" hides reordering bugs).
- Dev `Rails.cache` as a NullStore is a feature here: every `fetch` block executes, so the
  comparison is cache-free.
- Any DB write during verification goes inside
  `transaction { ...; raise ActiveRecord::Rollback }`. Never run job workers against a
  prod-shaped DB — integration jobs will make real HTTP calls.
- Finish with a server-level HTML diff: run the old and new code against the same local
  server and data, curl the affected pages, normalize per-request noise (csrf token, nonces,
  profiler ids), and diff. Byte-identical output is the strongest "same results" proof
  you can get without deploying.
- Watch for the classic behavior-drift traps: eager_load dedup vs array indexing, ORDER BY
  tie groups (plan-dependent), `LIMIT 1` without ORDER BY on duplicated keys (arbitrary row
  → make it deterministic with `.order(:id)`), enum String-vs-Symbol comparisons, and
  `.presence`/`group_by`/`drop`/`sample` forcing full loads.
- **Merged ≠ deployed ≠ applied.** A merged migration isn't live until deployed; a
  DB-side change (index, view definition) isn't live until someone runs it. Verify with the
  catalog (`pg_index.indisvalid`, `pg_matviews.definition`), not with git.

## Ops guardrails this method assumes

- `pg_stat_statements` installed and preloaded; reset it after a major traffic change (e.g.
  blocking a heavy crawler) so the window describes the workload you actually have — archive
  the final B/C first, the cumulative totals are gone forever otherwise.
- Statement timeouts on batch/cron connections. One runaway refresh or analytics query
  should die and alert, not camp on a core for 12 hours.
- Every scheduled job's DB work bounded: batch lookups, skip-if-unchanged writes,
  advisory-lock overlap guards.
- Alert → automated diagnostics dump (above), so every incident leaves evidence even if
  nobody was watching.