Query Profiling

Reviewed & published by Brayan K

By the end of this lesson you'll be able to find the slow query that's actually hurting you, read its execution plan, fix it with an index or rewrite, and verify the win — using the right tool for PostgreSQL, MySQL, or SQL Server. This is how senior engineers stop guessing and start measuring.

Part of the free SQL course at LearnCodingFast — hands-on lessons with examples you run in your browser, plus practice exercises and a quick quiz.

What You'll Learn

• Read EXPLAIN (ANALYZE, BUFFERS) output line by line
• Spot the costliest node and what it's telling you
• Tell estimated-vs-actual row gaps from I/O problems
• Find the top offender with pg_stat_statements & the slow log
• Use MySQL Performance Schema and SQL Server Query Store
• Follow a find → read → fix → verify tuning loop

The Profiling Mindset

"Profiling" means measuring where a query spends its time so you fix the real bottleneck instead of a guess. The cardinal rule: measure first, optimise second. Every engine gives you two kinds of tool — an aggregator that ranks all your queries by cost, and a plan reader that dissects one query.

A doctor doesn't operate on a hunch. First a chart of all patients flags who is sickest (that's pg_stat_statements / the slow log / Query Store), then a scan shows what's wrong inside that one patient (that's EXPLAIN ANALYZE / the execution plan). You treat, then re-scan to confirm. Same four steps, every time.

Those four steps are the spine of this whole lesson:

• Find the slow query — rank by total time, not the single slowest run.
• Read its plan — find the costliest node and why it's costly.
• Fix it — add or fix an index, refresh statistics, or rewrite the query.
• Verify — re-run the plan and confirm the numbers actually fell.

1. Find — rank queries by total time

The instinct is to hunt for the query with the worst single run. That's a trap. The query that hurts is the one whose cumulative time is highest: calls × average. pg_stat_statements records exactly that, grouping queries by shape (the literal values are stripped out), so thousands of executions roll up into one rankable row.

-- STEP 1 — FIND the slow query (PostgreSQL).
-- Don't guess. pg_stat_statements records every query the server has run,
-- aggregated by "shape" (literals stripped out), so 50,000 calls of the
-- same SELECT collapse into one row you can rank.

SELECT
    LEFT(query, 60)                       AS query_preview,
    calls,                                -- how many times it ran
    ROUND(total_exec_time::numeric)       AS total_ms,   -- 👈 rank by THIS
    ROUND(mean_exec_time::numeric, 2)     AS avg_ms,
    rows                                  AS total_rows
FROM pg_stat_statements
ORDER BY total_exec_time DESC             -- biggest CUMULATIVE cost first
LIMIT 5;

-- Why total_exec_time and not max? A 40 ms query run 100,000×/day
-- (4,000,000 ms) hurts far more than a 9-second report run twice
-- (18,000 ms). Optimise the line that dominates the total.

2. Read — EXPLAIN (ANALYZE, BUFFERS)

Once you know which query, ask the engine how it runs it. Plain EXPLAIN shows the planner's guess. EXPLAIN ANALYZE actually executes the query and reports the real timings and row counts, and BUFFERS adds the I/O story: which pages came from memory versus disk.

-- STEP 2 — READ its plan with EXPLAIN (ANALYZE, BUFFERS).
-- ANALYZE actually RUNS the query and reports real timings + row counts.
-- BUFFERS shows the I/O: pages served from cache vs read from disk.

EXPLAIN (ANALYZE, BUFFERS)
SELECT c.name, SUM(o.total) AS spent
FROM customers c
JOIN orders o ON o.customer_id = c.id
WHERE o.order_date >= '2024-01-01'
GROUP BY c.name
ORDER BY spent DESC
LIMIT 20;

-- ⚠️ EXPLAIN ANALYZE executes the statement. On an UPDATE/DELETE/INSERT,
--    wrap it in a transaction you ROLLBACK so it doesn't change data:
--    BEGIN; EXPLAIN ANALYZE UPDATE ...; ROLLBACK;

