On Wed, 11 Nov 2020 at 22:40, Fujii Masao <masao.fu...@oss.nttdata.com>
wrote:

>
> On 2020/11/12 6:00, Euler Taveira wrote:
>
> > 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.
>
> Fujii, thanks for reviewing it. It provides the same information as the
"last
completed transaction was" message.


> > 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?
>
> Indeed the checkpoint timestamp is from before it determines the REDO LSN.
Are
you saying the this checkpoint timestamp is inconsistent because it is not
near
the point it saves the RedoRecPtr? If so, let's move checkPoint.time a few
lines below.

    /*
     * Here we update the shared RedoRecPtr for future XLogInsert calls;
this
     * must be done while holding all the insertion locks.
     *
     * Note: if we fail to complete the checkpoint, RedoRecPtr will be left
     * pointing past where it really needs to point.  This is okay; the only
     * consequence is that XLogInsert might back up whole buffers that it
     * didn't really need to.  We can't postpone advancing RedoRecPtr
because
     * XLogInserts that happen while we are dumping buffers must assume that
     * their buffer changes are not included in the checkpoint.
     */
    RedoRecPtr = XLogCtl->Insert.RedoRecPtr = checkPoint.redo;
    checkPoint.time = (pg_time_t) time(NULL);

I realized that I was using the wrong variable in one of the debug messages.


> > 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.
>
> I have the same idea until I realized that checkPoint.time is pg_time_t
and not
TimestampTz. [digging the code a bit...] I figure out there is a function
that
converts from pg_time_t to TimestampTz: time_t_to_timestamptz(). I removed
that
ugly code but have to duplicate this function into compat.c. I don't have a
strong preference but I'm attaching a new patch.

At the end, I asked myself if it is worth changing this type from pg_time_t
to
TimestampTz.


-- 
Euler Taveira                 http://www.2ndQuadrant.com/
PostgreSQL Development, 24x7 Support, Remote DBA, Training & Services
From df8f4d295ebc205d46e77c5037c399afda17c546 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..2ff83c49e2 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(ControlFile->checkPointCopy.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 7ae7e1e41df935c046c10471bdce7f72fc12331b 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 |  3 ++-
 src/bin/pg_waldump/compat.c            | 13 +++++++++++++
 2 files changed, 15 insertions(+), 1 deletion(-)

diff --git a/src/backend/access/rmgrdesc/xlogdesc.c b/src/backend/access/rmgrdesc/xlogdesc.c
index 3200f777f5..02a6dacfdd 100644
--- a/src/backend/access/rmgrdesc/xlogdesc.c
+++ b/src/backend/access/rmgrdesc/xlogdesc.c
@@ -44,12 +44,13 @@ xlog_desc(StringInfo buf, XLogReaderState *record)
 	{
 		CheckPoint *checkpoint = (CheckPoint *) rec;
 
-		appendStringInfo(buf, "redo %X/%X; "
+		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,
+						 timestamptz_to_str(time_t_to_timestamptz(checkpoint->time)),
 						 checkpoint->ThisTimeLineID,
 						 checkpoint->PrevTimeLineID,
 						 checkpoint->fullPageWrites ? "true" : "false",
diff --git a/src/bin/pg_waldump/compat.c b/src/bin/pg_waldump/compat.c
index 7cb0539e74..2a1e7f8140 100644
--- a/src/bin/pg_waldump/compat.c
+++ b/src/bin/pg_waldump/compat.c
@@ -33,6 +33,19 @@ timestamptz_to_time_t(TimestampTz t)
 	return result;
 }
 
+/* copied from timestamp.c */
+TimestampTz
+time_t_to_timestamptz(pg_time_t tm)
+{
+	TimestampTz result;
+
+	result = (TimestampTz) tm -
+		((POSTGRES_EPOCH_JDATE - UNIX_EPOCH_JDATE) * SECS_PER_DAY);
+	result *= USECS_PER_SEC;
+
+	return result;
+}
+
 /*
  * Stopgap implementation of timestamptz_to_str that doesn't depend on backend
  * infrastructure.  This will work for timestamps that are within the range
-- 
2.20.1

Reply via email to