On Thu, Jan 13, 2022 at 11:50 AM Bharath Rupireddy
<bharath.rupireddyforpostg...@gmail.com> wrote:
> 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
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 b6f2a53bcaea2d37e317bc3d9922893c10712d3a Mon Sep 17 00:00:00 2001
From: Bharath Rupireddy <bharath.rupireddyforpostgres@gmail.com>
Date: Fri, 14 Jan 2022 12:55:30 +0000
Subject: [PATCH v3] 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 c9d4cbf3ff..b2eabc72f9 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
