public inbox for [email protected]
help / color / mirror / Atom feedFrom: Bharath Rupireddy <[email protected]>
To: 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: Tue, 28 Dec 2021 08:26:28 +0530
Message-ID: <CALj2ACUP84UYSimewLSs8--rT9dUTA7CUYTgXTnEb-2iHkc9wA@mail.gmail.com> (raw)
In-Reply-To: <CALj2ACXzv6FJNbTnP9uYsPXFeA4UcugSWDecxr19SjFCUCxP-g@mail.gmail.com>
References: <CALj2ACWt6kqriAHrO+AJj+OmP=suwbktHT5JoYAn-nqZe2gd2g@mail.gmail.com>
<[email protected]>
<[email protected]>
<CALj2ACXzv6FJNbTnP9uYsPXFeA4UcugSWDecxr19SjFCUCxP-g@mail.gmail.com>
On Fri, Dec 24, 2021 at 5:54 PM Bharath Rupireddy
<[email protected]> wrote:
>
> On Fri, Dec 24, 2021 at 5:42 PM Michael Paquier <[email protected]> wrote:
> >
> > On Fri, Dec 24, 2021 at 02:51:34PM +0900, Kyotaro Horiguchi wrote:
> > > I thougt about something like the following, but your proposal may be
> > > clearer.
> >
> > + "LSN=%X/%X, REDO LSN=%X/%X",
> > This could be rather confusing for the average user, even if I agree
> > that this is some information that only an advanced user could
> > understand. Could it be possible to define those fields in a more
> > deterministic way? For one, it is hard to understand the relationship
> > between both fields without looking at the code, particulary if both
> > share the same value. It is at least rather.. Well, mostly, easy to
> > guess what each other field means in this context, which is not the
> > case of what you are proposing here. One idea could be use also
> > "start point" for REDO, for example.
>
> How about "location=%X/%X, REDO start location=%X/%X"? The entire log
> message can look like below:
>
> 2021-12-24 12:20:19.140 UTC [1977834] LOG: checkpoint
> complete:location=%X/%X, REDO start location=%X/%X; wrote 7 buffers
> (0.0%); 0 WAL file(s) added, 0 removed, 0 recycled; write=0.005 s,
> sync=0.007 s, total=0.192 s; sync files=5, longest=0.005 s,
> average=0.002 s; distance=293 kB, estimate=56584 kB
>
> Another variant:
> 2021-12-24 12:20:19.140 UTC [1977834] LOG: checkpoint completed at
> location=%X/%X with REDO start location=%X/%X: wrote 7 buffers (0.0%);
> 0 WAL file(s) added, 0 removed, 0 recycled; write=0.005 s, sync=0.007
> s, total=0.192 s; sync files=5, longest=0.005 s, average=0.002 s;
> distance=293 kB, estimate=56584 kB
> 2021-12-24 12:20:19.140 UTC [1977834] LOG: restartpoint completed at
> location=%X/%X with REDO start location=%X/%X: wrote 7 buffers (0.0%);
> 0 WAL file(s) added, 0 removed, 0 recycled; write=0.005 s, sync=0.007
> s, total=0.192 s; sync files=5, longest=0.005 s, average=0.002 s;
> distance=293 kB, estimate=56584 kB
Here are the 2 patches.
one(v2-1-XXX.patch) adding the info as:
2021-12-28 02:44:34.870 UTC [2384386] LOG: checkpoint complete:
location=0/1B03040, REDO start location=0/1B03008; wrote 466 buffers
(2.8%); 0 WAL file(s) added, 0 removed, 0 recycled; write=0.014 s,
sync=0.038 s, total=0.072 s; sync files=21, longest=0.022 s,
average=0.002 s; distance=6346 kB, estimate=6346 kB
another(v2-2-XXX.patch) adding the info as:
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
attaching v1-0001-XXX from the initial mail again just for the sake of
completion:
2021-12-23 14:58:54.714 UTC [1965649] LOG: checkpoint complete: wrote
0 buffers (0.0%); 0 WAL file(s) added, 0 removed, 0 recycled;
write=0.001 s, sync=0.001 s, total=0.025 s; sync files=0,
longest=0.000 s, average=0.000 s; distance=0 kB, estimate=0 kB;
LSN=0/14D0AD0, REDO LSN=0/14D0AD0
Thoughts?
Regards,
Bharath Rupireddy.
Attachments:
[application/octet-stream] v2-1-Add-checkpoint-and-redo-LSN-to-LogCheckpointEnd-l.patch (2.5K, ../CALj2ACUP84UYSimewLSs8--rT9dUTA7CUYTgXTnEb-2iHkc9wA@mail.gmail.com/2-v2-1-Add-checkpoint-and-redo-LSN-to-LogCheckpointEnd-l.patch)
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
[application/octet-stream] v2-2-Add-checkpoint-and-redo-LSN-to-LogCheckpointEnd-l.patch (2.5K, ../CALj2ACUP84UYSimewLSs8--rT9dUTA7CUYTgXTnEb-2iHkc9wA@mail.gmail.com/3-v2-2-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
[application/octet-stream] v1-0001-Add-checkpoint-and-redo-LSN-to-LogCheckpointEnd-l.patch (2.8K, ../CALj2ACUP84UYSimewLSs8--rT9dUTA7CUYTgXTnEb-2iHkc9wA@mail.gmail.com/4-v1-0001-Add-checkpoint-and-redo-LSN-to-LogCheckpointEnd-l.patch)
download | inline diff:
From a641d82e8eb4fa9582a0f83a6f8da5ff468d1710 Mon Sep 17 00:00:00 2001
From: Bharath Rupireddy <[email protected]>
Date: Thu, 23 Dec 2021 15:03:30 +0000
Subject: [PATCH v1] 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 | 14 ++++++++++----
1 file changed, 10 insertions(+), 4 deletions(-)
diff --git a/src/backend/access/transam/xlog.c b/src/backend/access/transam/xlog.c
index 1e1fbe957f..9816f7d328 100644
--- a/src/backend/access/transam/xlog.c
+++ b/src/backend/access/transam/xlog.c
@@ -8924,7 +8924,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,
@@ -8937,14 +8938,17 @@ 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),
+ 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,
@@ -8957,7 +8961,9 @@ 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),
+ LSN_FORMAT_ARGS(ControlFile->checkPoint),
+ LSN_FORMAT_ARGS(ControlFile->checkPointCopy.redo))));
}
/*
--
2.25.1
view thread (17+ 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]
Subject: Re: Add checkpoint and redo LSN to LogCheckpointEnd log message
In-Reply-To: <CALj2ACUP84UYSimewLSs8--rT9dUTA7CUYTgXTnEb-2iHkc9wA@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