A plan is a tree of nodes, read inside-out: the deepest, most-indented node runs first and feeds its parent. Here's realistic output for that customers/orders query before any tuning. Read it slowly — every number is a clue:

Limit  (cost=21450..21450 rows=20) (actual time=812.4..812.5 rows=20 loops=1)
  ->  Sort  (actual time=812.4..812.4 rows=20 loops=1)
        Sort Key: (sum(o.total)) DESC
        Sort Method: quicksort  Memory: 41kB
        ->  HashAggregate  (actual time=805.1..809.9 rows=4821 loops=1)
              Group Key: c.name
              ->  Hash Join  (actual time=120.3..690.4 rows=486110 loops=1)
                    Hash Cond: (o.customer_id = c.id)
                    ->  Seq Scan on orders o
                          (cost=0.00..18234 rows=512) (actual rows=486110 loops=1)
                          Filter: (order_date >= '2024-01-01')
                          Rows Removed by Filter: 13290
                          Buffers: shared hit=44 read=18102
                    ->  Hash  (actual rows=5000 loops=1)
                          ->  Seq Scan on customers c (actual rows=5000 loops=1)
Planning Time: 0.31 ms
Execution Time: 813.0 ms

Walk through what each line is screaming at you:

• Estimated vs actual rows. The Seq Scan on orders says rows=512 (the planner's guess) but actual rows=486110. A ~1000× mismatch means the planner is flying blind — its statistics are stale. It chose a sequential scan because it thought only 512 rows matched; in reality almost half a million did.
• The costliest node. Subtract a node's start time from its end time. The Seq Scan/Hash Join branch runs from ~120 ms to ~690 ms — roughly 570 ms of the 813 ms total. That sequential scan over orders is the bottleneck; the Sort and Limit are cheap by comparison.
• Buffers (I/O). shared hit=44 means 44 pages were already in cache; read=18102 means 18,102 pages were pulled from disk. Disk reads are orders of magnitude slower than cache hits — a sea of read is a flashing sign that the query is scanning data it shouldn't have to touch.
• Wasted work. Rows Removed by Filter: 13290 plus the huge scan means the engine is reading rows only to throw them away. An index on the filtered column would let it skip straight to the matches.

For any plan, ask: (1) Is any actual rows wildly different from its estimate? → stale stats, run ANALYZE. (2) Is there a big Seq Scan with high shared read on a table you filter or join? → it wants an index. Those two questions catch the majority of slow queries.

Your Turn: diagnose the plan

No SQL to write here — read the EXPLAIN ANALYZE output in the comments and fill the blanks with the slow node and why it's slow. The answer key is in the comments so you can self-check.

-- 🎯 YOUR TURN — you don't write SQL here, you DIAGNOSE.
-- Read this EXPLAIN (ANALYZE, BUFFERS) output and fill the blanks in the
-- comments with the node name and the reason it is slow.

--  Limit  (actual time=812.4..812.5 rows=20 loops=1)
--    ->  Sort  (actual time=812.4..812.4 rows=20 loops=1)
--          Sort Key: (sum(o.total)) DESC
--          Sort Method: quicksort  Memory: 41kB
--          ->  HashAggregate  (actual time=805.1..809.9 rows=4821 loops=1)
--                ->  Seq Scan on orders o
--                      (cost=0.00..18234  rows=512  (actual rows=486110))
--                      Filter: (order_date >= '2024-01-01')
--                      Rows Removed by Filter: 13290
--                      Buffers: shared read=18102 hit=44

-- 👉 The slow node is a ___ on the orders table.
-- 👉 It is slow because the planner estimated rows=512 but ACTUAL rows
--    were ___ — a huge mismatch caused by ___ statistics.
-- 👉 "Buffers: shared read=18102" means 18,102 pages came from ___,
--    not cache, so this also ran on a cold/under-indexed table.

-- ✅ Expected: slow node = Seq Scan; actual rows = 486110 (not 512);
--    mismatch = stale (out-of-date) statistics → run ANALYZE orders;
--    shared read = disk. Fix: ANALYZE + an index on (order_date).

3. Fix — refresh stats, then index

The plan gave you two leads: stale statistics and a missing index. Apply them cheapest-first. ANALYZE resamples the table so the planner's estimates match reality — that alone sometimes flips a bad plan into a good one. If a scan is still happening, an index lets the engine jump straight to matching rows instead of reading the whole table.

-- STEP 3 — FIX. The plan blamed a Seq Scan on "orders" with a stale
-- estimate. Two fixes, applied in order:

-- 3a) Refresh the planner's statistics (cheap; do this first):
ANALYZE orders;

