Subject: Re: Add checkpoint and redo LSN to LogCheckpointEnd log message

From: Kyotaro Horiguchi <[email-masked]>
Date: Wed, 16 Mar 2022 09:19:13 +0900 (JST)

At Tue, 15 Mar 2022 18:26:26 +0900, Michael Paquier <[email-masked]> wrote in 
> On Tue, Mar 15, 2022 at 05:23:40PM +0900, Kyotaro Horiguchi wrote:
> > At Tue, 15 Mar 2022 12:19:47 +0530, Bharath Rupireddy <[email-masked]> wrote in 
> >> On Fri, Mar 4, 2022 at 10:40 AM Kyotaro Horiguchi
> >> <[email-masked]> wrote:
> >> 0001 - I don't think you need to do this as UpdateControlFile
> >> (update_controlfile) will anyway update it, no?
> >> + /* Update control file using current time */
> >> + ControlFile->time = (pg_time_t) time(NULL);
> > 
> > Ugh.. Yes. It is a copy-pasto from older versions.  They may have the
> > same copy-pasto..
> 
> This thread has shifted to an entirely different discussion,
> presenting patches that touch code paths unrelated to what was first
> stated.  Shouldn't you create a new thread with a proper $subject to
> attract a more correct audience?  

I felt the same since some messages ago.  I thought Fujii-san thought
that he wants to fix the CreateRestartPoint issue before the
checkpoint log patch but he looks like busy these days.

Since the CreateRestartPoint issue is orthogonal to the main patch,
I'll separate that part into anther thread.

This thread is discussing one other topic, wordings in user-facing
texts. This is also orthogonal (3-dimentionally?) to the two topics.

In short, I split out the two topics other than checkpoint log to
other threads.

Thanks for cueing me to do that!

regareds.

-- 
Kyotaro Horiguchi
NTT Open Source Software Center

---

From: Kyotaro Horiguchi <[email-masked]>
Date: Wed, 16 Mar 2022 10:29:47 +0900 (JST)

At Wed, 16 Mar 2022 09:19:13 +0900 (JST), Kyotaro Horiguchi <[email-masked]> wrote in 
> In short, I split out the two topics other than checkpoint log to

So, this is about the main topic of this thread, adding LSNs to
checkpint log.  Other topics have moved to other treads [1], [2] ,
[3].

I think this is no longer controversial alone.  So this patch is now
really Read-for-Commiter and is waiting to be picked up.

regards.

[1] https://www.postgresql.org/message-id/20220316.102444.2193181487576617583.horikyota.ntt%40gmail.com
[2] https://www.postgresql.org/message-id/20220316.102900.2003692961119672246.horikyota.ntt%40gmail.com
[3] https://www.postgresql.org/message-id/20220316.102509.785466054344164656.horikyota.ntt%40gmail.com

>From 4c3d40e7aaf29cb905f3561a291d35981d762456 Mon Sep 17 00:00:00 2001
From: Bharath Rupireddy <[email-masked]>
Date: Fri, 4 Mar 2022 13:22:41 +0900
Subject: [PATCH v13] Add checkpoint and redo LSN to LogCheckpointEnd log
 message

It is useful (for debugging purposes) if the checkpoint end message
has the checkpoint LSN(end) and REDO LSN(start). It gives more
context while analyzing checkpoint-related issues. The pg_controldata
gives the last checkpoint LSN and REDO LSN, but having this info
alongside the log message helps analyze issues that happened
previously, connect the dots and identify the root cause.
---
 src/backend/access/transam/xlog.c | 22 ++++++++++++++++++----
 1 file changed, 18 insertions(+), 4 deletions(-)

diff --git a/src/backend/access/transam/xlog.c b/src/backend/access/transam/xlog.c
index ed16f279b1..b85c76d8f8 100644
--- a/src/backend/access/transam/xlog.c
+++ b/src/backend/access/transam/xlog.c
@@ -6121,7 +6121,8 @@ LogCheckpointEnd(bool restartpoint)
 						"%d WAL file(s) added, %d removed, %d recycled; "
 						"write=%ld.%03d s, sync=%ld.%03d s, total=%ld.%03d s; "
 						"sync files=%d, longest=%ld.%03d s, average=%ld.%03d s; "
