PostgreSQL 17 and the Logs That Reveal Why the Startup Process Hung

Every DBA who has ever stared at a PostgreSQL instance "hanging" on startup, with no new log line for several minutes, knows the wrong temptation: restart it. Christophe Pettus, in the article All Your GUCs in a Row: log_startup_progress_interval and log_recovery_conflict_waits, published on Planet PostgreSQL, dedicates the piece exactly to this blind spot, the startup process, the backend that replays the WAL, and to the two parameters that force it to say what it's doing.

The framing is precise because the two GUCs answer the same question in opposite contexts. On the primary, the startup process only exists during crash recovery, and while it exists no one can connect: the client gets FATAL: the database system is not yet accepting connections. On the standby, it never ends, it replays for the entire life of the server, and the question stops being "how much is left" and becomes "why did it stop". One parameter for each situation, and both answer in the server log, because in both situations the log is the only place there is to look.

The Primary That Went Silent

log_startup_progress_interval arrived in PostgreSQL 15. The default is 10s, the unit is milliseconds if you omit it, 0 disables it, and the context is sighup. Once per interval, while a long startup operation is still running, the process writes a line saying so. Three operations qualify: syncing the data directory (an fsync() of every file in the cluster, done whenever the last shutdown wasn't clean, which includes the first start of a freshly restored base backup), resetting unlogged relations, and WAL replay. Each has its own timer.

The replay lines are the ones that matter, because they carry the LSN:

LOG: redo starts at 0/902EC1F0
LOG: redo in progress, elapsed time: 10.00 s, current LSN: 0/A905D938
LOG: redo in progress, elapsed time: 20.00 s, current LSN: 0/B8FB2DB8
LOG: redo done at 0/C0B96070 system usage: CPU: user: 11.43 s, system: 8.45 s, elapsed: 27.80 s

Two of these lines already give a replay rate. The startup process doesn't know where the WAL ends until it reads an invalid record, so it doesn't print an estimate, but the highest-numbered segment in pg_wal is the upper bound, and rate plus distance gives an ETA, which is exactly the number whoever is on call wants to hear. Before version 15, this calculation came from watching the segment name in the process title in ps and timing it by hand, a method Pettus attributes to Nikolay Samokhvalov's how-to, and one that remains the only path in PostgreSQL 14.

Why the Parameter Exists

The commit that added the feature explains why: the person starts the server, sees three lines, sees nothing for minutes, and concludes it's stuck. What they do next, restart it, is the worst available move. The restart repeats the entire data directory sync, resumes replay from where the last completed restartpoint stopped, and even adds a HINT to the log saying the data is probably corrupted and that the last backup will be needed.

Here's the warning worth internalizing: that HINT isn't a diagnosis. It appears because the control file records that the previous startup died in the middle of recovery, which in fact happened, because you killed it. The sync phase is the one that most deserves attention: on a large cluster on network storage with a cold cache, it can run for many minutes with nothing in the log, and the progress line names the file it's on. If this is the slow phase, recovery_init_sync_method = syncfs is the fix, and it's the parameter itself that reveals this need.

An operational detail Pettus is careful to point out: the timer is armed at the start of each phase with the value in effect at that moment. If the parameter was set to 0 when replay began, reloading a new value in the middle of recovery does nothing. In his words:

This is a parameter you set before the crash, and the default is already the right value. The only setting that requires a decision is 0, and the decision is no.

>

-- Christophe Pettus

The Standby That Stopped

On the standby, replay lines are suppressed (the process would report progress forever), but the sync and unlogged reset phases still report. So, a standby that goes silent after redo starts at is replaying, not syncing. And here there are better instruments than the log: pg_last_wal_replay_lsn() on the standby and replay_lag in pg_stat_replication on the primary. The only gap is a standby restarting with a large local WAL backlog: between redo starts at and consistent recovery state reached you have neither SQL nor progress lines, and you're back to ps.

The second parameter is log_recovery_conflict_waits, which arrived in PostgreSQL 14. It's boolean, off by default, context sighup, and only does something on a hot standby. It reports the recovery conflict mechanism: replay and a running query want the same thing (a row version replay needs to remove, a relation lock replay needs to take, a buffer pinned by a scan), and the startup process waits up to max_standby_streaming_delay (30 seconds by default) for the query to get out of the way before cancelling it.

With the parameter turned on, a wait that exceeds deadlock_timeout (the same one-second timer used by log_lock_waits) generates one line when it crosses the threshold and another when it ends:

LOG: recovery still waiting after 1077.432 ms: recovery conflict on snapshot
DETAIL: Conflicting process: 8617.
CONTEXT: WAL redo at 0/7901F4C0 for Heap2/PRUNE_VACUUM_SCAN: ... blkref #0: rel 1663/5/16384, blk 0
LOG: recovery finished waiting after 12877.511 ms: recovery conflict on snapshot

There's nothing between the two lines, no matter how long the wait. So a still waiting with no finished waiting after it means the standby is stuck right now. The reason can be snapshot, lock, buffer pin, or tablespace. The DETAIL names the session getting in the way (buffer pin conflicts have no DETAIL, because PostgreSQL doesn't track who holds a pin), and the CONTEXT brings the WAL record in pg_waldump format. The rel 1663/5/16384 is tablespace, database, and relfilenode: SELECT pg_filenode_relation(1663, 16384) in that database names the table.

The Case Where It's Indispensable

The real value of the parameter is in what the example didn't do: it was a thirteen-second stall that cancelled nothing. The session ended on its own, so pg_stat_database_conflicts (which counts cancellations) stayed at zero, the query received no error, and the only other evidence was replay_lag climbing on the primary. The log, though, says the standby was stuck at 03:12, for thirteen seconds, on a vacuum record for a specific table, and which session was responsible. That's exactly what's needed at 09:00, when someone asks why the reports were stale.

The intensity of the need depends on max_standby_streaming_delay:

| Value | Behavior | Log usefulness | |---|---|---| | 0 | startup never waits | nothing is logged, nothing needs to be | | 30s (default) | waits and cancels at 30s | useful, but reconstructible from the cancellation error | | -1 | waits forever | the still waiting line can be the last one for hours, with no error to reconstruct from |

The value -1 is the one used by every analytical replica configured to stop cancelling the nightly report, and it's the setting this parameter exists for. The reason string even settles whether hot_standby_feedback would have helped, since feedback prevents snapshot conflicts and no other type.

Pettus's recommendation is economical: it costs nothing until the startup process has already waited one second, at which point two extra lines aren't a problem. Turn it on for every standby and keep deadlock_timeout at one second. For the Brazilian developer who operates read replicas, the practical lesson is that these two GUCs aren't optional in serious production: they're the difference between debugging with evidence and guessing. And, as is almost always the case in PostgreSQL, the right decision is made before the incident, not during it.