Re: Add checkpoint and redo LSN to LogCheckpointEnd log message - Mailing list pgsql-hackers

At Wed, 16 Mar 2022 09:19:13 +0900 (JST), Kyotaro Horiguchi <horikyota.ntt@gmail.com> wrote in 
> In short, I split out the two topics other than checkpoint log to
> other threads.

So, this is about the main topic of this thread, adding LSNs to
checkpint log.  Other topics have moved to other treads [1], [2] ,
[3].

I think this is no longer controversial alone.  So this patch is now
really Read-for-Commiter and is waiting to be picked up.

regards.


[1] https://www.postgresql.org/message-id/20220316.102444.2193181487576617583.horikyota.ntt%40gmail.com
[2] https://www.postgresql.org/message-id/20220316.102900.2003692961119672246.horikyota.ntt%40gmail.com
[3] https://www.postgresql.org/message-id/20220316.102509.785466054344164656.horikyota.ntt%40gmail.com

-- 
Kyotaro Horiguchi
NTT Open Source Software Center
From 4c3d40e7aaf29cb905f3561a291d35981d762456 Mon Sep 17 00:00:00 2001
From: Bharath Rupireddy <bharath.rupireddyforpostgres@gmail.com>
Date: Fri, 4 Mar 2022 13:22:41 +0900
Subject: [PATCH v13] 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 | 22 ++++++++++++++++++----
 1 file changed, 18 insertions(+), 4 deletions(-)

diff --git a/src/backend/access/transam/xlog.c b/src/backend/access/transam/xlog.c
index ed16f279b1..b85c76d8f8 100644
--- a/src/backend/access/transam/xlog.c
+++ b/src/backend/access/transam/xlog.c
@@ -6121,7 +6121,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,
@@ -6134,14 +6135,21 @@ 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),
+                        /*
+                         * ControlFileLock is not required as we are the only
+                         * updator of these variables.
+                         */
+                        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,
@@ -6154,7 +6162,13 @@ 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),
+                        /*
+                         * ControlFileLock is not required as we are the only
+                         * updator of these variables.
+                         */
+                        LSN_FORMAT_ARGS(ControlFile->checkPoint),
+                        LSN_FORMAT_ARGS(ControlFile->checkPointCopy.redo))));
 }
 
 /*
-- 
2.27.0