Hi,
While restoring a backup using recovery_target immediate, I noticed that there
isn't a timestamp available.
LOG: consistent recovery state reached at 0/A000100
LOG: recovery stopping after reaching consistency
LOG: pausing at the end of recovery
HINT: Execute pg_wal_replay_resume() to promote.
LOG: database system is ready to accept read only connections
if you decide to use one of the targets or just recover until the end of the
WAL, you get a (last completed transaction) timestamp.
LOG: redo done at 0/10FFEC38 system usage: CPU: user: 0.10 s, system: 0.05 s, elapsed: 1.65 s
LOG: last completed transaction was at log time 2020-11-11 17:27:31.715251-03
LOG: restored log file "000000010000000000000010" from archive
cp: cannot stat '/a/pgarchive/00000002.history': No such file or directory
LOG: selected new timeline ID: 2
LOG: archive recovery complete
cp: cannot stat '/a/pgarchive/00000001.history': No such file or directory
LOG: database system is ready to accept connections
I dig into the pg_waldump output to figure out the timestamp, however, the
checkpoint timestamp isn't printed by pg_waldump. The checkpoint timestamp
might be useful information at least when you set large values for a checkpoint
or need to investigate a performance/corruption issue.
The first patch adds a new message that prints the latest completed checkpoint
when the consistent state is reached. It also exposes the checkpoint timestamp
in debug messages.
LOG: consistent recovery state reached at 0/A000100
DETAIL: Last completed checkpoint was at log time 2020-11-11 17:31:50 -03.
LOG: recovery stopping after reaching consistency
LOG: pausing at the end of recovery
HINT: Execute pg_wal_replay_resume() to promote.
LOG: database system is ready to accept read only connections
.
.
.
DEBUG: checkpoint record is at 0/A000060
DEBUG: checkpoint time is 2020-11-11 17:34:19 -03
The second patch provides the checkpoint timestamp in the pg_waldump output and
also when you enable wal_debug parameter. The pg_waldump output looks like
rmgr: XLOG len (rec/tot): 114/ 114, tx: 0, lsn: 0/0A000060, prev 0/0A000028, desc: CHECKPOINT_ONLINE redo 0/A000028; timestamp qua 11 nov 2020 17:34:19 -03; tli 1; prev tli 1; fpw true; xid 0:519; oid 24576; multi 1; offset 0; oldest xid 501 in DB 1; oldest multi 1 in DB 1; oldest/newest commit timestamp xid: 0/0; oldest running xid 519; online
and the debug messages are
DEBUG: checkpoint record is at 0/A000060
DEBUG: checkpoint time is 2020-11-11 17:37:47 -03
LOG: REDO @ 0/A000060; LSN 0/A0000D8: prev 0/A000028; xid 0; len 88 - XLOG/CHECKPOINT_ONLINE: redo 0/A000028; timestamp Wed Nov 11 17:37:47 2020; tli 1; prev tli 1; fpw true; xid 0:519; oid 24576; multi 1; offset 0; oldest xid 501 in DB 1; oldest multi 1 in DB 1; oldest/newest commit timestamp xid: 0/0; oldest running xid 519; online
Regards,
--
