Anatomy of a 4-Second Query: How an AI DBA Finds the Root Cause in 30 Seconds

TL;DR

• A slow query isn't always a missing index. It's often a stats, memory, or data distribution problem the planner can't see.
• EXPLAIN ANALYZE is a starting point, not the whole story. You must correlate its output with pg_stat_statements, buffer cache hits, and schema history to find the real bottleneck.
• Manual root-cause analysis is a slow guessing game of cross-referencing system views. AI-driven analysis automates this correlation to find and fix the actual problem, not just the most obvious symptom.

---

A PagerDuty alert fires. A critical API endpoint, backed by a single Postgres query, has breached its latency SLO. What was sub-500ms is now hovering around 4,000ms. The application team is blocked, and your Slack channels are lighting up.

Your first move, your muscle memory, is to grab the query and run EXPLAIN ANALYZE. You see it immediately: a Sequential Scan on events, a two-billion-row table. The cost is astronomical. The planner is clearly making a bad choice.

Case closed, right? Add an index, deploy, and get back to your coffee.

So you run CREATE INDEX CONCURRENTLY ON events (customer_id, event_type) WHERE created_at > NOW() - INTERVAL '90 days';.

You ship it. The new plan uses a Bitmap Heap Scan. Victory. Except... the query is now 3,200ms. It's better, but it's not fixed. The PagerDuty alert is still active. What did you miss?

The Index That Barely Helped

This is the most common trap in database performance tuning. You treated the symptom—the Seq Scan—without diagnosing the underlying disease. The original plan wasn't just 'wrong'; it was the planner's best guess based on faulty information. Your new index gave it another option, but you didn't fix the core problem.

Let's look at a plausible EXPLAIN output for the query after you added the index.

-- The problematic query
SELECT
    c.name,
    c.customer_id,
    COUNT(e.id) AS event_count
FROM
    customers c
JOIN
    events e ON c.id = e.customer_id
WHERE
    c.account_type = 'enterprise'
    AND e.event_type = 'login_failure'
    AND e.created_at > NOW() - INTERVAL '90 days'
GROUP BY 1, 2
ORDER BY 3 DESC
LIMIT 100;

And the plan after your 'fix':

Limit  (cost=74501.12..74501.37 rows=100 width=45) (actual time=3150.123..3150.158 rows=100 loops=1)
  Buffers: shared hit=15023 read=89432, temp read=54321 written=54321
  ->  Sort  (cost=74501.12..74501.78 rows=265 width=45) (actual time=3150.120..3150.132 rows=100 loops=1)
        Sort Key: (count(e.id)) DESC
        Sort Method: external merge  Disk: 424MB
        Buffers: shared hit=15023 read=89432, temp read=54321 written=54321
        ->  HashAggregate  (cost=74495.34..74497.99 rows=265 width=45) (actual time=2980.450..3010.789 rows=450123 loops=1)
              Group Key: c.name, c.customer_id
              Batches: 5  Memory Usage: 4096kB  Disk Usage: 424MB
              ->  Hash Join  (cost=2345.67..73250.12 rows=498088 width=37) (actual time=89.123..1450.987 rows=2345678 loops=1)
                    Hash Cond: (e.customer_id = c.id)
                    ->  Bitmap Heap Scan on events e  (cost=2300.11..68001.44 rows=498088 width=24) (actual time=45.678..850.321 rows=2345678 loops=1)
                          Recheck Cond: (event_type = 'login_failure' AND created_at > NOW() - INTERVAL '90 days')
                          Rows Removed by Index Recheck: 1200000
                          Heap Blocks: exact=75321
                          Buffers: shared hit=101 read=45321
                          ->  Bitmap Index Scan on events_customer_id_event_type_created_at_idx ...
                    ->  Hash  (cost=44.55..44.55 rows=8 width=16) (actual time=0.123..0.125 rows=15 loops=1)
                          ->  Seq Scan on customers c  (cost=0.00..44.55 rows=8 width=16) (actual time=0.010..0.080 rows=15 loops=1)
                                Filter: (account_type = 'enterprise')

The Real Root Causes You Missed

Your eyes went to the Bitmap Heap Scan and you thought your job was done. But look closer. A senior engineer, or a well-trained AI, sees three glaring problems that have nothing to do with the index itself.

1. Cardinality Misestimation (Stale Statistics)

Look at the Hash Join and the underlying Bitmap Heap Scan.

• Planner's estimate: rows=498088
• Actual execution: rows=2345678

The planner was off by nearly 5x. It thought this join would be moderately sized. In reality, it was huge. Why? Because the table statistics are stale. A recent data import, a backfill, or just a lagging autovacuum process meant the planner was working with an old map of your data's distribution. The cost of the Bitmap Heap Scan—which involves fetching the actual row from the heap for every entry found in the index—was catastrophically underestimated.

A human DBA would have to manually query pg_stat_user_tables to check last_analyze and last_autoanalyze timestamps. That's assuming they even think to look.

2. Memory Pressure (Disk Spills)

This is the smoking gun that explains why latency is still in the seconds, not milliseconds. Look at the Sort node:

Sort Method: external merge Disk: 424MB

This is a death sentence for query performance. Postgres tried to sort the 450,123 rows coming out of the aggregation, but it didn't have enough memory. The work_mem allocated for this operation was exhausted, forcing Postgres to write 424MB of temporary data to disk, sort it there, and read it back. This is an I/O storm completely invisible to most monitoring tools.

The HashAggregate confirms it: Disk Usage: 424MB. We're spilling to disk twice.

The planner chose this plan based on its faulty row estimate of just 265 rows for the final sort. It thought it would easily fit in memory. The 5x cardinality error cascaded upwards, destroying the plan's viability.

3. Inefficient Heap Fetches (I/O)

Look at the buffers for the Bitmap Heap Scan:

Buffers: shared hit=101 read=45321

We had almost zero blocks from the events table in the buffer cache. We had to go to disk for 45,321 8KB pages. Your index helped us locate which pages to fetch, but we still paid the full price of reading them from slow storage. When the planner's row estimates are this wrong, it might have been better off with the Seq Scan it originally chose, as that at least uses more efficient sequential I/O.

The Rows Removed by Index Recheck: 1200000 is also a sign of trouble, indicating the index wasn't as selective for the heap scan as we might have hoped, leading to wasted work.

What DeepSQL does about this

Your job isn't to guess CREATE INDEX and pray. It's to perform root cause analysis. A human does this by tediously stitching together clues from half a dozen pg_stat_* views, system settings, and EXPLAIN outputs. It's slow and error-prone.

DeepSQL automates this entire diagnostic process. It ingests the EXPLAIN (ANALYZE, BUFFERS) output and doesn't just see a Seq Scan. It parses the entire plan graph, comparing planner estimates to actuals at every node. When it sees a 5x cardinality misestimation, it automatically correlates it with the last_analyze timestamp on the events table and flags stale statistics as the primary root cause. When it sees external merge Disk, it identifies the disk spill and cross-references the required memory against the current work_mem setting. It then provides a specific, actionable recommendation: a targeted ANALYZE events, a session-level SET work_mem='512MB', or a query rewrite, complete with the predicted performance gain based on a cost model that understands these second-order effects.