-- 3b) Give the filter an index so the engine stops scanning every row.
--     CONCURRENTLY builds it WITHOUT locking writes on a live table:
CREATE INDEX CONCURRENTLY idx_orders_custdate
ON orders (customer_id, order_date);

-- A composite index ordered (customer_id, order_date) serves the JOIN key
-- AND the date filter in one structure. Leading column first — an index on
-- (order_date, customer_id) would NOT help a lookup by customer_id alone.

4. Verify — prove it got faster

A fix you didn't measure is a guess you got lucky with. Re-run the identical EXPLAIN (ANALYZE, BUFFERS) and check three things: the Seq Scan became an Index Scan, shared read dropped sharply, and actual rows now lines up with the estimate. Then reset pg_stat_statements so the next day's numbers measure the new world, not the old.

-- STEP 4 — VERIFY. Re-run the SAME EXPLAIN (ANALYZE, BUFFERS) and confirm
-- the node changed and the numbers fell. Then reset the counters so you can
-- measure the win in production over the next day.

EXPLAIN (ANALYZE, BUFFERS)
SELECT c.name, SUM(o.total) AS spent
FROM customers c
JOIN orders o ON o.customer_id = c.id
WHERE o.order_date >= '2024-01-01'
GROUP BY c.name
ORDER BY spent DESC
LIMIT 20;

-- Expect: "Seq Scan on orders" → "Index Scan using idx_orders_custdate",
-- shared read (disk pages) way down, actual time roughly back to estimate.

SELECT pg_stat_statements_reset();   -- start a clean measurement window

Here's the same query's plan after ANALYZE and the index — note the node, the buffers, and the time:

Limit  (actual time=8.9..9.0 rows=20 loops=1)
  ->  Sort  (actual time=8.9..8.9 rows=20 loops=1)
        ->  HashAggregate  (actual time=2.1..7.4 rows=4821 loops=1)
              ->  Nested Loop  (actual time=0.05..1.9 rows=4821 loops=1)
                    ->  Index Scan using idx_orders_custdate on orders o
                          (cost=0.42..210 rows=4800) (actual rows=4821 loops=1)
                          Index Cond: (order_date >= '2024-01-01')
                          Buffers: shared hit=812 read=3
Execution Time: 9.2 ms

From 813 ms to 9 ms: the Seq Scan is now an Index Scan, read collapsed from 18,102 pages to 3, and the estimate (4,800) finally matches actual (4,821). That's a verified win — not a hopeful one.

Your Turn: find the top offender

Two blanks. Complete the pg_stat_statements query so it returns the single query pattern with the highest total execution time.

-- 🎯 YOUR TURN — write the query that finds the WORST offender.
-- Goal: from pg_stat_statements, return the single query pattern with the
-- largest CUMULATIVE execution time (the one worth fixing first).

SELECT LEFT(query, 60) AS query_preview, calls, total_exec_time
FROM pg_stat_statements
ORDER BY ___ DESC          -- 👉 which column ranks by TOTAL time, not average?
LIMIT ___;                 -- 👉 we only want the single top offender

-- ✅ Expected: ORDER BY total_exec_time DESC LIMIT 1;
--    Returns one row — the query whose calls × avg time dominates the server.

5. The same loop in MySQL

MySQL changes the tools, not the method. To find, use the slow query log (writes any query over long_query_time to a file) or query the Performance Schema, which aggregates by digest just like pg_stat_statements. To read, MySQL 8.0+ has its own EXPLAIN ANALYZE; in plain EXPLAIN the type column is the headline — ALL means a full table scan, while ref/eq_ref/const mean it's using an index.

