On 2020/11/12 6:00, Euler Taveira wrote:
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.
I'm not sure how useful this information is in practice.
It also exposes the checkpoint timestamp
in debug messages.
ereport(DEBUG1,
(errmsg("checkpoint record is at %X/%X",
(uint32) (checkPointLoc
>> 32), (uint32) checkPointLoc)));
+ ereport(DEBUG1,
+ (errmsg("checkpoint time is %s",
str_time(checkPoint.time))));
The above first debug message displays the LSN of the checkpoint record.
OTOH, the second message displays the time when the checkpoint started
(not the time when checkpoint record was written at the end of checkpoint).
So isn't it confusing to display those inconsistent information together?
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
+1
+#ifdef FRONTEND
+ strftime(checkpointstr, sizeof(checkpointstr), "%c",
localtime(&time_tmp));
+#else
+ pg_strftime(checkpointstr, sizeof(checkpointstr), "%c",
pg_localtime(&time_tmp, log_timezone));
+#endif
You can simplify the code by using timestamptz_to_str() here instead, like
xact_desc_commit() does.
Regards,
--
Fujii Masao
Advanced Computing Technology Center
Research and Development Headquarters
NTT DATA CORPORATION
