public inbox for [email protected]
help / color / mirror / Atom feedFrom: Bharath Rupireddy <[email protected]>
To: Kyotaro Horiguchi <[email protected]>
Cc: Bossart, Nathan <[email protected]>
Cc: Julien Rouhaud <[email protected]>
Cc: Michael Paquier <[email protected]>
Cc: PostgreSQL Hackers <[email protected]>
Subject: Re: Add checkpoint and redo LSN to LogCheckpointEnd log message
Date: Fri, 28 Jan 2022 08:43:36 +0530
Message-ID: <CALj2ACUaGJQVbQ5Hms_C2tu+6iJX-EWkEdOiXwX1WfrxQX8pHA@mail.gmail.com> (raw)
In-Reply-To: <[email protected]>
References: <CALj2ACUGutu6As-9p76Ta2bV59J97fbiCc9NSzaWXqxPJdMvag@mail.gmail.com>
<CALj2ACVM4wjS+wiNZf4ssdNMhSR-XUhR99fYbV=pC9_-=5wCtw@mail.gmail.com>
<[email protected]>
<[email protected]>
On Thu, Jan 20, 2022 at 8:30 AM Kyotaro Horiguchi
<[email protected]> wrote:
>
> At Thu, 20 Jan 2022 00:36:32 +0000, "Bossart, Nathan" <[email protected]> wrote in
> > On 1/3/22, 5:52 PM, "Kyotaro Horiguchi" <[email protected]> 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."
>
> +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.
Attachments:
[application/octet-stream] v4-0001-Add-checkpoint-and-redo-LSN-to-LogCheckpointEnd-l.patch (2.4K, ../CALj2ACUaGJQVbQ5Hms_C2tu+6iJX-EWkEdOiXwX1WfrxQX8pHA@mail.gmail.com/2-v4-0001-Add-checkpoint-and-redo-LSN-to-LogCheckpointEnd-l.patch)
download | inline diff:
From f2319df1eba9600c8628910c509757ce5208874f Mon Sep 17 00:00:00 2001
From: Bharath Rupireddy <[email protected]>
Date: Fri, 28 Jan 2022 03:07:07 +0000
Subject: [PATCH v4] 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 | 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 dfe2a0bcce..adecc979c2 100644
--- a/src/backend/access/transam/xlog.c
+++ b/src/backend/access/transam/xlog.c
@@ -8919,11 +8919,14 @@ LogCheckpointEnd(bool restartpoint)
if (restartpoint)
ereport(LOG,
- (errmsg("restartpoint complete: wrote %d buffers (%.1f%%); "
+ (errmsg("restartpoint complete: start=%X/%X, end=%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->checkPointCopy.redo),
+ LSN_FORMAT_ARGS(ControlFile->checkPoint),
CheckpointStats.ckpt_bufs_written,
(double) CheckpointStats.ckpt_bufs_written * 100 / NBuffers,
CheckpointStats.ckpt_segs_added,
@@ -8939,11 +8942,14 @@ LogCheckpointEnd(bool restartpoint)
(int) (CheckPointDistanceEstimate / 1024.0))));
else
ereport(LOG,
- (errmsg("checkpoint complete: wrote %d buffers (%.1f%%); "
+ (errmsg("checkpoint complete: start=%X/%X, end=%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->checkPointCopy.redo),
+ LSN_FORMAT_ARGS(ControlFile->checkPoint),
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], [email protected]
Subject: Re: Add checkpoint and redo LSN to LogCheckpointEnd log message
In-Reply-To: <CALj2ACUaGJQVbQ5Hms_C2tu+6iJX-EWkEdOiXwX1WfrxQX8pHA@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