SQL / INDEXES AND QUERY PERFORMANCE
Measuring before optimising: timing real queries
Produce a trustworthy baseline for a SQL query: repeat runs, separate client time from server execution time, and rank queries by total time, not worst case.
What you will learn
- Discard the first cold run and record the median of five warm runs as the baseline
- Separate server Execution Time from client round-trip and row-fetch time
- Rank work by total time (calls x mean), not by the single slowest statement
- Time the statement the app really sends, with a realistic parameter and no added LIMIT
Understanding Measuring before optimising: timing real queries
A query's duration is not one number, it is parse and plan time, execution inside the server, and the time spent shipping rows to the client, plus whatever else the machine happened to be doing. The first execution usually also pays to pull the table's pages off disk into the buffer cache, which is why an identical second run can be twice as fast with no change to schema or SQL. So treat one timing as a single sample from a noisy distribution: run the statement six times, throw away the first, and record the median of the rest.
The tool you pick decides what is inside the number. psql's \timing measures the whole round trip, including network latency and materialising every returned row on the client, so it is closest to what the application feels. EXPLAIN (ANALYZE, BUFFERS) reports Planning Time and Execution Time separately and tells you whether pages came from shared buffers (shared hit) or had to be fetched (shared read), which is how you tell a real improvement from a warm cache.
Measurement also decides what deserves your attention. A report that takes 900 ms twelve times a day costs the server eleven seconds; a 2.7 ms lookup called 180,000 times costs eight minutes, so that is where the CPU actually goes. pg_stat_statements (or events_statements_summary_by_digest in MySQL) totals time per statement shape, which is the ranking that picks your target, while mean time is what one user notices. Measure with realistic volume and parameters too: on a 500-row dev table every plan is fast, and a user_id matching 3 rows does not behave like one matching 30,000.
CREATE TABLE events (
id bigserial PRIMARY KEY,
user_id integer NOT NULL,
created_at timestamptz NOT NULL,
payload text NOT NULL
);
INSERT INTO events (user_id, created_at, payload)
SELECT (g % 5000) + 1,
timestamp '2024-01-01' + (g % 365) * interval '1 day',
repeat('x', 80)
FROM generate_series(1, 300000) AS g;
VACUUM ANALYZE events;
SET max_parallel_workers_per_gather = 0; -- parallel plans add run-to-run noise
\timing on
SELECT count(*) FROM events WHERE user_id = 42; -- run 1, cold cache
SELECT count(*) FROM events WHERE user_id = 42; -- run 2
SELECT count(*) FROM events WHERE user_id = 42; -- run 3A performance claim is only meaningful against a repeated, warm, whole-statement baseline that you recorded before changing anything.
Worked examples
Splitting the duration with EXPLAIN (ANALYZE, BUFFERS)
Shows how much of the measured time is planning, how much is execution, and whether the pages were already cached.
EXPLAIN (ANALYZE, BUFFERS)
SELECT count(*) FROM events WHERE user_id = 42;Example explained
Line 1Planning Time: 0.062 ms is counted apart from execution, so a 2 ms statement planned 200k times can have a planning cost worth measuring on its own.
Line 2Buffers: shared hit=5172 with no read= entry means every page was already in the buffer cache; the same query on a cold cache prints shared read=5172 and is far slower.
Line 3Rows Removed by Filter: 299940 is the work being paid for: 300,000 rows touched to return 60.
Line 4Execution Time: 29.481 ms excludes sending the result to psql, which is why the client reported roughly 31 ms.
Finding out which statement is worth optimising
Ranks statements by accumulated server time so you attack the query that consumes the most, not the one that feels slowest.
CREATE EXTENSION IF NOT EXISTS pg_stat_statements;
SELECT calls,
round(mean_exec_time::numeric, 2) AS mean_ms,
round(total_exec_time::numeric, 1) AS total_ms,
left(query, 42) AS query
FROM pg_stat_statements
ORDER BY total_exec_time DESC
LIMIT 3;Example explained
Line 1pg_stat_statements replaces literals with $1, so all 184,203 executions of the same shape collapse into one row and can be totalled.
Line 2The 910 ms report is the slowest per call yet accounts for about 2% of the time; the 2.71 ms lookup accounts for 97%.
Line 3ORDER BY total_exec_time DESC answers 'where does the server's time go', while ordering by mean_exec_time answers 'what does one user wait for'.
Line 4Counters accumulate since server start or the last pg_stat_statements_reset(), so compare deltas over a window rather than absolute totals.
A five-sample harness with no client in the way
Times the same statement five times inside the server so the numbers exclude network and row transfer.
DO $$
DECLARE
t0 timestamptz;
ms numeric;
i integer;
BEGIN
FOR i IN 1..5 LOOP
t0 := clock_timestamp();
PERFORM count(*) FROM events WHERE user_id = 42;
ms := round((extract(epoch FROM clock_timestamp() - t0) * 1000)::numeric, 2);
RAISE NOTICE 'run % : % ms', i, ms;
END LOOP;
END $$;Example explained
Line 1clock_timestamp() re-reads the wall clock on every call; now() is frozen for the whole transaction and would report 0 ms for each run.
Line 2PERFORM executes the query and throws the rows away, so nothing crosses the connection and the number is pure server execution.
Line 3Run 1 is higher because plpgsql plans the statement on first use and any remaining pages are still being cached, so the baseline is the median of runs 2-5, about 30.8 ms.
Line 4Since the plan is then cached, this harness cannot reveal a planning-time regression; read Planning Time from EXPLAIN for that.
Important notes
EXPLAIN ANALYZE reads the clock twice per row per node, so on plans that pass millions of rows its Execution Time can exceed a plain run; re-check with EXPLAIN (ANALYZE, TIMING OFF) before trusting the figure.
Parallel plans, autovacuum, and other sessions all add variance: fix what you can (as with max_parallel_workers_per_gather = 0 above) and measure on an otherwise idle instance.
Common mistakes
Timing one cold run before the change and one warm run after it, then reporting '10x faster': most of the gain was the buffer cache, and production sees nothing like it.
Benchmarking against a 500-row copy of the table, where a sequential scan genuinely is the cheapest plan, so the index looks pointless and the conclusion does not carry over to five million rows.
Adding LIMIT 20 or wrapping the query as SELECT count(*) FROM (...) t to keep the output readable: the plan can now stop early and the sort and transfer of the full result vanish, so you optimise a statement nobody runs.
Comparing psql's Time: against EXPLAIN's Execution Time and treating the gap as a bug, when it is round trip plus client-side row handling.
Try it yourself
Change, predict, then run
Create the events table with 300,000 generated rows in a Postgres fiddle and run the five-sample DO block, noting the first duration and the median of runs 2-5. Then add an index on user_id, run the same block again, and compare medians only, not first runs.
Open the SQL workspaceCheck your understanding
You time a query once at 620 ms, add an index, run it once more and get 45 ms. What is the weakest part of that evidence?
- The 620 ms run was the only cold-cache run, so part of the gain may be cache warming rather than the index
- 45 ms is impossible for an index lookup, so the second run must have come from a cached result set
- The index cannot be trusted until ANALYZE has refreshed the table statistics
- Client-side timing includes network latency, so comparing two client timings is never valid
Show answer
Both figures are single samples and only the first one paid to read the table from disk, so the comparison mixes the index effect with buffer cache warming; medians of five warm runs on each side, plus shared read versus shared hit from BUFFERS, separate the two. Option 3 is tempting because stale statistics really do cause bad plans, but CREATE INDEX already exposes the index to the planner and rebuilding statistics is not what makes this measurement weak; the sampling is.