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
From 4b725a45dfb89ee9a463e6ee7987cd8b660053cd Mon Sep 17 00:00:00 2001
From: Euler Taveira <euler.tave...@enterprisedb.com>
Date: Wed, 11 Nov 2020 11:24:25 -0300
Subject: [PATCH 1/2] Report latest completed checkpoint timestamp
A new detail message prints the latest completed checkpoint when
reaching the consistent state. This information is useful when you use
recovery_target = immediate because it is not clear what timestamp it
stops applying the WAL.
It also adds new debug messages that report the checkpoint timestamp.
It might be useful for debug purposes.
---
src/backend/access/transam/xlog.c | 8 +++++++-
1 file changed, 7 insertions(+), 1 deletion(-)
diff --git a/src/backend/access/transam/xlog.c b/src/backend/access/transam/xlog.c
index aa63f37615..cf70950932 100644
--- a/src/backend/access/transam/xlog.c
+++ b/src/backend/access/transam/xlog.c
@@ -6524,6 +6524,8 @@ StartupXLOG(void)
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))));
InRecovery = true; /* force recovery even if SHUTDOWNED */
/*
@@ -6657,6 +6659,8 @@ StartupXLOG(void)
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))));
}
else
{
@@ -8033,7 +8037,9 @@ CheckRecoveryConsistency(void)
ereport(LOG,
(errmsg("consistent recovery state reached at %X/%X",
(uint32) (lastReplayedEndRecPtr >> 32),
- (uint32) lastReplayedEndRecPtr)));
+ (uint32) lastReplayedEndRecPtr),
+ errdetail("Last completed checkpoint was at log time %s.",
+ str_time(ControlFile->checkPointCopy.time))));
}
/*
--
2.20.1
From 9b7b3effad8c860a003dc60eb1ea53aa15a26ad9 Mon Sep 17 00:00:00 2001
From: Euler Taveira <euler.tave...@enterprisedb.com>
Date: Wed, 11 Nov 2020 11:25:48 -0300
Subject: [PATCH 2/2] Print checkpoint timestamp for xlog_desc
Checkpoint timestamp might be useful for debug purposes. Let's expose
it. Since this function is used by frontend (pg_waldump) and backend
(WAL_DEBUG), use different code paths to print the timestamp.
---
src/backend/access/rmgrdesc/xlogdesc.c | 16 +++++++++++++++-
1 file changed, 15 insertions(+), 1 deletion(-)
diff --git a/src/backend/access/rmgrdesc/xlogdesc.c b/src/backend/access/rmgrdesc/xlogdesc.c
index 3200f777f5..76b4388701 100644
--- a/src/backend/access/rmgrdesc/xlogdesc.c
+++ b/src/backend/access/rmgrdesc/xlogdesc.c
@@ -14,6 +14,10 @@
*/
#include "postgres.h"
+#ifdef FRONTEND
+#include <time.h>
+#endif
+
#include "access/transam.h"
#include "access/xlog.h"
#include "access/xlog_internal.h"
@@ -43,13 +47,23 @@ xlog_desc(StringInfo buf, XLogReaderState *record)
info == XLOG_CHECKPOINT_ONLINE)
{
CheckPoint *checkpoint = (CheckPoint *) rec;
+ time_t time_tmp;
+ char checkpointstr[128];
- appendStringInfo(buf, "redo %X/%X; "
+ time_tmp = (time_t) checkpoint->time;
+#ifdef FRONTEND
+ strftime(checkpointstr, sizeof(checkpointstr), "%c", localtime(&time_tmp));
+#else
+ pg_strftime(checkpointstr, sizeof(checkpointstr), "%c", pg_localtime(&time_tmp, log_timezone));
+#endif
+
+ appendStringInfo(buf, "redo %X/%X; timestamp %s; "
"tli %u; prev tli %u; fpw %s; xid %u:%u; oid %u; multi %u; offset %u; "
"oldest xid %u in DB %u; oldest multi %u in DB %u; "
"oldest/newest commit timestamp xid: %u/%u; "
"oldest running xid %u; %s",
(uint32) (checkpoint->redo >> 32), (uint32) checkpoint->redo,
+ checkpointstr,
checkpoint->ThisTimeLineID,
checkpoint->PrevTimeLineID,
checkpoint->fullPageWrites ? "true" : "false",
--
2.20.1
