public inbox for [email protected]  
help / color / mirror / Atom feed
From: Bharath Rupireddy <[email protected]>
To: Julien Rouhaud <[email protected]>
Cc: Michael Paquier <[email protected]>
Cc: Kyotaro Horiguchi <[email protected]>
Cc: PostgreSQL Hackers <[email protected]>
Subject: Re: Add checkpoint and redo LSN to LogCheckpointEnd log message
Date: Thu, 13 Jan 2022 11:50:53 +0530
Message-ID: <CALj2ACUGutu6As-9p76Ta2bV59J97fbiCc9NSzaWXqxPJdMvag@mail.gmail.com> (raw)
In-Reply-To: <CAOBaU_aefLN5Gze52os5JzkNR_Fc+bJHPk=m67zov33-66MfZw@mail.gmail.com>
References: <CALj2ACWt6kqriAHrO+AJj+OmP=suwbktHT5JoYAn-nqZe2gd2g@mail.gmail.com>
	<[email protected]>
	<[email protected]>
	<CALj2ACXzv6FJNbTnP9uYsPXFeA4UcugSWDecxr19SjFCUCxP-g@mail.gmail.com>
	<CALj2ACUP84UYSimewLSs8--rT9dUTA7CUYTgXTnEb-2iHkc9wA@mail.gmail.com>
	<CAOBaU_aefLN5Gze52os5JzkNR_Fc+bJHPk=m67zov33-66MfZw@mail.gmail.com>

On Wed, Jan 12, 2022 at 11:39 AM Julien Rouhaud <[email protected]> wrote:
>
> Hi,
>
> On Tue, Dec 28, 2021 at 10:56 AM Bharath Rupireddy
> <[email protected]> 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.

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 protected]>
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 protected]>
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



Attachments:

  [text/plain] v2-0002-Add-checkpoint-and-redo-LSN-to-LogCheckpointEnd-l.txt (2.5K, ../CALj2ACUGutu6As-9p76Ta2bV59J97fbiCc9NSzaWXqxPJdMvag@mail.gmail.com/2-v2-0002-Add-checkpoint-and-redo-LSN-to-LogCheckpointEnd-l.txt)
  download | inline diff:
From c23010c67a66dd21e318ae4d475ee0d85c5c1d08 Mon Sep 17 00:00:00 2001
From: Bharath Rupireddy <[email protected]>
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



  [application/octet-stream] v2-0001-Add-checkpoint-and-redo-LSN-to-LogCheckpointEnd-l.patch (2.5K, ../CALj2ACUGutu6As-9p76Ta2bV59J97fbiCc9NSzaWXqxPJdMvag@mail.gmail.com/3-v2-0001-Add-checkpoint-and-redo-LSN-to-LogCheckpointEnd-l.patch)
  download | inline diff:
From c23010c67a66dd21e318ae4d475ee0d85c5c1d08 Mon Sep 17 00:00:00 2001
From: Bharath Rupireddy <[email protected]>
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



  [text/plain] v2-0003-Add-checkpoint-and-redo-LSN-to-LogCheckpointEnd-l.txt (2.5K, ../CALj2ACUGutu6As-9p76Ta2bV59J97fbiCc9NSzaWXqxPJdMvag@mail.gmail.com/4-v2-0003-Add-checkpoint-and-redo-LSN-to-LogCheckpointEnd-l.txt)
  download | inline diff:
From 999cfd53ce4e16ccfff94c0022cd80fe8ff84be5 Mon Sep 17 00:00:00 2001
From: Bharath Rupireddy <[email protected]>
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



view thread (15+ messages)  latest in thread

reply

Reply instructions:

You may reply publicly to this message via plain-text email
using any one of the following methods:

* Reply to all the recipients using the --to and --cc options:
  reply via email

  To: [email protected]
  Cc: [email protected], [email protected], [email protected], [email protected], [email protected]
  Subject: Re: Add checkpoint and redo LSN to LogCheckpointEnd log message
  In-Reply-To: <CALj2ACUGutu6As-9p76Ta2bV59J97fbiCc9NSzaWXqxPJdMvag@mail.gmail.com>

* Save the following mbox file, import it into your mail client,
  and reply-to-all from there: mbox

This inbox is served by agora; see mirroring instructions
for how to clone and mirror all data and code used for this inbox