auto_explain and Slow Query Forensics

A slow query only fires under specific production load and cannot be reproduced in testing. auto_explain captures its real execution plan automatically, the moment it actually happens.

auto_explain hooks into query execution to automatically log an EXPLAIN plan for any statement exceeding a configured duration threshold — exactly what a query that only manifests under specific, unreproducible production load needs, since there is no need to catch it happening live or guess at reproducing it manually. Unlike pg_stat_statements from Lesson 3.6.1, auto_explain lives in session_preload_libraries and genuinely loads with nothing more than a configuration reload — a real, direct contrast worth confirming rather than assuming both preload mechanisms behave identically.\n\nSeeing its output turns out to depend on something else entirely: this VM's logging_collector defaults to off, meaning log messages normally go straight to the server's console rather than any persistent file — a real, separate requirement (and a real restart, since logging_collector is postmaster-context) that has nothing to do with auto_explain itself. And since pgBadger, the curriculum's suggested report generator, is confirmed absent on this server (no network, no compiler), this lab substitutes real grep against the real log file — the same honest substitution pattern already used for every other absent tool this course has encountered.

Loading auto_explain, No Restart Required

sed -i "s/#session_preload_libraries = ''/session_preload_libraries = 'auto_explain'/" /var/lib/postgresql/18/data/postgresql.conf

SELECT pg_reload_conf();
SHOW session_preload_libraries;  -- auto_explain

Genuinely applied with just a reload — a real, direct contrast with pg_stat_statements' shared_preload_libraries in Lesson 3.6.1, which needed a full restart.

A Separate, VM-Specific Requirement: logging_collector

# This VM's own postgresql.conf explicitly sets logging_collector = off by default —
# auto_explain's messages would otherwise go straight to the console, not any file
sed -i 's/logging_collector = off/logging_collector = on/' /var/lib/postgresql/18/data/postgresql.conf
pg_ctl restart -D /var/lib/postgresql/18/data -w

LOG:  redirecting log output to logging collector process
HINT:  Future log output will appear in directory "log".

logging_collector is postmaster-context — a genuine restart, entirely separate from auto_explain's own reload-only requirement a moment ago.

Only the Genuinely Slow Query Gets Captured

SET auto_explain.log_min_duration = 100;
SET auto_explain.log_buffers = on;
SET auto_explain.log_analyze = on;
SELECT pg_sleep(0.05);   -- 50ms, below the threshold
SELECT b.name, r.score FROM beers b JOIN beer_ratings r ON r.beer_id = b.id ORDER BY r.score DESC LIMIT 5;  -- genuinely slower

LOG:  duration: 154.002 ms  plan:
	Query Text: SELECT b.name, r.score FROM beers b JOIN beer_ratings r ON r.beer_id = b.id ORDER BY r.score DESC LIMIT 5;
	Limit  (cost=210.85..210.86 rows=5 width=44) (actual time=154.002..154.002 rows=5.00 loops=1)
	  Buffers: shared hit=3 read=98

The 50ms pg_sleep never appears in the log at all — only the query that genuinely exceeded the 100ms threshold, with its real execution plan and real buffer counts attached automatically.

pgBadger Confirmed Absent — Real grep Instead

which pgbadger   # nothing
grep -E 'duration:|Buffers:' /var/lib/postgresql/18/data/log/postgresql*.log

LOG:  duration: 158.389 ms  plan:
	  Buffers: shared hit=3 read=98
	        Buffers: shared hit=3 read=98
	              Buffers: shared read=98

read=98 is the largest single buffer-read count in this plan — the direct evidence for exactly where an index would help most, without needing pgBadger's formatted HTML report to find it.

session_preload_libraries vs shared_preload_libraries

Both preload modules before a session starts using them, but shared_preload_libraries loads a module into shared memory at postmaster startup (needed by modules like pg_stat_statements that maintain cluster-wide state, requiring a genuine restart), while session_preload_libraries loads a module fresh for each new session's own backend process, which is why a plain configuration reload is enough — no shared memory allocation is involved.

auto_explain.log_min_duration

The threshold, in milliseconds, above which auto_explain automatically logs a query's execution plan. Queries completing faster than this are not logged at all — set too low, it floods the log with routine fast queries; set at a genuinely meaningful threshold (matching what "slow" actually means for the workload), it captures exactly the outliers worth investigating, with zero need to reproduce them manually first.

⚙️ Load auto_explain With Just a Reload

Add auto_explain to session_preload_libraries and confirm it applies with a plain reload, no restart.

as-postgres sh -c "sed -i \"s/#session_preload_libraries = ''/session_preload_libraries = 'auto_explain'/\" /var/lib/postgresql/18/data/postgresql.conf"

psql -U postgres -d beer_db -c "SELECT pg_reload_conf();"

sleep 1; psql -U postgres -d beer_db -c "SHOW session_preload_libraries;"

student@lab:~$ as-postgres sh -c "sed -i \"s/#session_preload_libraries = ''/session_preload_libraries = 'auto_explain'/\" /var/lib/postgresql/18/data/postgresql.conf" student@lab:~$ psql -U postgres -d beer_db -c "SELECT pg_reload_conf();" SET pg_reload_conf ----------------- t (1 row) student@lab:~$ sleep 1; psql -U postgres -d beer_db -c "SHOW session_preload_libraries;" SET session_preload_libraries ---------------------------- auto_explain (1 row)

