Add checkpoint and REDO LSN to log_checkpoints message.

It is useful for debugging purposes to report the checkpoint LSN and
REDO LSN in log_checkpoints message. It can give more context while
analyzing checkpoint-related issues. pg_controldata reports the last
checkpoint LSN and REDO LSN, but having this information alongside
the log message helps analyze issues that happened previously,
connect the dots and identify the root cause.

Author: Bharath Rupireddy, Kyotaro Horiguchi
Reviewed-by: Michael Paquier, Julien Rouhaud, Nathan Bossart, Fujii Masao, Greg Stark
Discussion: https://postgr.es/m/CALj2ACWt6kqriAHrO+AJj+OmP=suwbktHT5JoYAn-nqZe2gd2g@mail.gmail.com

diff --git a/src/backend/access/transam/xlog.c b/src/backend/access/transam/xlog.c
index 1b2f24022833733c8023a256f00ea51851f72fc0..b809a2152cc7bbcfddf15d0bfe0c7389d3fd75e5 100644 (file)
--- a/src/backend/access/transam/xlog.c
+++ b/src/backend/access/transam/xlog.c
@@ -6129,13 +6129,19 @@ LogCheckpointEnd(bool restartpoint)
                        CheckpointStats.ckpt_sync_rels;
        average_msecs = (long) ((average_sync_time + 999) / 1000);
 
+       /*
+        * ControlFileLock is not required to see ControlFile->checkPoint and
+        * ->checkPointCopy here as we are the only updator of those variables at
+        * this moment.
+        */
        if (restartpoint)
                ereport(LOG,
                                (errmsg("restartpoint 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,
@@ -6148,14 +6154,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,
@@ -6168,7 +6177,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))));
 }
 
 /*