Hi all, This patch is an update after reworking the “checkpoint reason” changes as a standalone patch, separate from the pg_stat_checkpointer additions as suggested [1]. I applied the patch on a clean tree and verified that the logging changes work as expected under different workloads. I am attaching the observations and patch in support for this.This would improve clarity for performance debugging and help understand checkpoint behavior without parsing WAL logs manually. Below is one representative checkpoint log entry after a pgbench run and an explicit CHECKPOINT:
2025-12-01 15:33:30.121 IST [69178] LOG: checkpoint complete (immediate): wrote 3417 buffers (20.9%), wrote 3 SLRU buffers; 0 WAL file(s) added, 0 removed, 1 recycled; write=0.122 s, sync=0.022 s, total=0.166 s; sync files=9, longest=0.005 s, average=0.003 s; distance=31304 kB, estimate=489729 kB; lsn=0/65E92BC8, redo lsn=0/65E92B70 Regarding the pg_stat_checkpointer extensions [1], I understand the concerns that were raised and I will follow up with a separate full patch once I incorporate the remaining feedback. Thank you for the guidance. It has been very helpful. Looking forward to more further feedback. Regards, Soumya Reference [1] https://www.postgresql.org/message-id/flat/CAMtXxw_W6w2Q1QsCvMPnoq3xCMKzH28Zjk_EmL60oP%2BsCTkXOw%40mail.gmail.com
From 4045d7366171a1e512429ac8feb217d8a1199362 Mon Sep 17 00:00:00 2001 From: Soumya <[email protected]> Date: Mon, 1 Dec 2025 16:17:35 +0530 Subject: [PATCH] Expose checkpoint reason to completion log messages Signed-off-by: Soumya <[email protected]> --- src/backend/access/transam/xlog.c | 22 +++++++++++++++++----- 1 file changed, 17 insertions(+), 5 deletions(-) diff --git a/src/backend/access/transam/xlog.c b/src/backend/access/transam/xlog.c index 22d0a2e8c3..f699c79c71 100644 --- a/src/backend/access/transam/xlog.c +++ b/src/backend/access/transam/xlog.c @@ -6750,7 +6750,7 @@ LogCheckpointStart(int flags, bool restartpoint) * Log end of a checkpoint. */ static void -LogCheckpointEnd(bool restartpoint) +LogCheckpointEnd(bool restartpoint, int flags) { long write_msecs, sync_msecs, @@ -6758,6 +6758,16 @@ LogCheckpointEnd(bool restartpoint) longest_msecs, average_msecs; uint64 average_sync_time; + const char *ckpt_reason = "timed"; + /* Determine checkpoint reason */ + if (flags & CHECKPOINT_IS_SHUTDOWN) + ckpt_reason = "shutdown"; + else if (flags & CHECKPOINT_END_OF_RECOVERY) + ckpt_reason = "end-of-recovery"; + else if (flags & CHECKPOINT_FAST) + ckpt_reason = "immediate"; + else if (flags & CHECKPOINT_FORCE) + ckpt_reason = "forced"; CheckpointStats.ckpt_end_t = GetCurrentTimestamp(); @@ -6800,12 +6810,13 @@ LogCheckpointEnd(bool restartpoint) */ if (restartpoint) ereport(LOG, - (errmsg("restartpoint complete: wrote %d buffers (%.1f%%), " + (errmsg("restartpoint complete (%s): wrote %d buffers (%.1f%%), " "wrote %d SLRU buffers; %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=%X/%08X, redo lsn=%X/%08X", + ckpt_reason, CheckpointStats.ckpt_bufs_written, (double) CheckpointStats.ckpt_bufs_written * 100 / NBuffers, CheckpointStats.ckpt_slru_written, @@ -6824,12 +6835,13 @@ LogCheckpointEnd(bool restartpoint) LSN_FORMAT_ARGS(ControlFile->checkPointCopy.redo)))); else ereport(LOG, - (errmsg("checkpoint complete: wrote %d buffers (%.1f%%), " + (errmsg("checkpoint complete (%s): wrote %d buffers (%.1f%%), " "wrote %d SLRU buffers; %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=%X/%08X, redo lsn=%X/%08X", + ckpt_reason, CheckpointStats.ckpt_bufs_written, (double) CheckpointStats.ckpt_bufs_written * 100 / NBuffers, CheckpointStats.ckpt_slru_written, @@ -7418,7 +7430,7 @@ CreateCheckPoint(int flags) TruncateSUBTRANS(GetOldestTransactionIdConsideredRunning()); /* Real work is done; log and update stats. */ - LogCheckpointEnd(false); + LogCheckpointEnd(false, flags); /* Reset the process title */ update_checkpoint_display(flags, false, true); @@ -7886,7 +7898,7 @@ CreateRestartPoint(int flags) TruncateSUBTRANS(GetOldestTransactionIdConsideredRunning()); /* Real work is done; log and update stats. */ - LogCheckpointEnd(true); + LogCheckpointEnd(true, flags); /* Reset the process title */ update_checkpoint_display(flags, true, true); -- 2.34.1
