Server logs, auto_explain and auditing

conceptThe concept

Where: log_destination is stderr, csvlog, jsonlog (PostgreSQL 15+) or syslog. With logging_collector = on the server captures its own output into log_directory/log_filename and rotates by log_rotation_age and log_rotation_size; pg_current_logfile() tells you the current file. In containers, leave the collector off and let the platform collect stderr.

Prefix: log_line_prefix controls what each line starts with. A useful one is '%m [%p] %q%u@%d/%a ': timestamp, process id, then user, database and application name for client sessions.

What:

auto_explain logs the execution plan of any statement slower than auto_explain.log_min_duration, so you see why a query was slow at the moment it was slow, with the parameters it really had. pgaudit writes structured AUDIT lines per statement class (read, write, ddl, role) or per object, for compliance.

whyWhy it matters

Statistics views such as pg_stat_statements tell you which queries are slow on average; the log tells you when one was slow, with which parameters, who ran it, what it waited for and what plan it used. Incident timelines are built from logs.

Use caseReal-world scenario

Checkout latency spikes every night at 02:10. The log shows lock-wait lines naming a reporting job's process, auto_explain shows the job's plan switching to a nested loop over a stale-statistics table, and log_autovacuum lines show autovacuum on that table being cancelled. Three log settings explained the whole incident.

Try itExamples

Run and edit these in the interactive lesson.

SELECT name, setting, context
FROM pg_settings
WHERE name IN ('log_destination', 'logging_collector', 'log_line_prefix', 'log_min_duration_statement',
               'log_statement', 'log_lock_waits', 'log_temp_files', 'log_autovacuum_min_duration',
               'log_checkpoints', 'log_connections', 'log_min_messages')
ORDER BY name;

LOAD 'auto_explain';
BEGIN;
SET LOCAL auto_explain.log_min_duration = 0;
SET LOCAL auto_explain.log_level = notice;
SET LOCAL client_min_messages = notice;
SELECT count(*) FROM orders WHERE status = 'cancelled';
ROLLBACK;

LOAD 'auto_explain';
BEGIN;
SET LOCAL auto_explain.log_min_duration = 0;
SET LOCAL auto_explain.log_analyze = on;
SET LOCAL auto_explain.log_buffers = on;
SET LOCAL auto_explain.log_timing = off;
SET LOCAL auto_explain.log_level = notice;
SET LOCAL client_min_messages = notice;
SELECT c.tier, count(*)
FROM orders o JOIN customers c ON c.id = o.customer_id
WHERE o.status = 'paid'
GROUP BY c.tier;
ROLLBACK;

# postgresql.conf
logging_collector = on
log_destination = 'jsonlog'
log_directory = 'log'
log_filename = 'postgresql-%a.log'          # one file per weekday
log_truncate_on_rotation = on
log_rotation_age = 1d
log_line_prefix = '%m [%p] %q%u@%d/%a '
log_min_duration_statement = 500ms
log_lock_waits = on
log_temp_files = 0
log_autovacuum_min_duration = 1s
log_checkpoints = on
log_connections = 'authorization'
log_statement = 'ddl'

shared_preload_libraries = 'pg_stat_statements,auto_explain'
auto_explain.log_min_duration = '2s'
auto_explain.log_analyze = on
auto_explain.log_timing = off
auto_explain.log_nested_statements = on

# postgresql.conf (pgaudit is a separate package)
shared_preload_libraries = 'pg_stat_statements,pgaudit'
pgaudit.log = 'ddl, role, write'
pgaudit.log_catalog = off
pgaudit.log_parameter = off      -- parameters can contain personal data

-- object-level auditing: log every SELECT on the cards table only
CREATE ROLE auditor NOLOGIN;
ALTER SYSTEM SET pgaudit.role = 'auditor';
GRANT SELECT ON cards TO auditor;

-- a resulting log line
-- AUDIT: SESSION,12,1,WRITE,UPDATE,TABLE,public.accounts,"UPDATE accounts SET ...",<not logged>

# slowest statements in today's JSON log
jq -r 'select(.message | startswith("duration")) | [.timestamp, .user, .dbname, .message] | @tsv' \
  log/postgresql-Thu.json | sort -t$'\t' -k4 -r | head

# a full report with charts
pgbadger -j 4 -o report.html log/postgresql-*.json

internalsUnder the hood

Backends write log messages to stderr; with the collector on, a dedicated logger process reads a pipe and writes files, so slow log storage can back-pressure the database. Every message has a severity (DEBUG5 to PANIC); log_min_messages filters what reaches the log, client_min_messages what reaches the client. auto_explain hooks the executor: with log_analyze it enables instrumentation for every statement, which costs CPU even for fast queries, so use log_timing = off or sample_rate on busy systems.

Avoid / preferDo this, not that

log_statement = 'all'

log_min_duration_statement = 500ms
log_statement = 'ddl'

auto_explain.log_min_duration = 0
auto_explain.log_analyze = on

auto_explain.log_min_duration = '2s'
auto_explain.log_analyze = on
auto_explain.log_timing = off

PitfallsCommon mistakes

• Leaving log_line_prefix without user, database and application name, so a slow statement cannot be traced to a service.
• Putting the log directory on the same volume as the data directory with no rotation, then filling the disk.
• Enabling log_parameter or log_min_duration_statement with bind parameters on tables containing card numbers or personal data.
• Reading only pg_stat_statements during an incident and never looking at lock-wait and autovacuum log lines.

LimitsWhen not to use it

Logs are not a metrics system: do not parse them for request rates or connection counts that pg_stat_* views give you directly and cheaply. And do not use log_statement = 'all' as an audit trail; pgaudit produces structured, filterable records for that.

SecuritySecurity notes

Logs contain SQL text, which can include personal data, passwords in ALTER ROLE ... PASSWORD statements and literal values. Restrict log file permissions (log_file_mode), ship them to a store with access control and retention rules, and never paste raw logs into tickets or chat tools without redaction.

ChallengeTry it yourself

LOAD 'auto_explain';
BEGIN;
SET LOCAL auto_explain.log_min_duration = 0;
SET LOCAL auto_explain.log_analyze = on;
SET LOCAL auto_explain.log_level = notice;
SET LOCAL client_min_messages = notice;
SELECT rating, count(*) FROM reviews GROUP BY rating;
ROLLBACK;

InterviewQuestions you should be able to answer

QuizCheck your understanding

5 questions with instant feedback in the interactive lesson; a wrong answer goes into your review deck.

Go deeperOfficial documentation

• Cumulative statistics system
• Wait events