-- MySQL: same workflow, different tools.

-- FIND — the slow query log captures anything over long_query_time.
-- Set in my.cnf (or at runtime with SET GLOBAL ...):
--   slow_query_log      = ON
--   slow_query_log_file = /var/log/mysql/slow.log
--   long_query_time     = 1     -- seconds; log queries slower than this

-- FIND (live, no log file) — Performance Schema aggregates by digest,
-- exactly like pg_stat_statements:
SELECT
    LEFT(DIGEST_TEXT, 60)        AS query_preview,
    COUNT_STAR                   AS calls,
    SUM_TIMER_WAIT / 1e9         AS total_ms,   -- picoseconds → ms
    SUM_ROWS_EXAMINED            AS rows_examined
FROM performance_schema.events_statements_summary_by_digest
ORDER BY SUM_TIMER_WAIT DESC
LIMIT 5;

-- READ — MySQL 8.0+ has EXPLAIN ANALYZE (also runs the query):
--   EXPLAIN ANALYZE SELECT * FROM orders WHERE total > 500;
-- In plain EXPLAIN, the column that matters most is "type":
--   ALL  = full table scan (bad)      ref  = index lookup (good)
--   const/eq_ref = unique lookup (best)
-- And "Extra": "Using filesort" / "Using temporary" both flag slow work.

6. The same loop in SQL Server

SQL Server's Query Store is a built-in flight recorder: switch it on once and it keeps every query's plans and runtime stats over time, which makes it brilliant for spotting a query that regressed after a deploy. To find, rank sys.query_store_runtime_stats by total duration. To read, capture the actual execution plan (SET STATISTICS XML ON, or "Include Actual Execution Plan" in SSMS) and look at the operator with the highest cost percentage — a thick connecting arrow means a lot of rows are flowing, often the sign of a missing index.

-- SQL Server: Query Store is the built-in flight recorder.

-- Turn it on once per database; it then captures plans + runtime stats:
--   ALTER DATABASE mydb SET QUERY_STORE = ON;

-- FIND the top offenders by total duration (avg × executions):
SELECT TOP 5
    qt.query_sql_text,
    rs.count_executions,
    rs.avg_duration / 1000.0                              AS avg_ms,
    (rs.avg_duration * rs.count_executions) / 1000.0      AS total_ms,
    rs.avg_logical_io_reads                               AS avg_page_reads
FROM sys.query_store_runtime_stats rs
JOIN sys.query_store_plan         qp ON rs.plan_id = qp.plan_id
JOIN sys.query_store_query        qq ON qp.query_id = qq.query_id
JOIN sys.query_store_query_text   qt ON qq.query_text_id = qt.query_text_id
ORDER BY total_ms DESC;

-- READ — capture the actual execution plan to inspect the costliest operator:
--   SET STATISTICS XML ON;
--   SELECT * FROM orders WHERE customer_id = 42;
--   SET STATISTICS XML OFF;
-- In SSMS, "Include Actual Execution Plan" draws it; the operator with the
-- highest % cost is your starting point — and a thick arrow means many rows.

Common Mistakes (and the fix)

• Optimising without measuring: adding indexes "that feel right" before reading a plan. Every index slows down writes and uses disk. Profile first — let EXPLAIN ANALYZE tell you what the query actually does.
• Estimated rows ≠ actual rows: a large gap is almost always stale statistics, not a bug in your query. Run ANALYZE table; (PostgreSQL) or ANALYZE TABLE table; (MySQL) before you reach for anything fancier.
• Ignoring buffers / I/O: a query can look fast in CPU time yet hammer the disk. High shared read (or avg_logical_io_reads) means you're reading pages you shouldn't — usually a missing index, not slow hardware.
• Profiling a cold cache: the first run reads everything from disk and looks terrible; the second run is all cache hits and looks great. Run a query 2–3 times and read the warm numbers, or you'll "fix" a problem that was just cold storage.
• Forgetting EXPLAIN ANALYZE executes: on an UPDATE/DELETE it really changes data. Wrap it: BEGIN; EXPLAIN ANALYZE DELETE ...; ROLLBACK;

