Reporting WAL replay progress during pre-consistency standby reovery
Hackorum builds and tests every patch posted to the lists, not only commitfest submissions. This is Hackorum's own CI rather than the PostgreSQL project's, and it is still under testing - please report anything that looks wrong.
You can run a PostgreSQL built from this patch straight from Docker, with no checkout and no build:
docker run --rm -p 5432:5432 ghcr.io/hackorum-dev/postgres-patch:t254107psql -h localhost -U postgresBuilt from patchset v2 (message #2), October 24, 2026 at 09:14 AM.
Every patchset is also pushed to a branch of our PostgreSQL fork, so you can check out the same tree CI built. Without a PostgreSQL checkout:
git clone --branch t254107_2 https://github.com/hackorum-dev/postgres.gitIn a checkout you already have, add the fork once:
git remote add hackorum https://github.com/hackorum-dev/postgres.gitthen, for this patchset and every later one:
git fetch hackorum t254107_2 && git checkout t254107_2Patchset v2 (message #2) is on t254107_2
Hi,
Periodic replay progress reporting could be useful when a new standby
remains unavailable for a long time before reaching consistency. SQL
monitoring is not yet available during this period, and it can be
difficult to determine from the standby logs whether WAL replay is
advancing.
PostgreSQL already periodically reports:
redo in progress, elapsed time: ..., current LSN: ...
during non-standby recovery. This is intentionally suppressed in
standby mode because a standby can remain in recovery indefinitely,
which could result in unbounded logging.
Would it make sense to emit the existing message only while a standby
has not yet reached consistency, and disable the progress timer as
soon as consistency is reached?
This would help particularly while replaying WAL from pg_wal, for
which there is no per-segment LOG message. During archive recovery,
"restored log file ..." indicates retrieval rather than the current
replay position. Once streaming starts, the primary may expose
replay_lsn through pg_stat_replication, but that does not cover the
earlier local/archive replay period.
The proposal would reuse log_startup_progress_interval and report only
the elapsed time and current replay LSN and it would preserve the
current no-periodic-reporting behavior after consistency.
Does this seem like a useful observability improvement, or is there an
existing way to obtain equivalent replay progress during this period?
If this seems useful, I would be happy to prepare and share a patch.
Best Regards,
Nitin Jadhav
Microsoft
Hi,
Attached is a v1 patch implementing the proposed behavior. The patch
enables the existing redo progress reporting while a standby has not
yet reached consistency and disables the progress timer as soon as
consistency is reached. It reuses log_startup_progress_interval and
does not introduce a new GUC or log message.
Please review and share your feedback.
Best Regards,
Nitin Jadhav
Microsoft
The following review has been posted through the commitfest application:
make installcheck-world: tested, passed
Implements feature: tested, passed
Spec compliant: not tested
Documentation: tested, passed
Hello,
This patch looks good to me.
I have made 2 tests with a standby using log_startup_progress_interval = 1
With little load on primary I get in standby log:
2026-10-24 15:20:28.178 CEST [59310] LOG: entering standby mode
2026-10-24 15:20:28.180 CEST [59310] LOG: resetting unlogged relations (cleanup), elapsed time: 0.00 s, current path: base/27537
2026-10-24 15:20:28.181 CEST [59310] LOG: resetting unlogged relations (cleanup), elapsed time: 0.00 s, current path: base/24891
2026-10-24 15:20:28.182 CEST [59310] LOG: resetting unlogged relations (cleanup), elapsed time: 0.00 s, current path: base/4
2026-10-24 15:20:28.183 CEST [59310] LOG: resetting unlogged relations (cleanup), elapsed time: 0.00 s, current path: base/28385
2026-10-24 15:20:28.184 CEST [59310] LOG: resetting unlogged relations (cleanup), elapsed time: 0.00 s, current path: base/16388
2026-10-24 15:20:28.186 CEST [59310] LOG: resetting unlogged relations (cleanup), elapsed time: 0.00 s, current path: base/30501
2026-10-24 15:20:28.186 CEST [59310] LOG: resetting unlogged relations (cleanup), elapsed time: 0.00 s, current path: base/25301
2026-10-24 15:20:28.187 CEST [59310] LOG: resetting unlogged relations (cleanup), elapsed time: 0.00 s, current path: base/29668
2026-10-24 15:20:28.188 CEST [59310] LOG: resetting unlogged relations (cleanup), elapsed time: 0.00 s, current path: base/26081
2026-10-24 15:20:28.189 CEST [59310] LOG: resetting unlogged relations (cleanup), elapsed time: 0.01 s, current path: base/30560
2026-10-24 15:20:28.190 CEST [59310] LOG: redo starts at 0/4D000028
cp: impossible d'évaluer '/var/lib/pgsql/sarchive/00000001000000000000004E': Aucun fichier ou dossier de ce nom
2026-10-24 15:20:28.192 CEST [59310] LOG: redo in progress, elapsed time: 0.00 s, current LSN: 0/4D000050
2026-10-24 15:20:28.192 CEST [59310] LOG: consistent recovery state reached at 0/4E000000
2026-10-24 15:20:28.192 CEST [59304] LOG: database system is ready to accept read-only connections
If I stop standby, run a large insert on primary and restart standby I get lots of messages in standby log:
2026-10-24 15:28:21.609 CEST [60252] LOG: entering standby mode
2026-10-24 15:28:21.612 CEST [60252] LOG: resetting unlogged relations (cleanup), elapsed time: 0.00 s, current path: base/18903
2026-10-24 15:28:21.613 CEST [60252] LOG: resetting unlogged relations (cleanup), elapsed time: 0.00 s, current path: base/22741
2026-10-24 15:28:21.614 CEST [60252] LOG: resetting unlogged relations (cleanup), elapsed time: 0.00 s, current path: base/23973
2026-10-24 15:28:21.615 CEST [60252] LOG: resetting unlogged relations (cleanup), elapsed time: 0.00 s, current path: base/25963
2026-10-24 15:28:21.616 CEST [60252] LOG: resetting unlogged relations (cleanup), elapsed time: 0.00 s, current path: base/25796
2026-10-24 15:28:21.618 CEST [60252] LOG: resetting unlogged relations (cleanup), elapsed time: 0.00 s, current path: base/30501
2026-10-24 15:28:21.618 CEST [60252] LOG: resetting unlogged relations (cleanup), elapsed time: 0.00 s, current path: base/21447
2026-10-24 15:28:21.619 CEST [60252] LOG: resetting unlogged relations (cleanup), elapsed time: 0.00 s, current path: base/30579
2026-10-24 15:28:21.621 CEST [60252] LOG: resetting unlogged relations (cleanup), elapsed time: 0.00 s, current path: base/29311
2026-10-24 15:28:21.621 CEST [60252] LOG: resetting unlogged relations (cleanup), elapsed time: 0.01 s, current path: base/25762
2026-10-24 15:28:21.622 CEST [60252] LOG: resetting unlogged relations (cleanup), elapsed time: 0.01 s, current path: base/30820
2026-10-24 15:28:21.623 CEST [60252] LOG: redo starts at 0/4E01FFE8
2026-10-24 15:28:21.624 CEST [60252] LOG: redo in progress, elapsed time: 0.00 s, current LSN: 0/4E026EA0
2026-10-24 15:28:21.625 CEST [60252] LOG: redo in progress, elapsed time: 0.00 s, current LSN: 0/4E02D3A8
2026-10-24 15:28:21.626 CEST [60252] LOG: redo in progress, elapsed time: 0.00 s, current LSN: 0/4E033B30
2026-10-24 15:28:21.627 CEST [60252] LOG: redo in progress, elapsed time: 0.00 s, current LSN: 0/4E03A510
2026-10-24 15:28:21.628 CEST [60252] LOG: redo in progress, elapsed time: 0.00 s, current LSN: 0/4E040FD8
2026-10-24 15:28:21.629 CEST [60252] LOG: redo in progress, elapsed time: 0.00 s, current LSN: 0/4E047720
2026-10-24 15:28:21.630 CEST [60252] LOG: redo in progress, elapsed time: 0.00 s, current LSN: 0/4E04DEA8
2026-10-24 15:28:21.631 CEST [60252] LOG: redo in progress, elapsed time: 0.00 s, current LSN: 0/4E054908
2026-10-24 15:28:21.632 CEST [60252] LOG: redo in progress, elapsed time: 0.00 s, current LSN: 0/4E05B410
2026-10-24 15:28:21.633 CEST [60252] LOG: redo in progress, elapsed time: 0.01 s, current LSN: 0/4E061ED8
2026-10-24 15:28:21.634 CEST [60252] LOG: redo in progress, elapsed time: 0.01 s, current LSN: 0/4E068A38
2026-10-24 15:28:21.635 CEST [60252] LOG: redo in progress, elapsed time: 0.01 s, current LSN: 0/4E06F740
2026-10-24 15:28:21.636 CEST [60252] LOG: redo in progress, elapsed time: 0.01 s, current LSN: 0/4E076320
2026-10-24 15:28:21.637 CEST [60252] LOG: redo in progress, elapsed time: 0.01 s, current LSN: 0/4E07CDA8
2026-10-24 15:28:21.638 CEST [60252] LOG: redo in progress, elapsed time: 0.01 s, current LSN: 0/4E0838F0
2026-10-24 15:28:21.639 CEST [60252] LOG: redo in progress, elapsed time: 0.01 s, current LSN: 0/4E08A450
2026-10-24 15:28:21.640 CEST [60252] LOG: redo in progress, elapsed time: 0.01 s, current LSN: 0/4E090F58
2026-10-24 15:28:21.641 CEST [60252] LOG: redo in progress, elapsed time: 0.01 s, current LSN: 0/4E097960
2026-10-24 15:28:21.642 CEST [60252] LOG: redo in progress, elapsed time: 0.01 s, current LSN: 0/4E09E480
2026-10-24 15:28:21.643 CEST [60252] LOG: redo in progress, elapsed time: 0.02 s, current LSN: 0/4E0A4FC8
...
...
...
2026-10-24 15:28:21.858 CEST [60252] LOG: redo in progress, elapsed time: 0.23 s, current LSN: 0/4E6496E0
2026-10-24 15:28:21.858 CEST [60252] LOG: consistent recovery state reached at 0/4E650718
2026-10-24 15:28:21.858 CEST [60246] LOG: database system is ready to accept read-only connections
I have checked updated documentation.
I don't think there is a need to check SQL compliance.
Regards,
PF.
The new status of this patch is: Ready for Committer