Hi all, On Tue, Jan 13, 2026 at 6:40 PM Fujii Masao <[email protected]> wrote: > > On Tue, Jan 13, 2026 at 3:29 PM Soumya S Murali > <[email protected]> wrote: > > Thank you for the detailed review and suggestions. > > I have reworked the patch on a fresh tree, addressed the formatting > > and indentation issues, and aligned the helper implementation with > > PostgreSQL coding conventions. The updated patch has been pgindented > > and validated with make check and the full recovery TAP test suite. I > > am attaching the revised patch for further review. > > Thanks for updating the patch! > > With this patch, the checkpoint log messages look like this: > > LOG: checkpoint starting: fast force wait > LOG: checkpoint complete (fast force wait): ... > > The formatting of the checkpoint flags differs between the starting and > complete messages: the complete message wraps them in parentheses, > while the starting message does not. I think it would be better to log > the flags in a consistent way in both messages. For example: > > LOG: checkpoint starting: fast force wait > LOG: checkpoint complete: fast force wait: ... > > > - if ($node_primary->log_contains("checkpoint complete: ", $logstart)) > + if ($node_primary->log_contains(qr/checkpoint complete(?: > \([^)]*\))?:/, $logstart)) > > If we adopt a format like the above example, this test change would > no longer be needed. > > > +#define APPEND_REASON(str) \ > + do \ > + { \ > + if (!first) \ > > Wouldn't it be simpler to just build the string with snprintf() based on > the flags? For example: > > --------------------------------------------------- > static char buf[128]; > > snprintf(buf, sizeof(buf), "%s%s%s%s%s%s%s%s", > (flags & CHECKPOINT_IS_SHUTDOWN) ? " shutdown" : "", > (flags & CHECKPOINT_END_OF_RECOVERY) ? " end-of-recovery" : "", > (flags & CHECKPOINT_FAST) ? " fast" : "", > (flags & CHECKPOINT_FORCE) ? " force" : "", > (flags & CHECKPOINT_WAIT) ? " wait" : "", > (flags & CHECKPOINT_CAUSE_XLOG) ? " wal" : "", > (flags & CHECKPOINT_CAUSE_TIME) ? " time" : "", > (flags & CHECKPOINT_FLUSH_UNLOGGED) ? " flush-unlogged" : ""); > > return buf; > --------------------------------------------------- > > > + * Format checkpoint reason flags consistently for log messages. > + * The returned string is suitable for inclusion after > + * "checkpoint starting:" or inside "checkpoint complete (...)". > + */ > +static const char * > +CheckpointReasonString(int flags) > > These flags include more than just the reason a checkpoint was triggered, > so using "reason" here seems misleading. Wouldn't just "flags" be a better > term? >
Thank you for the detailed review and suggestions. Based on the feedback, I have updated the patch to make the checkpoint and restart point log formatting fully consistent between start and completion log messages. The completion messages now use the same format as the start messages without parentheses. I have also replaced the term "reason" with the term "flags". The patch has been rebuilt and validated with make check and the full recovery TAP test suite, and I have manually verified the resulting log output to confirm the expected formatting. I am attaching the updated patch for further review. Please let me know if any additional adjustments are needed. Regards, Soumya
From 6987dad63e07700bbde9e095516f880719b9c729 Mon Sep 17 00:00:00 2001 From: Soumya <[email protected]> Date: Wed, 14 Jan 2026 15:32:29 +0530 Subject: [PATCH] Expose checkpoint reason in completion log messages Signed-off-by: Soumya <[email protected]> --- src/backend/access/transam/xlog.c | 79 ++++++++++++++++------- src/test/recovery/t/019_replslot_limit.pl | 2 +- 2 files changed, 56 insertions(+), 25 deletions(-) diff --git a/src/backend/access/transam/xlog.c b/src/backend/access/transam/xlog.c index 22d0a2e8c3..881e656f25 100644 --- a/src/backend/access/transam/xlog.c +++ b/src/backend/access/transam/xlog.c @@ -6714,6 +6714,50 @@ ShutdownXLOG(int code, Datum arg) } } +/* + * Format checkpoint reason flags consistently for log messages. + * The returned string is suitable for inclusion after + * "checkpoint starting:" or inside "checkpoint complete (...)". + */ +static const char * +CheckpointFlagsString(int flags) +{ + static char buf[128]; + bool first = true; + + buf[0] = '\0'; + +#define APPEND_REASON(str) \ + do \ + { \ + if (!first) \ + strcat(buf, " "); \ + strcat(buf, (str)); \ + first = false; \ + } while (0) + + if (flags & CHECKPOINT_IS_SHUTDOWN) + APPEND_REASON("shutdown"); + if (flags & CHECKPOINT_END_OF_RECOVERY) + APPEND_REASON("end-of-recovery"); + if (flags & CHECKPOINT_FAST) + APPEND_REASON("fast"); + if (flags & CHECKPOINT_FORCE) + APPEND_REASON("force"); + if (flags & CHECKPOINT_WAIT) + APPEND_REASON("wait"); + if (flags & CHECKPOINT_CAUSE_XLOG) + APPEND_REASON("wal"); + if (flags & CHECKPOINT_CAUSE_TIME) + APPEND_REASON("time"); + if (flags & CHECKPOINT_FLUSH_UNLOGGED) + APPEND_REASON("flush-unlogged"); + +#undef APPEND_REASON + + return buf; +} + /* * Log start of a checkpoint. */ @@ -6723,34 +6767,19 @@ LogCheckpointStart(int flags, bool restartpoint) if (restartpoint) ereport(LOG, /* translator: the placeholders show checkpoint options */ - (errmsg("restartpoint starting:%s%s%s%s%s%s%s%s", - (flags & CHECKPOINT_IS_SHUTDOWN) ? " shutdown" : "", - (flags & CHECKPOINT_END_OF_RECOVERY) ? " end-of-recovery" : "", - (flags & CHECKPOINT_FAST) ? " fast" : "", - (flags & CHECKPOINT_FORCE) ? " force" : "", - (flags & CHECKPOINT_WAIT) ? " wait" : "", - (flags & CHECKPOINT_CAUSE_XLOG) ? " wal" : "", - (flags & CHECKPOINT_CAUSE_TIME) ? " time" : "", - (flags & CHECKPOINT_FLUSH_UNLOGGED) ? " flush-unlogged" : ""))); + (errmsg("restartpoint starting: %s", + CheckpointFlagsString(flags)))); else ereport(LOG, - /* translator: the placeholders show checkpoint options */ - (errmsg("checkpoint starting:%s%s%s%s%s%s%s%s", - (flags & CHECKPOINT_IS_SHUTDOWN) ? " shutdown" : "", - (flags & CHECKPOINT_END_OF_RECOVERY) ? " end-of-recovery" : "", - (flags & CHECKPOINT_FAST) ? " fast" : "", - (flags & CHECKPOINT_FORCE) ? " force" : "", - (flags & CHECKPOINT_WAIT) ? " wait" : "", - (flags & CHECKPOINT_CAUSE_XLOG) ? " wal" : "", - (flags & CHECKPOINT_CAUSE_TIME) ? " time" : "", - (flags & CHECKPOINT_FLUSH_UNLOGGED) ? " flush-unlogged" : ""))); + (errmsg("checkpoint starting: %s", + CheckpointFlagsString(flags)))); } /* * Log end of a checkpoint. */ static void -LogCheckpointEnd(bool restartpoint) +LogCheckpointEnd(bool restartpoint, int flags) { long write_msecs, sync_msecs, @@ -6800,12 +6829,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", + CheckpointFlagsString(flags), CheckpointStats.ckpt_bufs_written, (double) CheckpointStats.ckpt_bufs_written * 100 / NBuffers, CheckpointStats.ckpt_slru_written, @@ -6824,12 +6854,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", + CheckpointFlagsString(flags), CheckpointStats.ckpt_bufs_written, (double) CheckpointStats.ckpt_bufs_written * 100 / NBuffers, CheckpointStats.ckpt_slru_written, @@ -7418,7 +7449,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 +7917,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); diff --git a/src/test/recovery/t/019_replslot_limit.pl b/src/test/recovery/t/019_replslot_limit.pl index 6468784b83..ad2088ef3a 100644 --- a/src/test/recovery/t/019_replslot_limit.pl +++ b/src/test/recovery/t/019_replslot_limit.pl @@ -203,7 +203,7 @@ is($result, "rep1|f|t|lost|", my $checkpoint_ended = 0; for (my $i = 0; $i < 10 * $PostgreSQL::Test::Utils::timeout_default; $i++) { - if ($node_primary->log_contains("checkpoint complete: ", $logstart)) + if ($node_primary->log_contains("checkpoint complete:", $logstart)) { $checkpoint_ended = 1; last; -- 2.34.1