📘 Quick Reference

Read EXPLAIN plans inside-out: the deepest node runs first. Watch for Seq Scan (PG) / type: ALL (MySQL) on big tables, estimate-vs-actual gaps, and high disk reads.

Frequently Asked Questions

Q: What's the difference between EXPLAIN and EXPLAIN ANALYZE?

Plain EXPLAIN shows the planner's predicted plan and costs without running anything. EXPLAIN ANALYZE actually executes the query and reports real timings and row counts — which is the only way to catch estimate-vs-actual mismatches. Because it runs the statement, be careful with writes.

Q: My query is fast in EXPLAIN ANALYZE but slow in production. Why?

Usually caching. Your test run warmed the cache, so everything was a buffer hit; production hits cold pages, or a different parameter value matches far more rows. Check BUFFERS for high shared read, and test with realistic parameter values, not a hand-picked easy one.

Q: Should I optimise the slowest query or the most frequent one?

Rank by total time = calls × average. A fast query run millions of times usually beats a slow query run rarely. That's exactly why pg_stat_statements, Performance Schema, and Query Store all let you sort by cumulative cost.

Q: pg_stat_statements isn't there — where is it?

It's an extension that must be preloaded: add pg_stat_statements to shared_preload_libraries in postgresql.conf, restart, then run CREATE EXTENSION pg_stat_statements;. Until then the view simply doesn't exist.

Mini-Challenge: profile & fix a timeout

Put the whole loop together — diagnose the root cause, write the command to confirm it, and propose the index. The expected fix is in the comments so you can check your reasoning.

-- 🎯 MINI-CHALLENGE — profile and propose a fix.
-- Scenario: an API endpoint that lists a user's recent pending orders is
-- timing out. The query is:
--
--   SELECT * FROM orders
--   WHERE customer_id = 42 AND status = 'pending'
--   ORDER BY order_date DESC
--   LIMIT 25;
--
-- pg_stat_statements shows it runs ~30,000×/day at ~280 ms each, and its
-- EXPLAIN (ANALYZE, BUFFERS) shows: "Seq Scan on orders", actual rows close
-- to the planner's estimate (stats are fine), high "shared read".
--
-- 1. Decide the root cause (it is NOT stale stats — estimate ≈ actual).
-- 2. Write the EXPLAIN (ANALYZE, BUFFERS) line you'd run to confirm it.
-- 3. Write the CREATE INDEX that fixes it. Think about which columns the
--    WHERE filters on AND which column the ORDER BY needs.
--
-- ✅ Expected shape of the fix:
--    CREATE INDEX CONCURRENTLY idx_orders_cust_status_date
--    ON orders (customer_id, status, order_date DESC);
--    → Seq Scan becomes Index Scan; the engine reads only matching rows
--      already in date order, so the Sort and most disk reads disappear.

-- your answer here

🎉 Lesson Complete

• ✅ The loop is always the same: find → read → fix → verify
• ✅ Find by total time — pg_stat_statements, the slow log, or Query Store
• ✅ Read with EXPLAIN (ANALYZE, BUFFERS); watch estimate-vs-actual rows, the costliest node, and disk reads
• ✅ A big estimate/actual gap means stale stats → ANALYZE; a big Seq Scan with high reads wants an index
• ✅ Always verify on a warm cache, then reset your counters
• ✅ Next: Buffer Pool & Memory — why those cache hits and disk reads happen in the first place

Practice quiz

Continue this course

• Previous: Analytical SQL for BI: Cubes, Rollups, Grouping Sets
• Next: Understanding Buffer Pool, Caches, Memory & I/O Optimization — Tune the buffer pool, shared buffers, and memory for faster query I/O
• Quick reference: SQL cheat sheet
• From the blog: Database Indexing Strategies