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

From: Julien Rouhaud <[email-masked]>
Date: Wed, 12 Jan 2022 14:09:21 +0800

Hi,

On Tue, Dec 28, 2021 at 10:56 AM Bharath Rupireddy
<[email-masked]> wrote:
>
> attaching v1-0001-XXX from the initial mail again just for the sake of
> completion:

Unfortunately this breaks the cfbot as it tries to apply this patch
too: http://cfbot.cputube.org/patch_36_3474.log.

For this kind of situation I think that the usual solution is to use a
.txt extension to make sure that the cfbot won't try to apply it.

---

From: Tom Lane <[email-masked]>
Date: Wed, 12 Jan 2022 01:19:22 -0500

> .txt extension to make sure that the cfbot won't try to apply it.

Yeah ... this has come up before.  Is there a documented way to
attach files that the cfbot will ignore?

Two specific scenarios seem to be interesting:

1. You are attaching patch(es) plus some non-patch files

2. You are attaching some random files, and would like to not
displace the cfbot's idea of the latest patchset.

I don't know exactly how to do either of those.

			regards, tom lane

---

From: Julien Rouhaud <[email-masked]>
Date: Wed, 12 Jan 2022 14:31:53 +0800

> attach files that the cfbot will ignore?

Not that I know of unfortunately.  I think the apply part is done by
https://github.com/macdice/cfbot/blob/master/cfbot_patchburner_chroot_ctl.sh#L93-L120,
which seems reasonable.  So basically any extension outside of those could be
used, excluding of course anything clearly suspicious that would be rejected by
many email providers.

> displace the cfbot's idea of the latest patchset.

I'm assuming that someone wanting to send an additional patch to be applied on
top of the OP patchset is part of 2?

---

From: Tom Lane <[email-masked]>
Date: Wed, 12 Jan 2022 01:37:05 -0500

> top of the OP patchset is part of 2?

AFAIK, if you're submitting a patch then you have to attach a complete
patchset, or the cfbot will be totally lost.  Getting the bot to
understand incremental patches would be useful for sure ... but it's
outside the scope of what I'm asking for now, which is just clear
documentation of what the bot can do already.

			regards, tom lane

---

From: Julien Rouhaud <[email-masked]>
Date: Wed, 12 Jan 2022 14:50:36 +0800

> documentation of what the bot can do already.

Right, but the use case I'm mentioning is a bit different: provide
another patch while *not* triggering the cfbot.  I've seen cases in
the past where people want to share some code to the OP and it seems
reasonable to allow that without risking the trigger the cfbot, at
least not without the OP validating or adapting the changes.

---

From: Thomas Munro <[email-masked]>
Date: Wed, 12 Jan 2022 19:52:00 +1300

> documentation of what the bot can do already.

By way of documentation, I've just now tried to answer these question
in the new FAQ at:

https://wiki.postgresql.org/wiki/Cfbot

---

From: Tom Lane <[email-masked]>
Date: Wed, 12 Jan 2022 01:58:40 -0500

> https://wiki.postgresql.org/wiki/Cfbot

Thanks!

			regards, tom lane

---

From: Bharath Rupireddy <[email-masked]>
Date: Thu, 13 Jan 2022 11:50:53 +0530

> .txt extension to make sure that the cfbot won't try to apply it.

Thanks.  IMO, the following format of logging is better, so attaching
the v2-0001-Add-checkpoint-and-redo-LSN-to-LogCheckpointEnd-l.patch as
.patch

2021-12-28 02:52:24.464 UTC [2394396] LOG:  checkpoint completed at
location=0/212FFC8 with REDO start location=0/212FF90: wrote 451
buffers (2.8%); 0 WAL file(s) added, 0 removed, 1 recycled;
write=0.012 s, sync=0.032 s, total=0.071 s; sync files=6,
longest=0.022 s, average=0.006 s; distance=6272 kB, estimate=6272 kB

Others are attached as .txt files.

Regards,
Bharath Rupireddy.
From c23010c67a66dd21e318ae4d475ee0d85c5c1d08 Mon Sep 17 00:00:00 2001
From: Bharath Rupireddy <[email-masked]>
Date: Tue, 28 Dec 2021 02:52:49 +0000
Subject: [PATCH v2] Add checkpoint and redo LSN to LogCheckpointEnd log
 message

