Module 5: Query Profiling in Production
`auto_explain`: capturing plans in production
Capsule overview
pg_stat_statements (capsules 02 and 03) tells you which queries are a problem. But it doesn't tell you why. To understand the why you need the execution plan, and that's what EXPLAIN ANALYZE gives you. In module 2 you learned to run it manually: you connect with psql, prefix the query with EXPLAIN (ANALYZE, BUFFERS), read the result.
In production that flow doesn't work. You can't ask the user to reproduce the slow query so you can run it by hand. You can't launch EXPLAIN ANALYZE over an UPDATE or DELETE because it actually runs the query. And by the time you get around to investigating, conditions have already changed (different cached data, planner with different statistics, different load).
auto_explain solves this: it's an optional PostgreSQL module that automatically captures to the log the execution plan of any query that takes longer than a configured threshold. No manual intervention. No re-execution. The plan you see is the plan that actually ran at that moment, with that data, under those conditions.
This capsule teaches you:
- Enabling
auto_explainwith the correct configuration (threshold, format, options). - Deciding an appropriate threshold (
log_min_duration) that captures what matters without flooding the log. - Reading the captured plans in the PostgreSQL log.
- Combining
auto_explainwithpg_stat_statementsin an integrated workflow: identify the problematic queryid, pull the plan from the log, decide a fix. - Anticipating operational problems (overhead, log size, queries with sensitive literals).
By the end, you'll have auto_explain running against your local bookstore capturing the plans of slow queries that pg_stat_statements flags as priorities.
Mental model: a security camera over slow queries
Imagine a store with a security camera that activates only when an alarm goes off. The camera doesn't record all day (it would be terabytes of useless video) — it records only when the sensor detects suspicious movement. When you go to investigate a robbery, you have the video of the exact moment.
auto_explain works like that. It doesn't capture the plan of every query (it would be gigabytes of log and would kill performance). It captures only when a query exceeds the threshold you defined — for example, "record the plan of any query that takes longer than 500ms".
Query runs in 50ms → not captured
Query runs in 200ms → not captured
Query runs in 800ms → ALARM: capture plan to log
Query runs in 50ms → not captured
The "log" where it's recorded is the normal PostgreSQL log (postgresql.log or the configured destination). The plans end up there mixed with other messages, but clearly labeled with LOG: duration: Xms plan: so they're easily extractable.
Difference from pg_stat_statements:
| Aspect | pg_stat_statements | auto_explain |
|---|---|---|
| What it captures | Aggregate metrics per queryid | Complete execution plan |
| Granularity | One entry per query shape | One entry per execution that exceeded the threshold |
| Where it's stored | In-memory table (view) | PostgreSQL log (text/JSON) |
| Read cost | Trivial: SELECT FROM pg_stat_statements | You have to parse the log |
| What it's for | Identify problematic queries | Understand the why of the problem |
The two are complementary. pg_stat_statements tells you "this query is slow"; auto_explain tells you "because it's doing a Sequential Scan instead of an Index Scan".
Enabling auto_explain
auto_explain is also a contrib module, it's shipped with PostgreSQL for years. Unlike pg_stat_statements, it does not require CREATE EXTENSION — it's only loaded via shared_preload_libraries (or session_preload_libraries for advanced cases) and configured with parameters.
Recommended minimal configuration
Add these lines to your postgresql.conf (continuing with the setup from capsule 02):
# pg-config/postgresql.conf — extends the previous configuration
shared_preload_libraries = 'pg_stat_statements,auto_explain'
# auto_explain configuration
auto_explain.log_min_duration = '500ms' # capture queries that take > 500ms
auto_explain.log_analyze = on # include real timings (like ANALYZE)
auto_explain.log_buffers = on # include buffer info
auto_explain.log_verbose = off # more column info (optional, makes logs longer)
auto_explain.log_format = 'text' # 'text' | 'json' | 'xml' | 'yaml'
auto_explain.log_nested_statements = on # also capture queries inside functions
auto_explain.log_triggers = off # trigger time (off for simplicity)
Important: shared_preload_libraries is a comma-separated list. If you already had 'pg_stat_statements', now you put 'pg_stat_statements,auto_explain'. After the change you need a restart, just like in capsule 02.
Applying it with Docker
If you followed the setup from capsule 02:
# 1. Edit the postgresql.conf file with the new configuration
# (add the auto_explain.* lines and update shared_preload_libraries)
# 2. Restart the container
docker restart bookstore-pg
# 3. Verify that auto_explain loaded
docker logs bookstore-pg 2>&1 | grep -i auto_explain
# Expected: no error line; if nothing appears, it's loaded silently
Unlike pg_stat_statements, auto_explain doesn't generate a "registering background worker" message — it simply activates. The way to verify is to generate a slow query and see if the plan gets logged.
Applying it on native PostgreSQL
# 1. Edit postgresql.conf:
sudo vim /etc/postgresql/16/main/postgresql.conf
# (add the mentioned lines)
# 2. Restart:
sudo systemctl restart postgresql
Verify that it captures
Generate an intentionally slow query:
docker exec -it bookstore-pg psql -U bookstore -d bookstore -c \
"SELECT pg_sleep(1.5), 'test auto_explain' AS marker;"
Then check the container log:
docker logs bookstore-pg 2>&1 | grep -A 30 "auto_explain\|test auto_explain\|duration: 1"
Expected output (something similar):
LOG: duration: 1503.234 ms plan:
Query Text: SELECT pg_sleep(1.5), 'test auto_explain' AS marker;
Result (cost=0.00..0.02 rows=1 width=40) (actual time=1500.123..1500.124 rows=1 loops=1)
If you see that line, auto_explain is working. If not, check that the restart happened and that log_min_duration is at a value your query exceeds.
Choosing the right log_min_duration
This is the most important parameter of auto_explain. Setting it wrong can make your log useless or capture nothing.
Trade-offs
log_min_duration = 0 → captures EVERYTHING. Log explodes in minutes. NEVER in production.
log_min_duration = 100ms → captures a lot. Log grows fast. Useful in development.
log_min_duration = 500ms → reasonable balance. Recommended default for production.
log_min_duration = 1s → only the slowest. You miss 700ms queries that might matter.
log_min_duration = -1 → disables capture without disabling the module.
How to decide based on your context
For local development (bookstore on your machine):
Start with log_min_duration = '100ms'. You'll capture a lot, but your traffic volume is low (just you testing) so the log stays manageable. It helps you see almost any problematic query.
For staging with production-like data:
log_min_duration = '250ms' or '500ms'. You want to capture real problems without the log growing to gigabytes per hour.
For production:
Start conservative ('1000ms') and lower it gradually. The practical rule:
- Enable at 1s. Observe the rate of logs per hour over a day.
- If the log is manageable (<100MB/day generated by
auto_explain), lower it to 500ms. - Repeat. Going below 250ms in high-traffic production starts to be risky.
The right approach: use tools like pganalyze, pgbadger, or pg_log_to_metrics to process the logs without having to read them by hand.
Per-session override
auto_explain.log_min_duration can be overridden per session (not as a global GUC, but by changing the parameter temporarily):
-- Only in this session, capture everything:
LOAD 'auto_explain';
SET auto_explain.log_min_duration = 0;
SET auto_explain.log_analyze = on;
-- Your debugging query:
SELECT * FROM books WHERE author_id = 5;
-- You return to the default without affecting other sessions.
Useful for interactive debugging in production without changing the global config.
Reading a captured plan
Assume that pg_stat_statements flagged this query as a problem (hypothetical queryid):
SELECT b.id, b.title, count(r.id) AS review_count
FROM books b
LEFT JOIN reviews r ON r.book_id = b.id
WHERE b.author_id = $1
GROUP BY b.id, b.title
ORDER BY review_count DESC
LIMIT 20;
Mean time: 850ms. Calls: 120. The query exceeds the 500ms threshold almost always, so auto_explain will have captured it. Let's go to the log:
docker logs bookstore-pg 2>&1 | grep -A 50 "review_count"
Example output (cleaned up for readability):
LOG: duration: 845.230 ms plan:
Query Text: SELECT b.id, b.title, count(r.id) AS review_count
FROM books b
LEFT JOIN reviews r ON r.book_id = b.id
WHERE b.author_id = $1
GROUP BY b.id, b.title
ORDER BY review_count DESC
LIMIT 20;
Limit (cost=15234.50..15234.55 rows=20 width=44) (actual time=843.120..845.180 rows=20 loops=1)
Buffers: shared hit=12000 read=4500
-> Sort (cost=15234.50..15238.75 rows=1700 width=44) (actual time=843.118..843.150 rows=20 loops=1)
Sort Key: (count(r.id)) DESC
Sort Method: top-N heapsort Memory: 27kB
Buffers: shared hit=12000 read=4500
-> HashAggregate (cost=15180.00..15197.00 rows=1700 width=44) (actual time=820.450..830.230 rows=1700 loops=1)
Group Key: b.id
Buffers: shared hit=12000 read=4500
-> Hash Right Join (cost=125.50..14010.00 rows=234000 width=20) (actual time=8.230..720.310 rows=235000 loops=1)
Hash Cond: (r.book_id = b.id)
Buffers: shared hit=12000 read=4500
-> Seq Scan on reviews r (cost=0.00..12500.00 rows=500000 width=8) (actual time=0.012..480.230 rows=500000 loops=1)
Buffers: shared hit=10000 read=4200
-> Hash (cost=120.00..120.00 rows=1700 width=20) (actual time=8.100..8.101 rows=1700 loops=1)
Buckets: 2048 Batches: 1 Memory Usage: 95kB
-> Index Scan using idx_books_author_id on books b (cost=0.42..120.00 rows=1700 width=20) (actual time=0.025..6.500 rows=1700 loops=1)
Index Cond: (author_id = $1)
Buffers: shared hit=2000 read=300
Planning Time: 0.450 ms
Execution Time: 845.300 ms
How to read this plan
Assuming you already have the module 2 base (reading plans), the key points here:
1. The bottleneck is the Seq Scan on reviews:
Seq Scan on reviews r ... (actual time=0.012..480.230 rows=500000 loops=1)
Buffers: shared hit=10000 read=4200
This line consumes 480ms of the 845ms total. It reads all 500,000 rows of reviews to do the JOIN, reading 14,200 blocks (10k from cache + 4.2k from disk).
2. The books part is fine:
Index Scan using idx_books_author_id on books b ... (actual time=0.025..6.500 rows=1700 loops=1)
Only 6.5ms for 1,700 books by the author. The index works.
3. After the JOIN, the HashAggregate groups the 235,000 results:
HashAggregate ... (actual time=820.450..830.230 rows=1700 loops=1)
It transforms the 235k result rows into 1,700 groups. It takes ~10ms for the aggregate itself.
4. Diagnosis:
The Seq Scan on reviews is the problem. Cause: there's no index on reviews.book_id that the planner can use for the JOIN. Without an index, it has to scan the whole table.
5. Proposed fix (module 3):
CREATE INDEX idx_reviews_book_id ON reviews(book_id);
With that index, the plan should change to Index Scan or Bitmap Index Scan for reviews, reading only the reviews of the author's 1,700 books (much less than 500,000).
6. Validation:
After applying the index, reset pg_stat_statements, generate load, and confirm that mean_exec_time dropped. If it dropped, the auto_explain log should no longer capture this query (it's below the 500ms threshold).
Integrated workflow: pg_stat_statements + auto_explain
Real use combines the two tools in one flow:
1. Query pg_stat_statements (top queries by the 4 dimensions).
2. Identify the problematic queryid.
3. Search the auto_explain log for recent executions of that query.
4. Read the captured plan.
5. Decide a fix (index, rewrite, eager loading, refactor).
6. Apply the fix.
7. Reset pg_stat_statements.
8. Generate load.
9. Verify that the queryid no longer appears in the top and that the plan in the log improved.
How to cross-reference the data
pg_stat_statements uses the queryid (hash). auto_explain logs the complete Query Text in the log. There's no direct join by queryid in the default log. The practical way to cross-reference:
Option 1: extract the text and search:
-- Pull the query text from the top:
SELECT query FROM pg_stat_statements WHERE queryid = 1234567890;
Then grep the log:
docker logs bookstore-pg 2>&1 | grep -B 1 -A 50 "the first fragment of the query text"
Option 2: enable log_line_prefix with queryid (PG 14+):
In postgresql.conf:
log_line_prefix = '%m [%p] %q%u@%d %Q '
# %Q includes the queryid if compute_query_id is enabled
compute_query_id = on
This adds the queryid to every log line, letting you grep by queryid directly. Useful when your log is voluminous.
Option 3: use pgbadger or another parsing tool:
pgbadger is the classic tool for processing PostgreSQL logs into interactive HTML. It reads auto_explain output and presents it grouped by query. For real production, don't parse logs by hand.
Why this matters in real work
1. It's the canonical tool for debugging queries in production. All serious DBAs use auto_explain (or pganalyze, which uses it internally) on every PostgreSQL they maintain. It's not optional.
2. It enables root cause analysis without reproducing the query. In development you connect and run EXPLAIN ANALYZE. In production you can't — the cached data changes, the concurrent load changes. auto_explain captures the plan under the real conditions of the failure, which is 10x more useful for diagnosing.
3. It enables postmortems with data. When there's an incident, being able to show the team "this is the plan that was running at 3am when the outage started" is the difference between theory and certainty. Without automatic capture, your post-incident plan is always guesswork.
4. It detects plan flapping. If a query sometimes runs with Index Scan and sometimes with Seq Scan, you'll see both plans in the log at different moments. That tells you the planner is changing strategy, which generally points to stale statistics (module 7) or skewed parameters.
5. It's the foundation of pganalyze, Datadog DBM, AWS Performance Insights, and any serious DB APM. If you understand auto_explain, you understand what those products show you. If you don't understand it, you pay for them blindly.
Traps and common mistakes
Mistake 1 (configuration): log_min_duration too low in production
Symptom: "I enabled auto_explain with log_min_duration = 0 so I wouldn't miss anything. The log generated 50GB in an hour and the app got slow."
Why it happens: capturing the plan has overhead (not huge, but real). Capturing it for every query, especially the trivial ones that run thousands of times per second, adds up. Also the generated log consumes disk and makes it hard to find what matters amid the noise.
How to distinguish: monitor the size of the PostgreSQL log after enabling auto_explain. If it grows more than 100MB/day just from auto_explain, your threshold is too low.
How to fix it: raise log_min_duration gradually. Start at 1s for a new system, lower it to 500ms if the log stays small, don't go below 250ms in high-traffic production.
Mistake 2 (interpretation): reading the captured plan as if it were the current plan
Symptom: "I saw this plan in the log, I added an index, but pg_stat_statements still shows the query as slow."
Why it happens: the plan in the log is from that moment. If the captured plan was before your fix, applying the fix doesn't change the logged plan — what changes are the future plans that auto_explain captures.
How to distinguish: look at the date of the log. If it's from before your fix deploy, it's not relevant. Reset pg_stat_statements, generate new load, and review the auto_explain logs after the fix.
How to fix it: always work with recent plans. After any fix, regenerate load and review the new plans. The old ones are historical.
Mistake 3 (operational): not including log_buffers
Symptom: "I captured the plan but I don't see info about how many blocks were read from cache vs disk."
Why it happens: auto_explain.log_buffers is off by default. Without that option, the plan doesn't include Buffers: shared hit=X read=Y.
How to distinguish: if your captured plan only has cost and actual time but no Buffers, you're missing the option.
How to fix it:
auto_explain.log_buffers = on
And restart (or pg_reload_conf() if you only change this parameter, which does support reload). With log_buffers, the plan includes the I/O info that is critical for diagnosing cache problems.
Mistake 4 (format): choosing text when you're going to parse
Symptom: "I want to process the auto_explain plans with a Python script, but parsing text is a nightmare."
Why it happens: the text format is for humans. It has indentation, multiple lines, and it's not trivial to parse with regex.
How to distinguish: if your use is only human reading (interactive debugging), text is fine. If your use is ingestion into an APM, metrics, or automated analysis, text is the worst option.
How to fix it:
auto_explain.log_format = 'json'
Each plan is logged as parseable JSON. A bit more voluminous but much more useful for tooling. pganalyze and pgbadger support both formats.
Mistake 5 (security): plans with sensitive data in Query Text
Symptom: "The auto_explain log shows queries like WHERE email = 'alice@example.com' with the email in plain text."
Why it happens: if the app builds queries with literals instead of parameters (same problem we saw in capsule 02), the plan's Query Text contains them. Anyone with access to the PostgreSQL log can read them.
How to distinguish: review the Query Text in your log. If they contain concrete strings (emails, names, IDs), they're badly parameterized queries in your app.
How to fix it:
- Audit the app and migrate to parameterized queries (same fix as capsule 02).
- Restrict access to the PostgreSQL log to authorized personnel only.
- For regulated environments (PII, PCI), consider
auto_explain.log_parameter_max_length = 0, which omits parameter values from the log (replaces them with<no value>).
Mistake 6 (operational): not rotating the log
Symptom: "I enabled auto_explain 3 months ago, the log reached 200GB and the disk filled up."
Why it happens: auto_explain writes to the normal PostgreSQL log. If you don't have rotation configured, it grows indefinitely.
How to distinguish: check du -sh /var/log/postgresql/ or equivalent. If it exceeds 1GB and there's no rotation, you're heading for the problem.
How to fix it: configure logrotate (Linux) or the OS's equivalent system. PostgreSQL also has log_rotation_age and log_rotation_size to auto-rotate:
log_rotation_age = '1d'
log_rotation_size = '500MB'
log_truncate_on_rotation = on
Exercises
Exercise 1: enable auto_explain in the bookstore
Add auto_explain to the Docker setup you have from capsule 02. Configure log_min_duration = 250ms, log_analyze = on, log_buffers = on. Verify with a query that explicitly takes more than 250ms.
See solution
1. Edit the pg-config/postgresql.conf file:
Add/modify:
shared_preload_libraries = 'pg_stat_statements,auto_explain'
# auto_explain configuration
auto_explain.log_min_duration = '250ms'
auto_explain.log_analyze = on
auto_explain.log_buffers = on
auto_explain.log_format = 'text'
auto_explain.log_nested_statements = on
2. Restart the container:
docker restart bookstore-pg
3. Generate a slow query:
docker exec -it bookstore-pg psql -U bookstore -d bookstore -c \
"SELECT pg_sleep(0.4), 'verifying auto_explain' AS test;"
4. Check the log:
docker logs bookstore-pg 2>&1 | grep -A 5 "verifying auto_explain"
Expected output:
LOG: duration: 401.230 ms plan:
Query Text: SELECT pg_sleep(0.4), 'verifying auto_explain' AS test;
Result (cost=0.00..0.02 rows=1 width=40) (actual time=400.123..400.124 rows=1 loops=1)
Buffers: shared hit=0 read=0
If you see that output with plan: after the duration, auto_explain is active. If you only see the duration without a plan, the configuration is missing or it wasn't restarted.
Exercise 2: capture the plan of a problematic bookstore query
Run queries against the /books-with-reviews?author_id=5 endpoint (assume it exists and does a query with a JOIN over books and reviews with a count). Capture its plan in the log and save it to a plan-books-reviews.txt file.
See solution
1. Make sure auto_explain is configured with a low threshold (250ms or less for this capsule):
Check postgresql.conf and apply a restart if it was necessary.
2. Generate load over the endpoint:
for i in {1..30}; do
curl -s "http://localhost:8000/books-with-reviews?author_id=5" > /dev/null
done
3. Search for the plan in the log:
docker logs bookstore-pg 2>&1 | grep -B 1 -A 50 "books_with_reviews\|reviews\|book_id" \
| grep -A 40 "duration:" \
> plan-books-reviews.txt
If your endpoint doesn't generate slow queries because your DB is small, force a slow query directly:
docker exec -it bookstore-pg psql -U bookstore -d bookstore -c "
SELECT b.id, b.title, count(r.id) AS reviews
FROM books b
LEFT JOIN reviews r ON r.book_id = b.id
GROUP BY b.id, b.title
ORDER BY reviews DESC
LIMIT 50;
"
4. Inspect the plan:
cat plan-books-reviews.txt
Identify:
- Which scan does it use for
books(Seq, Index, Bitmap)? - Which scan does it use for
reviews? - How many buffers did it read (
shared hitvsread)? - What is the total
Execution Time? - Which is the most expensive step (highest
actual time)?
5. Compare with pg_stat_statements:
docker exec -it bookstore-pg psql -U bookstore -d bookstore -c "
SELECT calls, round(mean_exec_time::numeric, 2) AS mean_ms,
round(total_exec_time::numeric, 2) AS total_ms, query
FROM pg_stat_statements
WHERE query LIKE '%books%reviews%'
ORDER BY total_exec_time DESC
LIMIT 5;
"
Confirm that the queryid of the slow query appears in the top and that the plan in the log corresponds to that query.
Exercise 3: identify the bottleneck in a captured plan
You're given this captured auto_explain plan:
LOG: duration: 1245.30 ms plan:
Query Text: SELECT u.email, sum(o.total) FROM users u JOIN orders o ON o.user_id = u.id WHERE u.country = $1 GROUP BY u.email
HashAggregate (cost=24500..24800 rows=1500 width=44) (actual time=1240..1244 rows=1500 loops=1)
Group Key: u.email
Buffers: shared hit=8000 read=12000
-> Hash Join (cost=2500..23000 rows=120000 width=20) (actual time=120..1100 rows=120000 loops=1)
Hash Cond: (o.user_id = u.id)
Buffers: shared hit=8000 read=12000
-> Seq Scan on orders o (cost=0..18000 rows=500000 width=12) (actual time=0..900 rows=500000 loops=1)
Buffers: shared hit=4000 read=10000
-> Hash (cost=2400..2400 rows=1500 width=12) (actual time=110..110 rows=1500 loops=1)
-> Index Scan using idx_users_country on users u (cost=0.5..2400 rows=1500 width=12) (actual time=0.05..100 rows=1500 loops=1)
Index Cond: (country = $1)
Buffers: shared hit=4000 read=2000
Answer:
- Which is the slowest step?
- What is the probable cause?
- What fix do you propose?
- Which module covers that fix?
See solution
1. Slowest step:
Seq Scan on orders consumes 900ms of the 1245ms total (~72% of the time). It reads all 500,000 rows of orders, reading 14,000 blocks (4k cache + 10k disk).
2. Probable cause:
There's no index on orders.user_id that would serve the JOIN. Without an index, the planner has to scan the whole orders table. The users part is already fine (it uses idx_users_country).
3. Proposed fix:
CREATE INDEX idx_orders_user_id ON orders(user_id);
With that index, the planner should choose Nested Loop with Index Scan on orders, reading only the orders of the 1,500 users in the filtered country. Estimate: the orders step should drop from 900ms to ~50ms.
4. Module that covers the fix:
Module 3 (Advanced Indexing). In this case it's a simple B-tree, but the module covers when to choose each index type. If orders.user_id already had an index and the planner ignored it, we'd jump to module 7 (Statistics, Autovacuum & Planner) to diagnose why the planner isn't using it.
Post-fix validation:
Apply the index → reset pg_stat_statements → repeat the load → review the new plan in auto_explain. The duration should drop from 1245ms to something like 200-400ms.
Exercise 4: configure auto_explain for high-traffic production
Your app has a sustained 500 RPS. Some queries are <10ms (high frequency, OK), others are 50-200ms (medium, important), and slow queries that pass 800ms are critical. Your disk has 50GB free. Design the auto_explain configuration that captures what matters without saturating the log.
See solution
Analysis:
- Total traffic: 500 RPS × 86,400 seconds/day = ~43M queries/day.
- If you capture at 100ms, suppose 5% of queries pass that threshold = 2.15M plans/day. Each plan ~3KB in text format → 6.5GB/day. Unviable.
- If you capture at 500ms, suppose 0.5% = 215k plans/day = 650MB/day. Manageable but tight.
- If you capture at 1s, suppose 0.1% = 43k plans/day = 130MB/day. Comfortable.
Proposed configuration:
shared_preload_libraries = 'pg_stat_statements,auto_explain'
auto_explain.log_min_duration = '1000ms' # start conservative
auto_explain.log_analyze = on
auto_explain.log_buffers = on
auto_explain.log_format = 'json' # parseable by pgbadger / pganalyze
auto_explain.log_nested_statements = on
auto_explain.log_verbose = off # save space
auto_explain.log_parameter_max_length = 0 # truncate params (PII safety)
# PG log rotation
log_rotation_age = '1d'
log_rotation_size = '500MB'
log_truncate_on_rotation = on
Progressive tuning plan:
Day 1-7: with 1s, observe the real log size and what gets captured. If the log stays <500MB/day and the 500-1000ms queries do NOT appear in pg_stat_statements as a problem, it's fine. If they appear, lower it.
Day 8: lower to 750ms if the log grew <300MB/day. Repeat the observation.
Day 15: evaluate whether to lower to 500ms. If yes, do it during low-demand hours and with active monitoring for 30 minutes.
Critical note: in real production, it's almost always worth ingesting the logs into a specialized tool (pganalyze, Datadog DBM, AWS Performance Insights). Manual log parsing doesn't scale. The configuration here is the foundation; the tool is the frontend.
Exercise 5: integrate pg_stat_statements and auto_explain in a workflow
Design a bash script (or pseudocode) that:
- Identifies the query with the highest
total_exec_timeinpg_stat_statements. - Pulls its
querytext. - Searches the PostgreSQL log for the captured plans that correspond (by matching a fragment of the query text).
- Prints the most recent plan.
See solution
#!/bin/bash
# top-query-plan.sh
# Finds the query with the highest total_exec_time and shows its most recent captured plan.
set -e
CONTAINER="bookstore-pg"
DB_USER="bookstore"
DB_NAME="bookstore"
# 1. Identify the query with the highest total_exec_time (excluding noise):
QUERY_TEXT=$(docker exec -it "$CONTAINER" psql -U "$DB_USER" -d "$DB_NAME" -tA -c "
SELECT query
FROM pg_stat_statements
WHERE query NOT LIKE '%pg_stat_statements%'
AND query NOT LIKE '%pg_catalog%'
AND query NOT LIKE 'BEGIN%'
ORDER BY total_exec_time DESC
LIMIT 1;
")
if [ -z "$QUERY_TEXT" ]; then
echo "No queries found in pg_stat_statements."
exit 1
fi
echo "=== Top query by total_exec_time ==="
echo "$QUERY_TEXT"
echo ""
# 2. Extract a distinctive fragment (first 60 characters):
FRAGMENT=$(echo "$QUERY_TEXT" | cut -c1-60)
echo "=== Searching for plans in the log with fragment: $FRAGMENT ==="
echo ""
# 3. Search for the most recent plan containing that fragment:
docker logs "$CONTAINER" 2>&1 | \
grep -B 1 -A 40 "$FRAGMENT" | \
grep -A 40 "duration:" | \
tail -42
echo ""
echo "=== End of captured plan ==="
Usage:
chmod +x top-query-plan.sh
./top-query-plan.sh
Script limitations:
- If the
Query Textin the log doesn't match exactly the one inpg_stat_statements(due to whitespace, for example), the grep fails. Better solution: parse logs in JSON withjq. - It only brings the most recent plan; if you want to compare multiple executions, you need more logic.
- In real production, this is replaced by direct queries to the pganalyze API or equivalent.
Professional workflow:
In teams that invest more in tooling: pganalyze, Datadog DBM, or AWS Performance Insights already do this matching automatically. They made the pg_stat_statements + auto_explain pair into their product. The skill of doing it by hand (this exercise) serves to understand what those tools do internally.
Summary and next step
In this capsule you:
- Enabled
auto_explainin PostgreSQL 16 viashared_preload_librarieswith the appropriate configuration (log_min_duration,log_analyze,log_buffers,log_format). - Decided an appropriate threshold for different contexts: low in development (100ms), medium in staging (250-500ms), high and gradually tuned in production (1s → 500ms).
- Read a captured plan and identified the bottleneck (Seq Scan where there should be an Index Scan, JOINs without indexes, etc.).
- Integrated
pg_stat_statements(which queries are a problem) withauto_explain(why they're a problem) in a diagnostic workflow. - Anticipated the traps: an exploding log, irrelevant historical plans, sensitive data in
Query Text, lack of rotation.
Before moving on, you should be able to:
- Enable
auto_explainon any PostgreSQL you have access to. - Decide an appropriate threshold based on the environment's context.
- Read a plan from the log and identify the most expensive step.
- Combine
pg_stat_statementsandauto_explainto diagnose and validate fixes.
Next capsule — the slow query log and when to use it. auto_explain captures the complete plan, which is ideal for deep debugging. But sometimes you only need to know which queries passed a certain threshold, without the plan, without the cost of capturing it. PostgreSQL has log_min_duration_statement which fulfills this simpler function. Capsule 05 teaches you when each one is appropriate, how they combine, and why many serious teams use the two together: log_min_duration_statement with a low threshold (all slow queries, but only the text), and auto_explain with a higher threshold (the truly problematic ones, with the full plan).
Resources
- PostgreSQL 16 —
auto_explainreference — the complete official reference for parameters and examples. - pgAnalyze — "Logging slow query plans with auto_explain" — a practical guide with configuration tips.
- Hubert "depesz" Lubaczewski — explain.depesz.com — a tool to visualize PostgreSQL plans in interactive HTML.
- pgBadger — a PostgreSQL log analyzer in HTML, supports
auto_explain. - Datadog — "Postgres slow query logging with auto_explain" — an APM perspective on plan logging.
- Crunchy Data — "Get to Know auto_explain" — an operational overview of the extension.
Module 5 — Database Performance & Query Tuning Guide