recovery_target immediate timestamp

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,

--
Euler Taveira http://www.2ndQuadrant.com/
PostgreSQL Development, 24x7 Support, Remote DBA, Training & Services