It is useful (for debugging purposes) if the checkpoint end message
has the checkpoint LSN and REDO LSN. 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 | 10 ++++++++--
 1 file changed, 8 insertions(+), 2 deletions(-)

diff --git a/src/backend/access/transam/xlog.c b/src/backend/access/transam/xlog.c
index 1e1fbe957f..cd3fce6a2c 100644
--- a/src/backend/access/transam/xlog.c
+++ b/src/backend/access/transam/xlog.c
@@ -8920,11 +8920,14 @@ LogCheckpointEnd(bool restartpoint)
 
 	if (restartpoint)
 		ereport(LOG,
-				(errmsg("restartpoint complete: wrote %d buffers (%.1f%%); "
+				(errmsg("restartpoint completed at location=%X/%X with REDO start location=%X/%X: "
+						"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",
+						LSN_FORMAT_ARGS(ControlFile->checkPoint),
+						LSN_FORMAT_ARGS(ControlFile->checkPointCopy.redo),
 						CheckpointStats.ckpt_bufs_written,
 						(double) CheckpointStats.ckpt_bufs_written * 100 / NBuffers,
 						CheckpointStats.ckpt_segs_added,
@@ -8940,11 +8943,14 @@ LogCheckpointEnd(bool restartpoint)
 						(int) (CheckPointDistanceEstimate / 1024.0))));
 	else
 		ereport(LOG,
-				(errmsg("checkpoint complete: wrote %d buffers (%.1f%%); "
+				(errmsg("checkpoint completed at location=%X/%X with REDO start location=%X/%X: "
+						"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",
+						LSN_FORMAT_ARGS(ControlFile->checkPoint),
+						LSN_FORMAT_ARGS(ControlFile->checkPointCopy.redo),
 						CheckpointStats.ckpt_bufs_written,
 						(double) CheckpointStats.ckpt_bufs_written * 100 / NBuffers,
 						CheckpointStats.ckpt_segs_added,
-- 
2.25.1

From 999cfd53ce4e16ccfff94c0022cd80fe8ff84be5 Mon Sep 17 00:00:00 2001
From: Bharath Rupireddy <[email-masked]>
Date: Tue, 28 Dec 2021 02:45:51 +0000
Subject: [PATCH v2] Add checkpoint and redo LSN to LogCheckpointEnd log
 message

It is useful (for debugging purposes) if the checkpoint end message
has the checkpoint LSN and REDO LSN. 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 | 10 ++++++++--
 1 file changed, 8 insertions(+), 2 deletions(-)

diff --git a/src/backend/access/transam/xlog.c b/src/backend/access/transam/xlog.c
index 1e1fbe957f..26eb2a22f3 100644
--- a/src/backend/access/transam/xlog.c
+++ b/src/backend/access/transam/xlog.c
@@ -8920,11 +8920,14 @@ LogCheckpointEnd(bool restartpoint)
 
 	if (restartpoint)
 		ereport(LOG,
-				(errmsg("restartpoint complete: wrote %d buffers (%.1f%%); "
+				(errmsg("restartpoint complete: location=%X/%X, REDO start location=%X/%X; "
+						"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",
+						LSN_FORMAT_ARGS(ControlFile->checkPoint),
+						LSN_FORMAT_ARGS(ControlFile->checkPointCopy.redo),
 						CheckpointStats.ckpt_bufs_written,
 						(double) CheckpointStats.ckpt_bufs_written * 100 / NBuffers,
 						CheckpointStats.ckpt_segs_added,
@@ -8940,11 +8943,14 @@ LogCheckpointEnd(bool restartpoint)
 						(int) (CheckPointDistanceEstimate / 1024.0))));
 	else
 		ereport(LOG,
-				(errmsg("checkpoint complete: wrote %d buffers (%.1f%%); "
+				(errmsg("checkpoint complete: location=%X/%X, REDO start location=%X/%X; "
+						"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",
+						LSN_FORMAT_ARGS(ControlFile->checkPoint),
+						LSN_FORMAT_ARGS(ControlFile->checkPointCopy.redo),
 						CheckpointStats.ckpt_bufs_written,
 						(double) CheckpointStats.ckpt_bufs_written * 100 / NBuffers,
 						CheckpointStats.ckpt_segs_added,
-- 
2.25.1

---

From: Bharath Rupireddy <[email-masked]>
Date: Fri, 14 Jan 2022 18:52:45 +0530

> longest=0.022 s, average=0.006 s; distance=6272 kB, estimate=6272 kB

One of the test cases was failing with the above style of the log
message, changing "checkpoint complete" to "checkpoint completed at
location" doesn't seem to be a better idea. It looks like the users or
the log monitoring tools might be using the same text "checkpoint
complete", therefore I don't want to break that. Here's the v3 patch
that I think will work better. Please review.

Regards,
Bharath Rupireddy.

---

From: "Bossart, Nathan" <[email-masked]>
Date: Thu, 20 Jan 2022 00:36:32 +0000

On 1/3/22, 5:52 PM, "Kyotaro Horiguchi" <[email-masked]> wrote:
> It seems to me "LSN" or just "location" is more confusing or
> mysterious than "REDO LSN" for the average user. If we want to avoid
> being technically too detailed, we would use just "start LSN=%X/%X,
> end LSN=%X/%X".  And it is equivalent to "WAL range=[%X/%X, %X/%X]"..

My first instinct was that this should stay aligned with
pg_controldata, but that would mean using "location=%X/%X, REDO
location=%X/%X," which doesn't seem terribly descriptive.  IIUC the
"checkpoint location" is the LSN of the WAL record for the checkpoint,
and the "checkpoint's REDO location" is the LSN where checkpoint
creation began (i.e., what you must retain for crash recovery).  My
vote is for "start=%X/%X, end=%X/%X."

Nathan

---

From: Kyotaro Horiguchi <[email-masked]>
Date: Thu, 20 Jan 2022 12:00:29 +0900 (JST)

At Thu, 20 Jan 2022 00:36:32 +0000, "Bossart, Nathan" <[email-masked]> wrote in 
> vote is for "start=%X/%X, end=%X/%X."

+1. Works for me.  %X/%X itself expresses it is an LSN.

regards.

-- 
Kyotaro Horiguchi
NTT Open Source Software Center

---

From: Bharath Rupireddy <[email-masked]>
Date: Thu, 27 Jan 2022 20:37:37 +0530

> vote is for "start=%X/%X, end=%X/%X."

I'm still not clear how the REDO location can be treated as a start
LSN? Can someone throw some light one what this checkpoint's REDO
location is?

Regards,
Bharath Rupireddy.

---

From: Nathan Bossart <[email-masked]>
Date: Thu, 27 Jan 2022 15:57:49 -0800

> LSN? Can someone throw some light one what this checkpoint's REDO

It's the WAL insert location at the time the checkpoint began (i.e., where
you need to begin replaying WAL from after a crash).

-- 
Nathan Bossart
Amazon Web Services: https://aws.amazon.com/

---

From: Bharath Rupireddy <[email-masked]>
Date: Fri, 28 Jan 2022 08:43:36 +0530

> +1. Works for me.  %X/%X itself expresses it is an LSN.

Thanks for the review. Here's the v4 patch, please have a look.

Let's not attempt to change how pg_controldata (tool and core
functions) emit the start and end LSN as checkpoint_lsn/redo_lsn and
checkpoint location/checkpoint's REDO location.

[1]
2022-01-28 03:06:10.213 UTC [2409486] LOG:  checkpoint starting:
immediate force wait
2022-01-28 03:06:10.257 UTC [2409486] LOG:  checkpoint complete:
start=0/14D9510, end=0/14D9548; wrote 4 buffers (0.0%); 0 WAL file(s)
added, 0 removed, 0 recycled; write=0.007 s, sync=0.008 s, total=0.044
s; sync files=3, longest=0.005 s, average=0.003 s; distance=0 kB,
estimate=0 kB

2022-01-28 03:06:42.254 UTC [2409486] LOG:  checkpoint starting:
immediate force wait
2022-01-28 03:06:42.279 UTC [2409486] LOG:  checkpoint complete:
start=0/14DBDB8, end=0/14DBDF0; wrote 2 buffers (0.0%); 0 WAL file(s)
added, 0 removed, 0 recycled; write=0.004 s, sync=0.004 s, total=0.025
s; sync files=2, longest=0.003 s, average=0.002 s; distance=10 kB,
estimate=10 kB

Regards,
Bharath Rupireddy.