📋 Enable logging_collector — A Separate, Real Requirement

Enable this VM's own logging_collector (off by default here) with a genuine restart, so a real log file will actually exist.

as-postgres sh -c "sed -i 's/logging_collector = off/logging_collector = on/' /var/lib/postgresql/18/data/postgresql.conf" && as-postgres sh -c 'pg_ctl restart -D /var/lib/postgresql/18/data -w'

student@lab:~$ as-postgres sh -c "sed -i 's/logging_collector = off/logging_collector = on/' /var/lib/postgresql/18/data/postgresql.conf" && as-postgres sh -c 'pg_ctl restart -D /var/lib/postgresql/18/data -w' waiting for server to shut down.... done server stopped waiting for server to start....2026-06-26 16:02:37.752 UTC [138] LOG: redirecting log output to logging collector process 2026-06-26 16:02:37.752 UTC [138] HINT: Future log output will appear in directory "log". done server started

🔬 Confirm Only the Genuinely Slow Query Gets Captured

Run a fast query and a genuinely slower one, and confirm the log only captures the one that actually exceeded the threshold.

psql -U postgres -d beer_db -c "SET auto_explain.log_min_duration = 100;" -c "SET auto_explain.log_buffers = on;" -c "SET auto_explain.log_analyze = on;" -c "SELECT pg_sleep(0.05);" -c "SELECT b.name, r.score FROM beers b JOIN beer_ratings r ON r.beer_id = b.id ORDER BY r.score DESC LIMIT 5;"

as-postgres sh -c "cat /var/lib/postgresql/18/data/log/postgresql*.log"

student@lab:~$ psql -U postgres -d beer_db -c "SET auto_explain.log_min_duration = 100;" -c "SET auto_explain.log_buffers = on;" -c "SET auto_explain.log_analyze = on;" -c "SELECT pg_sleep(0.05);" -c "SELECT b.name, r.score FROM beers b JOIN beer_ratings r ON r.beer_id = b.id ORDER BY r.score DESC LIMIT 5;" SET SET SET SET pg_sleep ---------- (1 row) name | score ----------------+------- Special Marzen | 10.0 Classic Sour | 10.0 Limited Weizen | 10.0 Special Weiss | 10.0 Wild Pilsner | 10.0 (5 rows) student@lab:~$ as-postgres sh -c "cat /var/lib/postgresql/18/data/log/postgresql*.log" 2026-06-26 16:02:37.399 UTC [135] LOG: starting PostgreSQL 18.4 on i686-buildroot-linux-gnu, compiled by i686-buildroot-linux-gnu-gcc.br_real (Buildroot 2024.02.3) 12.3.0, 32-bit 2026-06-26 16:02:37.403 UTC [135] LOG: listening on IPv4 address "0.0.0.0", port 5432 2026-06-26 16:02:37.403 UTC [135] LOG: listening on IPv6 address "::", port 5432 2026-06-26 16:02:37.412 UTC [135] LOG: listening on Unix socket "/tmp/.s.PGSQL.5432" 2026-06-26 16:02:37.475 UTC [139] LOG: database system was shut down at 2026-06-26 16:02:37 UTC 2026-06-26 16:02:37.512 UTC [135] LOG: database system is ready to accept connections 2026-06-26 16:02:39.288 UTC [146] LOG: duration: 154.002 ms plan: Query Text: SELECT b.name, r.score FROM beers b JOIN beer_ratings r ON r.beer_id = b.id ORDER BY r.score DESC LIMIT 5; Limit (cost=210.85..210.86 rows=5 width=44) (actual time=154.002..154.002 rows=5.00 loops=1) Buffers: shared hit=3 read=98

📊 Confirm pgBadger Is Absent and Use Real grep Instead

Check that pgBadger cannot be found on this server, then use grep directly against the real log to find the highest buffer-read count.

which pgbadger

as-postgres sh -c "grep -E 'duration:|Buffers:' /var/lib/postgresql/18/data/log/postgresql*.log"

student@lab:~$ which pgbadger student@lab:~$ as-postgres sh -c "grep -E 'duration:|Buffers:' /var/lib/postgresql/18/data/log/postgresql*.log" 2026-06-26 16:02:39.850 UTC [147] LOG: duration: 158.389 ms plan: Buffers: shared hit=3 read=98 Buffers: shared hit=3 read=98 Buffers: shared read=98 Buffers: shared read=73 Buffers: shared read=25 Buffers: shared read=25

Lab 3.6.3 complete. auto_explain, genuinely capturing a real slow query automatically:\n\n\n auto_explain loaded, reload only : ✅ no restart, confirmed directly\n logging_collector, separate restart : ✅ real log file now exists\n Only the slow query captured : ✅ 50ms skipped, 154ms logged with plan\n pgBadger absent, real grep substitute : ✅ confirmed, worked directly\n

Enable JavaScript to run the live terminal and track your progress.