And now, we put on our waders and venture into the swamp that is all of the PostgreSQL logging GUCs.
PostgreSQL 8.3 is the release in which the server started doing its own housekeeping in earnest: autovacuum on by default, checkpoints spread out over the interval instead of dumped at the end of it, HOT updates. The same release added three parameters for watching it do so, and shipped all three turned off. Fourteen years and fourteen major versions later, PostgreSQL 15 turned two of them on. The third is still waiting, and I’ll get to why it shouldn’t be.
log_checkpoints
Default on since 15, off before that; context sighup. Two lines per checkpoint (or restartpoint, on a standby), one when it starts and one when it finishes. Here is a pair from a sandbox with max_wal_size deliberately set too small:
1 LOG: checkpoints are occurring too frequently (10 seconds apart) 2 HINT: Consider increasing the configuration parameter "max_wal_size". 3 LOG: checkpoint starting: wal 4 LOG: checkpoint complete: wrote 1743 buffers (10.6%), wrote 0 SLRU buffers; 0 WAL file(s) added, 1 removed, 0 recycled; write=0.171 s, sync=0.138 s, total=0.437 s; sync files=26, longest=0.029 s, average=0.006 s; distance=12589 kB, estimate=12589 kB; lsn=0/3B90160, redo lsn=0/24001F0
What follows starting: is why the checkpoint ran. time is the checkpoint_timeout timer, which is what you want to see. wal means max_wal_size was hit first, and a steady diet of wal is the single most common checkpoint misconfiguration I run into. immediate force wait is someone typing CHECKPOINT; a base backup shows force wait, with immediate added only if it asked for a fast checkpoint; shutdown and end-of-recovery are what they say. The nag about frequency comes from checkpoint_warning and is not gated by this parameter; it tells you checkpoints are too frequent, and this parameter tells you what each one cost.
The complete line is the cost. The buffer count and percentage are how much of shared_buffers was dirty; write= is the spread-out write phase governed by checkpoint_completion_target, and sync= is the fsync() phase at the end, where the stalls live. longest= is the single slowest fsync(), and a longest that climbs into whole seconds is storage failing to absorb the burst. distance and estimate are how much WAL passed since the last checkpoint and the running estimate used to decide how many segments to recycle rather than delete. The two LSNs (16 and later) are the checkpoint record and the redo point; the redo point is where crash recovery would begin if the server died right now, which is what a checkpoint is for.
pg_stat_checkpointer (17 and later; before that, checkpoints_timed and checkpoints_req in pg_stat_bgwriter) gives you the timed-to-requested ratio, and that ratio is the headline. The log gives you the timestamp, which is what lets you lay a checkpoint’s sync phase over the latency spike in your graphs and stop arguing about whether they’re related. Leave it on. If you’ve inherited a configuration template from the era when it was off, and there are a lot of those, fix that first.
log_autovacuum_min_duration
Default 10min since 15, -1 before; context sighup; units are milliseconds. 0 logs every autovacuum and autoanalyze, -1 logs none, and anything in between logs the ones that ran at least that long. It can be overridden per table as a storage parameter (since 9.2). Any value other than -1 also gets you a line when autovacuum skips a table because it couldn’t get the lock or the table vanished underneath it.
The entry it writes is the same report VACUUM (VERBOSE) produces, and in 18 it’s a dozen lines: index scans, pages, tuples, the removable cutoff, relfrozenxid movement, frozen pages, visibility-map changes, per-index page counts, buffer and WAL usage, and the elapsed time. Add delay time (18, with track_cost_delay_timing on) and I/O timings (with track_io_timing on). Here is the part that matters, from a sandbox table that was updated while another session held a snapshot open:
1 LOG: automatic vacuum of table "postgres.public.hot": index scans: 0 2 pages: 0 removed, 443 remain, 443 scanned (100.00% of total), 0 eagerly scanned 3 tuples: 0 removed, 100000 remain, 50000 are dead but not yet removable 4 removable cutoff: 770, which was 1 XIDs old when operation ended 5 ... 6 system usage: CPU: user: 0.00 s, system: 0.00 s, elapsed: 0.21 s
Fifty thousand dead tuples, none removed, because something older than them was still holding a snapshot. That something is a long transaction (see idle_in_transaction_session_timeout), a standby with hot_standby_feedback, or a replication slot nobody remembers creating, and this line is how you find out it exists before the table has doubled. The vacuum took 0.21 seconds. At the default threshold it is never logged.
That’s the problem with the default. Ten minutes is a duration, and duration tracks table size, not trouble. The vacuums that run for ten minutes are on your largest tables, and they are mostly fine; they’re big because the table is big. The vacuums that describe a problem are the ones on a hot, medium-sized table that run every naptime, reclaim nothing, and finish in under a second. A duration threshold filters out exactly those. Set it to 0. The entries are a few hundred bytes each and arrive no faster than autovacuum finishes tables, and the “aggressive” and “to prevent wraparound” variants of the header, the index scan bypassed by failsafe line, and an index-scans count above one (the dead-item store filled and every index had to be scanned again) are all things you want in the log every time they happen, not only when they happened to take long enough.
log_temp_files
Default -1, meaning off; context superuser, so a superuser can turn it on for one session, and postgresql.conf plus a reload turns it on for everyone; units are kilobytes. 0 logs every temporary file; a positive value logs files at least that large. One line per file, written when the file is deleted (usually when the query finishes), with the statement attached:
1 LOG: temporary file: path "base/pgsql_tmp/pgsql_tmp635.0", size 12959744 2 STATEMENT: select count(*) from (select * from big order by h) s
A temporary file is a sort, a hash, or a tuplestore that outgrew work_mem and went to disk under pgsql_tmp (or a temporary tablespace). It is not a temporary table; those are ordinary relations that happen to be session-private. Every one of these files is I/O the query would not have done with a larger memory budget or a better plan, which makes this the work_mem diagnostic, and the only one that names the statement. pg_stat_database.temp_files and temp_bytes count every file whether or not this is on, so they tell you it’s happening and how much; pg_stat_statements tells you which normalized query; this tells you which statement, when, with the text. The STATEMENT line is courtesy of log_min_error_statement, whose default of ERROR includes LOG-level messages; raise it past LOG and the statement disappears.
The objection is volume. It’s real: a hash join at a tiny work_mem in my sandbox wrote sixty-two of these lines for one query, one per batch file. But a log full of temporary-file lines is not a logging problem. It’s a work_mem problem with a timestamp on every occurrence, and the log is the only place that list exists. Set it to 0. (temp_file_limit is the sibling that stops the worst offender from filling the disk; different post.)
This is the one that should have flipped in 15 along with the other two. The only argument against it is the log-volume argument, the same one that kept log_checkpoints off for fourteen years, and it was wrong then too. Three parameters, three answers: on, 0, 0. The project has conceded two of them; the defaults will catch up on the third eventually, and there’s no reason to wait.