-						"distance=%d kB, estimate=%d kB",
+						"distance=%d kB, estimate=%d kB; "
+						"lsn=%X/%X, redo lsn=%X/%X",
 						CheckpointStats.ckpt_bufs_written,
 						(double) CheckpointStats.ckpt_bufs_written * 100 / NBuffers,
 						CheckpointStats.ckpt_segs_added,
@@ -6134,14 +6135,21 @@ LogCheckpointEnd(bool restartpoint)
 						longest_msecs / 1000, (int) (longest_msecs % 1000),
 						average_msecs / 1000, (int) (average_msecs % 1000),
 						(int) (PrevCheckPointDistance / 1024.0),
-						(int) (CheckPointDistanceEstimate / 1024.0))));
+						(int) (CheckPointDistanceEstimate / 1024.0),
+						/*
+						 * ControlFileLock is not required as we are the only
+						 * updator of these variables.
+						 */
+						LSN_FORMAT_ARGS(ControlFile->checkPoint),
+						LSN_FORMAT_ARGS(ControlFile->checkPointCopy.redo))));
 	else
 		ereport(LOG,
 				(errmsg("checkpoint complete: wrote %d buffers (%.1f%%); "
 						"%d WAL file(s) added, %d removed, %d recycled; "
 						"write=%ld.%03d s, sync=%ld.%03d s, total=%ld.%03d s; "
 						"sync files=%d, longest=%ld.%03d s, average=%ld.%03d s; "
-						"distance=%d kB, estimate=%d kB",
+						"distance=%d kB, estimate=%d kB; "
+						"lsn=%X/%X, redo lsn=%X/%X",
 						CheckpointStats.ckpt_bufs_written,
 						(double) CheckpointStats.ckpt_bufs_written * 100 / NBuffers,
 						CheckpointStats.ckpt_segs_added,
@@ -6154,7 +6162,13 @@ LogCheckpointEnd(bool restartpoint)
 						longest_msecs / 1000, (int) (longest_msecs % 1000),
 						average_msecs / 1000, (int) (average_msecs % 1000),
 						(int) (PrevCheckPointDistance / 1024.0),
-						(int) (CheckPointDistanceEstimate / 1024.0))));
+						(int) (CheckPointDistanceEstimate / 1024.0),
+						/*
+						 * ControlFileLock is not required as we are the only
+						 * updator of these variables.
+						 */
+						LSN_FORMAT_ARGS(ControlFile->checkPoint),
+						LSN_FORMAT_ARGS(ControlFile->checkPointCopy.redo))));
 }
 
 /*
-- 
2.27.0

---

From: Greg Stark <[email-masked]>
Date: Mon, 28 Mar 2022 15:31:16 -0400

This patch is currently showing up with a test failure in the CFBot
however I do *not* believe this is a bug in the patch. I think it's a
bug in that test which is being discussed elsewhere.

It's also a very short and straightforward patch that a committer
could probably make a decision about whether it's a good idea or not
and then apply it quickly if so.

Just to give people a leg up and an idea how short the patch is...
Here's the entire patch:

diff --git a/src/backend/access/transam/xlog.c
b/src/backend/access/transam/xlog.c

 /*
-- 
2.27.0

---

From: Fujii Masao <[email-masked]>
Date: Thu, 7 Jul 2022 01:11:33 +0900

> really Read-for-Commiter and is waiting to be picked up.

+1

Isn't it better to add "at this time" or something at the end of the comment because only we're not always updator of them? No?

Barring any objection, I'm thinking to apply the above small change and commit the patch.

Regards,

-- 
Fujii Masao
Advanced Computing Technology Center
Research and Development Headquarters
NTT DATA CORPORATION

---

From: Kyotaro Horiguchi <[email-masked]>
Date: Thu, 07 Jul 2022 16:26:59 +0900 (JST)

At Thu, 7 Jul 2022 01:11:33 +0900, Fujii Masao <[email-masked]> wrote in 
> Isn't it better to add "at this time" or something at the end of the
> comment because only we're not always updator of them? No?

Excluding initialization, (I believe) checkpointer is really the only
updator of the variables/members.  But I'm fine with the addition.

regards.

---

From: Fujii Masao <[email-masked]>
Date: Thu, 7 Jul 2022 22:45:39 +0900

> updator of the variables/members.  But I'm fine with the addition.

Ok, so I modified the patch slightly and pushed it. Thanks!

Regards,