agora inbox for [email protected]
help / color / mirror / Atom feed[PATCH v2] Correctly update contfol file at the end of archive recovery
31+ messages / 7 participants
[nested] [flat]
* [PATCH v2] Correctly update contfol file at the end of archive recovery
@ 2022-02-14 04:04 Kyotaro Horiguchi <[email protected]>
0 siblings, 0 replies; 31+ messages in thread
From: Kyotaro Horiguchi @ 2022-02-14 04:04 UTC (permalink / raw)
CreateRestartPoint runs WAL file cleanup basing on the checkpoint just
have finished in the function. If the database has exited
DB_IN_ARCHIVE_RECOVERY state when the function is going to update
control file, the function refrains from updating the file at all then
proceeds to WAL cleanup having the latest REDO LSN, which is now
inconsistent with the control file. As the result, the succeeding
cleanup procedure overly removes WAL files against the control file
and leaves unrecoverable database until the next checkpoint finishes.
Since all buffers have flushed out, we may safely regard that restart
point established regardless of the recovery state. Thus we may and
should update checkpoint LSNs of checkpoint file in that case. Still
we update minRecoveryPoint only during archive recovery but explicitly
clear if we have exited recovery.
Addition to that fix, this commit makes some cosmetic changes that
consist with the changes we are going to make on the master branch.
---
src/backend/access/transam/xlog.c | 81 ++++++++++++++++++++-----------
1 file changed, 53 insertions(+), 28 deletions(-)
diff --git a/src/backend/access/transam/xlog.c b/src/backend/access/transam/xlog.c
index 6208e123e5..28c3c4b7cf 100644
--- a/src/backend/access/transam/xlog.c
+++ b/src/backend/access/transam/xlog.c
@@ -9653,7 +9653,7 @@ CreateRestartPoint(int flags)
/* Also update the info_lck-protected copy */
SpinLockAcquire(&XLogCtl->info_lck);
- XLogCtl->RedoRecPtr = lastCheckPoint.redo;
+ XLogCtl->RedoRecPtr = RedoRecPtr;
SpinLockRelease(&XLogCtl->info_lck);
/*
@@ -9672,7 +9672,10 @@ CreateRestartPoint(int flags)
/* Update the process title */
update_checkpoint_display(flags, true, false);
- CheckPointGuts(lastCheckPoint.redo, flags);
+ CheckPointGuts(RedoRecPtr, flags);
+
+ /* Update pg_control */
+ LWLockAcquire(ControlFileLock, LW_EXCLUSIVE);
/*
* Remember the prior checkpoint's redo ptr for
@@ -9681,52 +9684,74 @@ CreateRestartPoint(int flags)
PriorRedoPtr = ControlFile->checkPointCopy.redo;
/*
- * Update pg_control, using current time. Check that it still shows
- * DB_IN_ARCHIVE_RECOVERY state and an older checkpoint, else do nothing;
- * this is a quick hack to make sure nothing really bad happens if somehow
- * we get here after the end-of-recovery checkpoint.
+ * Update pg_control, using current time if no later checkpoints have been
+ * performed.
*/
- LWLockAcquire(ControlFileLock, LW_EXCLUSIVE);
- if (ControlFile->state == DB_IN_ARCHIVE_RECOVERY &&
- ControlFile->checkPointCopy.redo < lastCheckPoint.redo)
+ if (PriorRedoPtr < RedoRecPtr)
{
ControlFile->checkPoint = lastCheckPointRecPtr;
ControlFile->checkPointCopy = lastCheckPoint;
ControlFile->time = (pg_time_t) time(NULL);
/*
- * Ensure minRecoveryPoint is past the checkpoint record. Normally,
- * this will have happened already while writing out dirty buffers,
- * but not necessarily - e.g. because no buffers were dirtied. We do
- * this because a non-exclusive base backup uses minRecoveryPoint to
- * determine which WAL files must be included in the backup, and the
- * file (or files) containing the checkpoint record must be included,
- * at a minimum. Note that for an ordinary restart of recovery there's
- * no value in having the minimum recovery point any earlier than this
+ * Ensure minRecoveryPoint is past the checkpoint record while archive
+ * recovery is still ongoing. Normally, this will have happened
+ * already while writing out dirty buffers, but not necessarily -
+ * e.g. because no buffers were dirtied. We do this because a
+ * non-exclusive base backup uses minRecoveryPoint to determine which
+ * WAL files must be included in the backup, and the file (or files)
+ * containing the checkpoint record must be included, at a
+ * minimum. Note that for an ordinary restart of recovery there's no
+ * value in having the minimum recovery point any earlier than this
* anyway, because redo will begin just after the checkpoint record.
+ * This is a quick hack to make sure nothing really bad happens if
+ * somehow we get here after the end-of-recovery checkpoint.
*/
- if (ControlFile->minRecoveryPoint < lastCheckPointEndPtr)
+ if (ControlFile->state == DB_IN_ARCHIVE_RECOVERY)
{
- ControlFile->minRecoveryPoint = lastCheckPointEndPtr;
- ControlFile->minRecoveryPointTLI = lastCheckPoint.ThisTimeLineID;
+ if (ControlFile->minRecoveryPoint < lastCheckPointEndPtr)
+ {
+ ControlFile->minRecoveryPoint = lastCheckPointEndPtr;
+ ControlFile->minRecoveryPointTLI = lastCheckPoint.ThisTimeLineID;
- /* update local copy */
- minRecoveryPoint = ControlFile->minRecoveryPoint;
- minRecoveryPointTLI = ControlFile->minRecoveryPointTLI;
+ /* update local copy */
+ minRecoveryPoint = ControlFile->minRecoveryPoint;
+ minRecoveryPointTLI = ControlFile->minRecoveryPointTLI;
+ }
+ if (flags & CHECKPOINT_IS_SHUTDOWN)
+ ControlFile->state = DB_SHUTDOWNED_IN_RECOVERY;
}
- if (flags & CHECKPOINT_IS_SHUTDOWN)
- ControlFile->state = DB_SHUTDOWNED_IN_RECOVERY;
+ else
+ {
+ /*
+ * Aarchive recovery has ended. Crash recovery ever after should
+ * always recover to the end of WAL
+ */
+ ControlFile->minRecoveryPoint = InvalidXLogRecPtr;
+ ControlFile->minRecoveryPointTLI = 0;
+ }
+
UpdateControlFile();
}
LWLockRelease(ControlFileLock);
/*
* Update the average distance between checkpoints/restartpoints if the
- * prior checkpoint exists.
+ * prior checkpoint exists and we have advanced REDO LSN.
*/
- if (PriorRedoPtr != InvalidXLogRecPtr)
+ if (PriorRedoPtr != InvalidXLogRecPtr && RedoRecPtr > PriorRedoPtr)
UpdateCheckPointDistanceEstimate(RedoRecPtr - PriorRedoPtr);
+ /*
+ * Now we can safely regard this restart point as established.
+ *
+ * Since all buffers have been flushed so we regard this restart point as
+ * established. We could omit some of the following steps in the case
+ * where we have omitted control file updates, but we don't bother avoid
+ * them from performing since that case rarely happens and they don't harm
+ * even if they take place.
+ */
+
/*
* Delete old log files, those no longer needed for last restartpoint to
* prevent the disk holding the xlog from growing full.
@@ -9804,7 +9829,7 @@ CreateRestartPoint(int flags)
xtime = GetLatestXTime();
ereport((log_checkpoints ? LOG : DEBUG2),
(errmsg("recovery restart point at %X/%X",
- LSN_FORMAT_ARGS(lastCheckPoint.redo)),
+ LSN_FORMAT_ARGS(RedoRecPtr)),
xtime ? errdetail("Last completed transaction was at log time %s.",
timestamptz_to_str(xtime)) : 0));
--
2.27.0
----Next_Part(Mon_Feb_14_14_40_22_2022_983)----
^ permalink raw reply [nested|flat] 31+ messages in thread
* [PATCH v2] Correctly update contfol file at the end of archive recovery
@ 2022-02-14 04:04 Kyotaro Horiguchi <[email protected]>
0 siblings, 0 replies; 31+ messages in thread
From: Kyotaro Horiguchi @ 2022-02-14 04:04 UTC (permalink / raw)
CreateRestartPoint runs WAL file cleanup basing on the checkpoint just
have finished in the function. If the database has exited
DB_IN_ARCHIVE_RECOVERY state when the function is going to update
control file, the function refrains from updating the file at all then
proceeds to WAL cleanup having the latest REDO LSN, which is now
inconsistent with the control file. As the result, the succeeding
cleanup procedure overly removes WAL files against the control file
and leaves unrecoverable database until the next checkpoint finishes.
Along with that fix, we remove a dead code path for the case some
other process ran a simultaneous checkpoint. It seems like just a
preventive measure but it's no longer useful because we are sure that
checkpoint is performed only by checkpointer except single process
mode.
---
src/backend/access/transam/xlog.c | 73 ++++++++++++++++++++-----------
1 file changed, 47 insertions(+), 26 deletions(-)
diff --git a/src/backend/access/transam/xlog.c b/src/backend/access/transam/xlog.c
index 6208e123e5..ff4a90eacc 100644
--- a/src/backend/access/transam/xlog.c
+++ b/src/backend/access/transam/xlog.c
@@ -9587,6 +9587,9 @@ CreateRestartPoint(int flags)
XLogSegNo _logSegNo;
TimestampTz xtime;
+ /* we don't assume concurrent checkpoint/restartpoint to run */
+ Assert (!IsUnderPostmaster || MyBackendType == B_CHECKPOINTER);
+
/* Get a local copy of the last safe checkpoint record. */
SpinLockAcquire(&XLogCtl->info_lck);
lastCheckPointRecPtr = XLogCtl->lastCheckPointRecPtr;
@@ -9653,7 +9656,7 @@ CreateRestartPoint(int flags)
/* Also update the info_lck-protected copy */
SpinLockAcquire(&XLogCtl->info_lck);
- XLogCtl->RedoRecPtr = lastCheckPoint.redo;
+ XLogCtl->RedoRecPtr = RedoRecPtr;
SpinLockRelease(&XLogCtl->info_lck);
/*
@@ -9672,7 +9675,10 @@ CreateRestartPoint(int flags)
/* Update the process title */
update_checkpoint_display(flags, true, false);
- CheckPointGuts(lastCheckPoint.redo, flags);
+ CheckPointGuts(RedoRecPtr, flags);
+
+ /* Update pg_control */
+ LWLockAcquire(ControlFileLock, LW_EXCLUSIVE);
/*
* Remember the prior checkpoint's redo ptr for
@@ -9680,31 +9686,29 @@ CreateRestartPoint(int flags)
*/
PriorRedoPtr = ControlFile->checkPointCopy.redo;
+ Assert (PriorRedoPtr < RedoRecPtr);
+
+ ControlFile->checkPoint = lastCheckPointRecPtr;
+ ControlFile->checkPointCopy = lastCheckPoint;
+
+ /* Update control file using current time */
+ ControlFile->time = (pg_time_t) time(NULL);
+
/*
- * Update pg_control, using current time. Check that it still shows
- * DB_IN_ARCHIVE_RECOVERY state and an older checkpoint, else do nothing;
- * this is a quick hack to make sure nothing really bad happens if somehow
- * we get here after the end-of-recovery checkpoint.
+ * Ensure minRecoveryPoint is past the checkpoint record while archive
+ * recovery is still ongoing. Normally, this will have happened already
+ * while writing out dirty buffers, but not necessarily - e.g. because no
+ * buffers were dirtied. We do this because a non-exclusive base backup
+ * uses minRecoveryPoint to determine which WAL files must be included in
+ * the backup, and the file (or files) containing the checkpoint record
+ * must be included, at a minimum. Note that for an ordinary restart of
+ * recovery there's no value in having the minimum recovery point any
+ * earlier than this anyway, because redo will begin just after the
+ * checkpoint record. This is a quick hack to make sure nothing really bad
+ * happens if somehow we get here after the end-of-recovery checkpoint.
*/
- LWLockAcquire(ControlFileLock, LW_EXCLUSIVE);
- if (ControlFile->state == DB_IN_ARCHIVE_RECOVERY &&
- ControlFile->checkPointCopy.redo < lastCheckPoint.redo)
+ if (ControlFile->state == DB_IN_ARCHIVE_RECOVERY)
{
- ControlFile->checkPoint = lastCheckPointRecPtr;
- ControlFile->checkPointCopy = lastCheckPoint;
- ControlFile->time = (pg_time_t) time(NULL);
-
- /*
- * Ensure minRecoveryPoint is past the checkpoint record. Normally,
- * this will have happened already while writing out dirty buffers,
- * but not necessarily - e.g. because no buffers were dirtied. We do
- * this because a non-exclusive base backup uses minRecoveryPoint to
- * determine which WAL files must be included in the backup, and the
- * file (or files) containing the checkpoint record must be included,
- * at a minimum. Note that for an ordinary restart of recovery there's
- * no value in having the minimum recovery point any earlier than this
- * anyway, because redo will begin just after the checkpoint record.
- */
if (ControlFile->minRecoveryPoint < lastCheckPointEndPtr)
{
ControlFile->minRecoveryPoint = lastCheckPointEndPtr;
@@ -9716,8 +9720,25 @@ CreateRestartPoint(int flags)
}
if (flags & CHECKPOINT_IS_SHUTDOWN)
ControlFile->state = DB_SHUTDOWNED_IN_RECOVERY;
- UpdateControlFile();
}
+ else
+ {
+ /* recovery mode is not supposed to end during shutdown restartpoint */
+ Assert((flags & CHECKPOINT_IS_SHUTDOWN) == 0);
+
+ /*
+ * Aarchive recovery has ended. Crash recovery ever after should
+ * always recover to the end of WAL
+ */
+ ControlFile->minRecoveryPoint = InvalidXLogRecPtr;
+ ControlFile->minRecoveryPointTLI = 0;
+
+ /* also update local copy */
+ minRecoveryPoint = InvalidXLogRecPtr;
+ minRecoveryPointTLI = 0;
+ }
+
+ UpdateControlFile();
LWLockRelease(ControlFileLock);
/*
@@ -9804,7 +9825,7 @@ CreateRestartPoint(int flags)
xtime = GetLatestXTime();
ereport((log_checkpoints ? LOG : DEBUG2),
(errmsg("recovery restart point at %X/%X",
- LSN_FORMAT_ARGS(lastCheckPoint.redo)),
+ LSN_FORMAT_ARGS(RedoRecPtr)),
xtime ? errdetail("Last completed transaction was at log time %s.",
timestamptz_to_str(xtime)) : 0));
--
2.27.0
----Next_Part(Fri_Feb_25_15_31_12_2022_240)--
Content-Type: Text/Plain; charset=us-ascii
Content-Transfer-Encoding: 7bit
Content-Disposition: inline;
filename="v3-0001-Correctly-update-contfol-file-at-the-end-of_v13.txt"
^ permalink raw reply [nested|flat] 31+ messages in thread
* [PATCH v2] Correctly update contfol file at the end of archive recovery
@ 2022-02-14 04:04 Kyotaro Horiguchi <[email protected]>
0 siblings, 0 replies; 31+ messages in thread
From: Kyotaro Horiguchi @ 2022-02-14 04:04 UTC (permalink / raw)
CreateRestartPoint runs WAL file cleanup basing on the checkpoint just
have finished in the function. If the database has exited
DB_IN_ARCHIVE_RECOVERY state when the function is going to update
control file, the function refrains from updating the file at all then
proceeds to WAL cleanup having the latest REDO LSN, which is now
inconsistent with the control file. As the result, the succeeding
cleanup procedure overly removes WAL files against the control file
and leaves unrecoverable database until the next checkpoint finishes.
Along with that fix, we remove a dead code path for the case some
other process ran a simultaneous checkpoint. It seems like just a
preventive measure but it's no longer useful because we are sure that
checkpoint is performed only by checkpointer except single process
mode.
---
src/backend/access/transam/xlog.c | 73 ++++++++++++++++++++-----------
1 file changed, 47 insertions(+), 26 deletions(-)
diff --git a/src/backend/access/transam/xlog.c b/src/backend/access/transam/xlog.c
index 6208e123e5..ff4a90eacc 100644
--- a/src/backend/access/transam/xlog.c
+++ b/src/backend/access/transam/xlog.c
@@ -9587,6 +9587,9 @@ CreateRestartPoint(int flags)
XLogSegNo _logSegNo;
TimestampTz xtime;
+ /* we don't assume concurrent checkpoint/restartpoint to run */
+ Assert (!IsUnderPostmaster || MyBackendType == B_CHECKPOINTER);
+
/* Get a local copy of the last safe checkpoint record. */
SpinLockAcquire(&XLogCtl->info_lck);
lastCheckPointRecPtr = XLogCtl->lastCheckPointRecPtr;
@@ -9653,7 +9656,7 @@ CreateRestartPoint(int flags)
/* Also update the info_lck-protected copy */
SpinLockAcquire(&XLogCtl->info_lck);
- XLogCtl->RedoRecPtr = lastCheckPoint.redo;
+ XLogCtl->RedoRecPtr = RedoRecPtr;
SpinLockRelease(&XLogCtl->info_lck);
/*
@@ -9672,7 +9675,10 @@ CreateRestartPoint(int flags)
/* Update the process title */
update_checkpoint_display(flags, true, false);
- CheckPointGuts(lastCheckPoint.redo, flags);
+ CheckPointGuts(RedoRecPtr, flags);
+
+ /* Update pg_control */
+ LWLockAcquire(ControlFileLock, LW_EXCLUSIVE);
/*
* Remember the prior checkpoint's redo ptr for
@@ -9680,31 +9686,29 @@ CreateRestartPoint(int flags)
*/
PriorRedoPtr = ControlFile->checkPointCopy.redo;
+ Assert (PriorRedoPtr < RedoRecPtr);
+
+ ControlFile->checkPoint = lastCheckPointRecPtr;
+ ControlFile->checkPointCopy = lastCheckPoint;
+
+ /* Update control file using current time */
+ ControlFile->time = (pg_time_t) time(NULL);
+
/*
- * Update pg_control, using current time. Check that it still shows
- * DB_IN_ARCHIVE_RECOVERY state and an older checkpoint, else do nothing;
- * this is a quick hack to make sure nothing really bad happens if somehow
- * we get here after the end-of-recovery checkpoint.
+ * Ensure minRecoveryPoint is past the checkpoint record while archive
+ * recovery is still ongoing. Normally, this will have happened already
+ * while writing out dirty buffers, but not necessarily - e.g. because no
+ * buffers were dirtied. We do this because a non-exclusive base backup
+ * uses minRecoveryPoint to determine which WAL files must be included in
+ * the backup, and the file (or files) containing the checkpoint record
+ * must be included, at a minimum. Note that for an ordinary restart of
+ * recovery there's no value in having the minimum recovery point any
+ * earlier than this anyway, because redo will begin just after the
+ * checkpoint record. This is a quick hack to make sure nothing really bad
+ * happens if somehow we get here after the end-of-recovery checkpoint.
*/
- LWLockAcquire(ControlFileLock, LW_EXCLUSIVE);
- if (ControlFile->state == DB_IN_ARCHIVE_RECOVERY &&
- ControlFile->checkPointCopy.redo < lastCheckPoint.redo)
+ if (ControlFile->state == DB_IN_ARCHIVE_RECOVERY)
{
- ControlFile->checkPoint = lastCheckPointRecPtr;
- ControlFile->checkPointCopy = lastCheckPoint;
- ControlFile->time = (pg_time_t) time(NULL);
-
- /*
- * Ensure minRecoveryPoint is past the checkpoint record. Normally,
- * this will have happened already while writing out dirty buffers,
- * but not necessarily - e.g. because no buffers were dirtied. We do
- * this because a non-exclusive base backup uses minRecoveryPoint to
- * determine which WAL files must be included in the backup, and the
- * file (or files) containing the checkpoint record must be included,
- * at a minimum. Note that for an ordinary restart of recovery there's
- * no value in having the minimum recovery point any earlier than this
- * anyway, because redo will begin just after the checkpoint record.
- */
if (ControlFile->minRecoveryPoint < lastCheckPointEndPtr)
{
ControlFile->minRecoveryPoint = lastCheckPointEndPtr;
@@ -9716,8 +9720,25 @@ CreateRestartPoint(int flags)
}
if (flags & CHECKPOINT_IS_SHUTDOWN)
ControlFile->state = DB_SHUTDOWNED_IN_RECOVERY;
- UpdateControlFile();
}
+ else
+ {
+ /* recovery mode is not supposed to end during shutdown restartpoint */
+ Assert((flags & CHECKPOINT_IS_SHUTDOWN) == 0);
+
+ /*
+ * Aarchive recovery has ended. Crash recovery ever after should
+ * always recover to the end of WAL
+ */
+ ControlFile->minRecoveryPoint = InvalidXLogRecPtr;
+ ControlFile->minRecoveryPointTLI = 0;
+
+ /* also update local copy */
+ minRecoveryPoint = InvalidXLogRecPtr;
+ minRecoveryPointTLI = 0;
+ }
+
+ UpdateControlFile();
LWLockRelease(ControlFileLock);
/*
@@ -9804,7 +9825,7 @@ CreateRestartPoint(int flags)
xtime = GetLatestXTime();
ereport((log_checkpoints ? LOG : DEBUG2),
(errmsg("recovery restart point at %X/%X",
- LSN_FORMAT_ARGS(lastCheckPoint.redo)),
+ LSN_FORMAT_ARGS(RedoRecPtr)),
xtime ? errdetail("Last completed transaction was at log time %s.",
timestamptz_to_str(xtime)) : 0));
--
2.27.0
----Next_Part(Wed_Mar_16_10_24_44_2022_775)--
Content-Type: Text/Plain; charset=us-ascii
Content-Transfer-Encoding: 7bit
Content-Disposition: inline;
filename="v4-0001-Correctly-update-contfol-file-at-the-end-of_v13.txt"
^ permalink raw reply [nested|flat] 31+ messages in thread
* [PATCH v2] Correctly update contfol file at the end of archive recovery
@ 2022-02-25 05:46 Kyotaro Horiguchi <[email protected]>
0 siblings, 0 replies; 31+ messages in thread
From: Kyotaro Horiguchi @ 2022-02-25 05:46 UTC (permalink / raw)
CreateRestartPoint runs WAL file cleanup basing on the checkpoint just
have finished in the function. If the database has exited
DB_IN_ARCHIVE_RECOVERY state when the function is going to update
control file, the function refrains from updating the file at all then
proceeds to WAL cleanup having the latest REDO LSN, which is now
inconsistent with the control file. As the result, the succeeding
cleanup procedure overly removes WAL files against the control file
and leaves unrecoverable database until the next checkpoint finishes.
Along with that fix, we remove a dead code path for the case some
other process ran a simultaneous checkpoint. It seems like just a
preventive measure but it's no longer useful because we are sure that
checkpoint is performed only by checkpointer except single process
mode.
---
src/backend/access/transam/xlog.c | 73 ++++++++++++++++++++-----------
1 file changed, 47 insertions(+), 26 deletions(-)
diff --git a/src/backend/access/transam/xlog.c b/src/backend/access/transam/xlog.c
index 3d76fad128..3670ff81e7 100644
--- a/src/backend/access/transam/xlog.c
+++ b/src/backend/access/transam/xlog.c
@@ -9376,6 +9376,9 @@ CreateRestartPoint(int flags)
*/
LWLockAcquire(CheckpointLock, LW_EXCLUSIVE);
+ /* we don't assume concurrent checkpoint/restartpoint to run */
+ Assert (!IsUnderPostmaster || MyBackendType == B_CHECKPOINTER);
+
/* Get a local copy of the last safe checkpoint record. */
SpinLockAcquire(&XLogCtl->info_lck);
lastCheckPointRecPtr = XLogCtl->lastCheckPointRecPtr;
@@ -9445,7 +9448,7 @@ CreateRestartPoint(int flags)
/* Also update the info_lck-protected copy */
SpinLockAcquire(&XLogCtl->info_lck);
- XLogCtl->RedoRecPtr = lastCheckPoint.redo;
+ XLogCtl->RedoRecPtr = RedoRecPtr;
SpinLockRelease(&XLogCtl->info_lck);
/*
@@ -9461,7 +9464,10 @@ CreateRestartPoint(int flags)
if (log_checkpoints)
LogCheckpointStart(flags, true);
- CheckPointGuts(lastCheckPoint.redo, flags);
+ CheckPointGuts(RedoRecPtr, flags);
+
+ /* Update pg_control */
+ LWLockAcquire(ControlFileLock, LW_EXCLUSIVE);
/*
* Remember the prior checkpoint's redo ptr for
@@ -9469,31 +9475,29 @@ CreateRestartPoint(int flags)
*/
PriorRedoPtr = ControlFile->checkPointCopy.redo;
+ Assert (PriorRedoPtr < RedoRecPtr);
+
+ ControlFile->checkPoint = lastCheckPointRecPtr;
+ ControlFile->checkPointCopy = lastCheckPoint;
+
+ /* Update control file using current time */
+ ControlFile->time = (pg_time_t) time(NULL);
+
/*
- * Update pg_control, using current time. Check that it still shows
- * DB_IN_ARCHIVE_RECOVERY state and an older checkpoint, else do nothing;
- * this is a quick hack to make sure nothing really bad happens if somehow
- * we get here after the end-of-recovery checkpoint.
+ * Ensure minRecoveryPoint is past the checkpoint record while archive
+ * recovery is still ongoing. Normally, this will have happened already
+ * while writing out dirty buffers, but not necessarily - e.g. because no
+ * buffers were dirtied. We do this because a non-exclusive base backup
+ * uses minRecoveryPoint to determine which WAL files must be included in
+ * the backup, and the file (or files) containing the checkpoint record
+ * must be included, at a minimum. Note that for an ordinary restart of
+ * recovery there's no value in having the minimum recovery point any
+ * earlier than this anyway, because redo will begin just after the
+ * checkpoint record. This is a quick hack to make sure nothing really bad
+ * happens if somehow we get here after the end-of-recovery checkpoint.
*/
- LWLockAcquire(ControlFileLock, LW_EXCLUSIVE);
- if (ControlFile->state == DB_IN_ARCHIVE_RECOVERY &&
- ControlFile->checkPointCopy.redo < lastCheckPoint.redo)
+ if (ControlFile->state == DB_IN_ARCHIVE_RECOVERY)
{
- ControlFile->checkPoint = lastCheckPointRecPtr;
- ControlFile->checkPointCopy = lastCheckPoint;
- ControlFile->time = (pg_time_t) time(NULL);
-
- /*
- * Ensure minRecoveryPoint is past the checkpoint record. Normally,
- * this will have happened already while writing out dirty buffers,
- * but not necessarily - e.g. because no buffers were dirtied. We do
- * this because a non-exclusive base backup uses minRecoveryPoint to
- * determine which WAL files must be included in the backup, and the
- * file (or files) containing the checkpoint record must be included,
- * at a minimum. Note that for an ordinary restart of recovery there's
- * no value in having the minimum recovery point any earlier than this
- * anyway, because redo will begin just after the checkpoint record.
- */
if (ControlFile->minRecoveryPoint < lastCheckPointEndPtr)
{
ControlFile->minRecoveryPoint = lastCheckPointEndPtr;
@@ -9505,8 +9509,25 @@ CreateRestartPoint(int flags)
}
if (flags & CHECKPOINT_IS_SHUTDOWN)
ControlFile->state = DB_SHUTDOWNED_IN_RECOVERY;
- UpdateControlFile();
}
+ else
+ {
+ /* recovery mode is not supposed to end during shutdown restartpoint */
+ Assert((flags & CHECKPOINT_IS_SHUTDOWN) == 0);
+
+ /*
+ * Aarchive recovery has ended. Crash recovery ever after should
+ * always recover to the end of WAL
+ */
+ ControlFile->minRecoveryPoint = InvalidXLogRecPtr;
+ ControlFile->minRecoveryPointTLI = 0;
+
+ /* also update local copy */
+ minRecoveryPoint = InvalidXLogRecPtr;
+ minRecoveryPointTLI = 0;
+ }
+
+ UpdateControlFile();
LWLockRelease(ControlFileLock);
/*
@@ -9590,7 +9611,7 @@ CreateRestartPoint(int flags)
xtime = GetLatestXTime();
ereport((log_checkpoints ? LOG : DEBUG2),
(errmsg("recovery restart point at %X/%X",
- (uint32) (lastCheckPoint.redo >> 32), (uint32) lastCheckPoint.redo),
+ (uint32) (RedoRecPtr >> 32), (uint32) RedoRecPtr),
xtime ? errdetail("Last completed transaction was at log time %s.",
timestamptz_to_str(xtime)) : 0));
--
2.27.0
----Next_Part(Fri_Feb_25_15_31_12_2022_240)----
^ permalink raw reply [nested|flat] 31+ messages in thread
* [PATCH v2] Correctly update contfol file at the end of archive recovery
@ 2022-02-25 05:46 Kyotaro Horiguchi <[email protected]>
0 siblings, 0 replies; 31+ messages in thread
From: Kyotaro Horiguchi @ 2022-02-25 05:46 UTC (permalink / raw)
CreateRestartPoint runs WAL file cleanup basing on the checkpoint just
have finished in the function. If the database has exited
DB_IN_ARCHIVE_RECOVERY state when the function is going to update
control file, the function refrains from updating the file at all then
proceeds to WAL cleanup having the latest REDO LSN, which is now
inconsistent with the control file. As the result, the succeeding
cleanup procedure overly removes WAL files against the control file
and leaves unrecoverable database until the next checkpoint finishes.
Along with that fix, we remove a dead code path for the case some
other process ran a simultaneous checkpoint. It seems like just a
preventive measure but it's no longer useful because we are sure that
checkpoint is performed only by checkpointer except single process
mode.
---
src/backend/access/transam/xlog.c | 73 ++++++++++++++++++++-----------
1 file changed, 47 insertions(+), 26 deletions(-)
diff --git a/src/backend/access/transam/xlog.c b/src/backend/access/transam/xlog.c
index 3d76fad128..3670ff81e7 100644
--- a/src/backend/access/transam/xlog.c
+++ b/src/backend/access/transam/xlog.c
@@ -9376,6 +9376,9 @@ CreateRestartPoint(int flags)
*/
LWLockAcquire(CheckpointLock, LW_EXCLUSIVE);
+ /* we don't assume concurrent checkpoint/restartpoint to run */
+ Assert (!IsUnderPostmaster || MyBackendType == B_CHECKPOINTER);
+
/* Get a local copy of the last safe checkpoint record. */
SpinLockAcquire(&XLogCtl->info_lck);
lastCheckPointRecPtr = XLogCtl->lastCheckPointRecPtr;
@@ -9445,7 +9448,7 @@ CreateRestartPoint(int flags)
/* Also update the info_lck-protected copy */
SpinLockAcquire(&XLogCtl->info_lck);
- XLogCtl->RedoRecPtr = lastCheckPoint.redo;
+ XLogCtl->RedoRecPtr = RedoRecPtr;
SpinLockRelease(&XLogCtl->info_lck);
/*
@@ -9461,7 +9464,10 @@ CreateRestartPoint(int flags)
if (log_checkpoints)
LogCheckpointStart(flags, true);
- CheckPointGuts(lastCheckPoint.redo, flags);
+ CheckPointGuts(RedoRecPtr, flags);
+
+ /* Update pg_control */
+ LWLockAcquire(ControlFileLock, LW_EXCLUSIVE);
/*
* Remember the prior checkpoint's redo ptr for
@@ -9469,31 +9475,29 @@ CreateRestartPoint(int flags)
*/
PriorRedoPtr = ControlFile->checkPointCopy.redo;
+ Assert (PriorRedoPtr < RedoRecPtr);
+
+ ControlFile->checkPoint = lastCheckPointRecPtr;
+ ControlFile->checkPointCopy = lastCheckPoint;
+
+ /* Update control file using current time */
+ ControlFile->time = (pg_time_t) time(NULL);
+
/*
- * Update pg_control, using current time. Check that it still shows
- * DB_IN_ARCHIVE_RECOVERY state and an older checkpoint, else do nothing;
- * this is a quick hack to make sure nothing really bad happens if somehow
- * we get here after the end-of-recovery checkpoint.
+ * Ensure minRecoveryPoint is past the checkpoint record while archive
+ * recovery is still ongoing. Normally, this will have happened already
+ * while writing out dirty buffers, but not necessarily - e.g. because no
+ * buffers were dirtied. We do this because a non-exclusive base backup
+ * uses minRecoveryPoint to determine which WAL files must be included in
+ * the backup, and the file (or files) containing the checkpoint record
+ * must be included, at a minimum. Note that for an ordinary restart of
+ * recovery there's no value in having the minimum recovery point any
+ * earlier than this anyway, because redo will begin just after the
+ * checkpoint record. This is a quick hack to make sure nothing really bad
+ * happens if somehow we get here after the end-of-recovery checkpoint.
*/
- LWLockAcquire(ControlFileLock, LW_EXCLUSIVE);
- if (ControlFile->state == DB_IN_ARCHIVE_RECOVERY &&
- ControlFile->checkPointCopy.redo < lastCheckPoint.redo)
+ if (ControlFile->state == DB_IN_ARCHIVE_RECOVERY)
{
- ControlFile->checkPoint = lastCheckPointRecPtr;
- ControlFile->checkPointCopy = lastCheckPoint;
- ControlFile->time = (pg_time_t) time(NULL);
-
- /*
- * Ensure minRecoveryPoint is past the checkpoint record. Normally,
- * this will have happened already while writing out dirty buffers,
- * but not necessarily - e.g. because no buffers were dirtied. We do
- * this because a non-exclusive base backup uses minRecoveryPoint to
- * determine which WAL files must be included in the backup, and the
- * file (or files) containing the checkpoint record must be included,
- * at a minimum. Note that for an ordinary restart of recovery there's
- * no value in having the minimum recovery point any earlier than this
- * anyway, because redo will begin just after the checkpoint record.
- */
if (ControlFile->minRecoveryPoint < lastCheckPointEndPtr)
{
ControlFile->minRecoveryPoint = lastCheckPointEndPtr;
@@ -9505,8 +9509,25 @@ CreateRestartPoint(int flags)
}
if (flags & CHECKPOINT_IS_SHUTDOWN)
ControlFile->state = DB_SHUTDOWNED_IN_RECOVERY;
- UpdateControlFile();
}
+ else
+ {
+ /* recovery mode is not supposed to end during shutdown restartpoint */
+ Assert((flags & CHECKPOINT_IS_SHUTDOWN) == 0);
+
+ /*
+ * Aarchive recovery has ended. Crash recovery ever after should
+ * always recover to the end of WAL
+ */
+ ControlFile->minRecoveryPoint = InvalidXLogRecPtr;
+ ControlFile->minRecoveryPointTLI = 0;
+
+ /* also update local copy */
+ minRecoveryPoint = InvalidXLogRecPtr;
+ minRecoveryPointTLI = 0;
+ }
+
+ UpdateControlFile();
LWLockRelease(ControlFileLock);
/*
@@ -9590,7 +9611,7 @@ CreateRestartPoint(int flags)
xtime = GetLatestXTime();
ereport((log_checkpoints ? LOG : DEBUG2),
(errmsg("recovery restart point at %X/%X",
- (uint32) (lastCheckPoint.redo >> 32), (uint32) lastCheckPoint.redo),
+ (uint32) (RedoRecPtr >> 32), (uint32) RedoRecPtr),
xtime ? errdetail("Last completed transaction was at log time %s.",
timestamptz_to_str(xtime)) : 0));
--
2.27.0
----Next_Part(Wed_Mar_16_10_24_44_2022_775)--
Content-Type: Text/Plain; charset=us-ascii
Content-Transfer-Encoding: 7bit
Content-Disposition: inline;
filename="v4-0001-Correctly-update-contfol-file-at-the-end-of_v12-11.txt"
^ permalink raw reply [nested|flat] 31+ messages in thread
* [PATCH v3] Correctly update contfol file at the end of archive recovery
@ 2022-02-25 06:04 Kyotaro Horiguchi <[email protected]>
0 siblings, 0 replies; 31+ messages in thread
From: Kyotaro Horiguchi @ 2022-02-25 06:04 UTC (permalink / raw)
CreateRestartPoint runs WAL file cleanup basing on the checkpoint just
have finished in the function. If the database has exited
DB_IN_ARCHIVE_RECOVERY state when the function is going to update
control file, the function refrains from updating the file at all then
proceeds to WAL cleanup having the latest REDO LSN, which is now
inconsistent with the control file. As the result, the succeeding
cleanup procedure overly removes WAL files against the control file
and leaves unrecoverable database until the next checkpoint finishes.
Along with that fix, we remove a dead code path for the case some
other process ran a simultaneous checkpoint. It seems like just a
preventive measure but it's no longer useful because we are sure that
checkpoint is performed only by checkpointer except single process
mode.
---
src/backend/access/transam/xlog.c | 71 +++++++++++++++++++------------
1 file changed, 44 insertions(+), 27 deletions(-)
diff --git a/src/backend/access/transam/xlog.c b/src/backend/access/transam/xlog.c
index 885558f291..2b2568c475 100644
--- a/src/backend/access/transam/xlog.c
+++ b/src/backend/access/transam/xlog.c
@@ -9334,7 +9334,7 @@ CreateRestartPoint(int flags)
/* Also update the info_lck-protected copy */
SpinLockAcquire(&XLogCtl->info_lck);
- XLogCtl->RedoRecPtr = lastCheckPoint.redo;
+ XLogCtl->RedoRecPtr = RedoRecPtr;
SpinLockRelease(&XLogCtl->info_lck);
/*
@@ -9350,7 +9350,10 @@ CreateRestartPoint(int flags)
if (log_checkpoints)
LogCheckpointStart(flags, true);
- CheckPointGuts(lastCheckPoint.redo, flags);
+ CheckPointGuts(RedoRecPtr, flags);
+
+ /* Update pg_control */
+ LWLockAcquire(ControlFileLock, LW_EXCLUSIVE);
/*
* Remember the prior checkpoint's redo ptr for
@@ -9358,31 +9361,28 @@ CreateRestartPoint(int flags)
*/
PriorRedoPtr = ControlFile->checkPointCopy.redo;
+ Assert (PriorRedoPtr < RedoRecPtr);
+
+ ControlFile->checkPoint = lastCheckPointRecPtr;
+ ControlFile->checkPointCopy = lastCheckPoint;
+
+ /* Update control file using current time */
+ ControlFile->time = (pg_time_t) time(NULL);
+
/*
- * Update pg_control, using current time. Check that it still shows
- * IN_ARCHIVE_RECOVERY state and an older checkpoint, else do nothing;
- * this is a quick hack to make sure nothing really bad happens if somehow
- * we get here after the end-of-recovery checkpoint.
+ * Ensure minRecoveryPoint is past the checkpoint record while archive
+ * recovery is still ongoing. Normally, this will have happened already
+ * while writing out dirty buffers, but not necessarily - e.g. because no
+ * buffers were dirtied. We do this because a non-exclusive base backup
+ * uses minRecoveryPoint to determine which WAL files must be included in
+ * the backup, and the file (or files) containing the checkpoint record
+ * must be included, at a minimum. Note that for an ordinary restart of
+ * recovery there's no value in having the minimum recovery point any
+ * earlier than this anyway, because redo will begin just after the
+ * checkpoint record.
*/
- LWLockAcquire(ControlFileLock, LW_EXCLUSIVE);
- if (ControlFile->state == DB_IN_ARCHIVE_RECOVERY &&
- ControlFile->checkPointCopy.redo < lastCheckPoint.redo)
+ if (ControlFile->state == DB_IN_ARCHIVE_RECOVERY)
{
- ControlFile->checkPoint = lastCheckPointRecPtr;
- ControlFile->checkPointCopy = lastCheckPoint;
- ControlFile->time = (pg_time_t) time(NULL);
-
- /*
- * Ensure minRecoveryPoint is past the checkpoint record. Normally,
- * this will have happened already while writing out dirty buffers,
- * but not necessarily - e.g. because no buffers were dirtied. We do
- * this because a non-exclusive base backup uses minRecoveryPoint to
- * determine which WAL files must be included in the backup, and the
- * file (or files) containing the checkpoint record must be included,
- * at a minimum. Note that for an ordinary restart of recovery there's
- * no value in having the minimum recovery point any earlier than this
- * anyway, because redo will begin just after the checkpoint record.
- */
if (ControlFile->minRecoveryPoint < lastCheckPointEndPtr)
{
ControlFile->minRecoveryPoint = lastCheckPointEndPtr;
@@ -9393,9 +9393,26 @@ CreateRestartPoint(int flags)
minRecoveryPointTLI = ControlFile->minRecoveryPointTLI;
}
if (flags & CHECKPOINT_IS_SHUTDOWN)
- ControlFile->state = DB_SHUTDOWNED_IN_RECOVERY;
- UpdateControlFile();
+ ControlFile->state = DB_SHUTDOWNED_IN_RECOVERY;
}
+ else
+ {
+ /* recovery mode is not supposed to end during shutdown restartpoint */
+ Assert((flags & CHECKPOINT_IS_SHUTDOWN) == 0);
+
+ /*
+ * Aarchive recovery has ended. Crash recovery ever after should
+ * always recover to the end of WAL
+ */
+ ControlFile->minRecoveryPoint = InvalidXLogRecPtr;
+ ControlFile->minRecoveryPointTLI = 0;
+
+ /* also update local copy */
+ minRecoveryPoint = InvalidXLogRecPtr;
+ minRecoveryPointTLI = 0;
+ }
+
+ UpdateControlFile();
LWLockRelease(ControlFileLock);
/*
@@ -9470,7 +9487,7 @@ CreateRestartPoint(int flags)
xtime = GetLatestXTime();
ereport((log_checkpoints ? LOG : DEBUG2),
(errmsg("recovery restart point at %X/%X",
- (uint32) (lastCheckPoint.redo >> 32), (uint32) lastCheckPoint.redo),
+ (uint32) (RedoRecPtr >> 32), (uint32) RedoRecPtr),
xtime ? errdetail("Last completed transaction was at log time %s.",
timestamptz_to_str(xtime)) : 0));
--
2.27.0
----Next_Part(Wed_Mar_16_10_24_44_2022_775)--
Content-Type: Text/Plain; charset=us-ascii
Content-Transfer-Encoding: 7bit
Content-Disposition: inline;
filename="v4-0001-Correctly-update-contfol-file-at-the-end-of_v10.txt"
^ permalink raw reply [nested|flat] 31+ messages in thread
* [PATCH v3] Correctly update contfol file at the end of archive recovery
@ 2022-02-25 06:04 Kyotaro Horiguchi <[email protected]>
0 siblings, 0 replies; 31+ messages in thread
From: Kyotaro Horiguchi @ 2022-02-25 06:04 UTC (permalink / raw)
CreateRestartPoint runs WAL file cleanup basing on the checkpoint just
have finished in the function. If the database has exited
DB_IN_ARCHIVE_RECOVERY state when the function is going to update
control file, the function refrains from updating the file at all then
proceeds to WAL cleanup having the latest REDO LSN, which is now
inconsistent with the control file. As the result, the succeeding
cleanup procedure overly removes WAL files against the control file
and leaves unrecoverable database until the next checkpoint finishes.
Along with that fix, we remove a dead code path for the case some
other process ran a simultaneous checkpoint. It seems like just a
preventive measure but it's no longer useful because we are sure that
checkpoint is performed only by checkpointer except single process
mode.
---
src/backend/access/transam/xlog.c | 71 +++++++++++++++++++------------
1 file changed, 44 insertions(+), 27 deletions(-)
diff --git a/src/backend/access/transam/xlog.c b/src/backend/access/transam/xlog.c
index 885558f291..2b2568c475 100644
--- a/src/backend/access/transam/xlog.c
+++ b/src/backend/access/transam/xlog.c
@@ -9334,7 +9334,7 @@ CreateRestartPoint(int flags)
/* Also update the info_lck-protected copy */
SpinLockAcquire(&XLogCtl->info_lck);
- XLogCtl->RedoRecPtr = lastCheckPoint.redo;
+ XLogCtl->RedoRecPtr = RedoRecPtr;
SpinLockRelease(&XLogCtl->info_lck);
/*
@@ -9350,7 +9350,10 @@ CreateRestartPoint(int flags)
if (log_checkpoints)
LogCheckpointStart(flags, true);
- CheckPointGuts(lastCheckPoint.redo, flags);
+ CheckPointGuts(RedoRecPtr, flags);
+
+ /* Update pg_control */
+ LWLockAcquire(ControlFileLock, LW_EXCLUSIVE);
/*
* Remember the prior checkpoint's redo ptr for
@@ -9358,31 +9361,28 @@ CreateRestartPoint(int flags)
*/
PriorRedoPtr = ControlFile->checkPointCopy.redo;
+ Assert (PriorRedoPtr < RedoRecPtr);
+
+ ControlFile->checkPoint = lastCheckPointRecPtr;
+ ControlFile->checkPointCopy = lastCheckPoint;
+
+ /* Update control file using current time */
+ ControlFile->time = (pg_time_t) time(NULL);
+
/*
- * Update pg_control, using current time. Check that it still shows
- * IN_ARCHIVE_RECOVERY state and an older checkpoint, else do nothing;
- * this is a quick hack to make sure nothing really bad happens if somehow
- * we get here after the end-of-recovery checkpoint.
+ * Ensure minRecoveryPoint is past the checkpoint record while archive
+ * recovery is still ongoing. Normally, this will have happened already
+ * while writing out dirty buffers, but not necessarily - e.g. because no
+ * buffers were dirtied. We do this because a non-exclusive base backup
+ * uses minRecoveryPoint to determine which WAL files must be included in
+ * the backup, and the file (or files) containing the checkpoint record
+ * must be included, at a minimum. Note that for an ordinary restart of
+ * recovery there's no value in having the minimum recovery point any
+ * earlier than this anyway, because redo will begin just after the
+ * checkpoint record.
*/
- LWLockAcquire(ControlFileLock, LW_EXCLUSIVE);
- if (ControlFile->state == DB_IN_ARCHIVE_RECOVERY &&
- ControlFile->checkPointCopy.redo < lastCheckPoint.redo)
+ if (ControlFile->state == DB_IN_ARCHIVE_RECOVERY)
{
- ControlFile->checkPoint = lastCheckPointRecPtr;
- ControlFile->checkPointCopy = lastCheckPoint;
- ControlFile->time = (pg_time_t) time(NULL);
-
- /*
- * Ensure minRecoveryPoint is past the checkpoint record. Normally,
- * this will have happened already while writing out dirty buffers,
- * but not necessarily - e.g. because no buffers were dirtied. We do
- * this because a non-exclusive base backup uses minRecoveryPoint to
- * determine which WAL files must be included in the backup, and the
- * file (or files) containing the checkpoint record must be included,
- * at a minimum. Note that for an ordinary restart of recovery there's
- * no value in having the minimum recovery point any earlier than this
- * anyway, because redo will begin just after the checkpoint record.
- */
if (ControlFile->minRecoveryPoint < lastCheckPointEndPtr)
{
ControlFile->minRecoveryPoint = lastCheckPointEndPtr;
@@ -9393,9 +9393,26 @@ CreateRestartPoint(int flags)
minRecoveryPointTLI = ControlFile->minRecoveryPointTLI;
}
if (flags & CHECKPOINT_IS_SHUTDOWN)
- ControlFile->state = DB_SHUTDOWNED_IN_RECOVERY;
- UpdateControlFile();
+ ControlFile->state = DB_SHUTDOWNED_IN_RECOVERY;
}
+ else
+ {
+ /* recovery mode is not supposed to end during shutdown restartpoint */
+ Assert((flags & CHECKPOINT_IS_SHUTDOWN) == 0);
+
+ /*
+ * Aarchive recovery has ended. Crash recovery ever after should
+ * always recover to the end of WAL
+ */
+ ControlFile->minRecoveryPoint = InvalidXLogRecPtr;
+ ControlFile->minRecoveryPointTLI = 0;
+
+ /* also update local copy */
+ minRecoveryPoint = InvalidXLogRecPtr;
+ minRecoveryPointTLI = 0;
+ }
+
+ UpdateControlFile();
LWLockRelease(ControlFileLock);
/*
@@ -9470,7 +9487,7 @@ CreateRestartPoint(int flags)
xtime = GetLatestXTime();
ereport((log_checkpoints ? LOG : DEBUG2),
(errmsg("recovery restart point at %X/%X",
- (uint32) (lastCheckPoint.redo >> 32), (uint32) lastCheckPoint.redo),
+ (uint32) (RedoRecPtr >> 32), (uint32) RedoRecPtr),
xtime ? errdetail("Last completed transaction was at log time %s.",
timestamptz_to_str(xtime)) : 0));
--
2.27.0
----Next_Part(Fri_Feb_25_16_47_01_2022_087)--
Content-Type: Text/Plain; charset=us-ascii
Content-Transfer-Encoding: 7bit
Content-Disposition: inline;
filename="v3-0001-Correctly-update-contfol-file-at-the-end-of_v10.txt"
^ permalink raw reply [nested|flat] 31+ messages in thread
* [PATCH v3] Correctly update contfol file at the end of archive recovery
@ 2022-02-25 07:35 Kyotaro Horiguchi <[email protected]>
0 siblings, 0 replies; 31+ messages in thread
From: Kyotaro Horiguchi @ 2022-02-25 07:35 UTC (permalink / raw)
CreateRestartPoint runs WAL file cleanup basing on the checkpoint just
have finished in the function. If the database has exited
DB_IN_ARCHIVE_RECOVERY state when the function is going to update
control file, the function refrains from updating the file at all then
proceeds to WAL cleanup having the latest REDO LSN, which is now
inconsistent with the control file. As the result, the succeeding
cleanup procedure overly removes WAL files against the control file
and leaves unrecoverable database until the next checkpoint finishes.
Along with that fix, we remove a dead code path for the case some
other process ran a simultaneous checkpoint. It seems like just a
preventive measure but it's no longer useful because we are sure that
checkpoint is performed only by checkpointer except single process
mode.
---
src/backend/access/transam/xlog.c | 73 +++++++++++++++++++------------
1 file changed, 45 insertions(+), 28 deletions(-)
diff --git a/src/backend/access/transam/xlog.c b/src/backend/access/transam/xlog.c
index c64febdb53..9fb66ad7d5 100644
--- a/src/backend/access/transam/xlog.c
+++ b/src/backend/access/transam/xlog.c
@@ -9434,7 +9434,7 @@ CreateRestartPoint(int flags)
/* Also update the info_lck-protected copy */
SpinLockAcquire(&XLogCtl->info_lck);
- XLogCtl->RedoRecPtr = lastCheckPoint.redo;
+ XLogCtl->RedoRecPtr = RedoRecPtr;
SpinLockRelease(&XLogCtl->info_lck);
/*
@@ -9450,7 +9450,10 @@ CreateRestartPoint(int flags)
if (log_checkpoints)
LogCheckpointStart(flags, true);
- CheckPointGuts(lastCheckPoint.redo, flags);
+ CheckPointGuts(RedoRecPtr, flags);
+
+ /* Update pg_control */
+ LWLockAcquire(ControlFileLock, LW_EXCLUSIVE);
/*
* Remember the prior checkpoint's redo pointer, used later to determine
@@ -9458,32 +9461,29 @@ CreateRestartPoint(int flags)
*/
PriorRedoPtr = ControlFile->checkPointCopy.redo;
+ Assert (PriorRedoPtr < RedoRecPtr);
+
+ ControlFile->prevCheckPoint = ControlFile->checkPoint;
+ ControlFile->checkPoint = lastCheckPointRecPtr;
+ ControlFile->checkPointCopy = lastCheckPoint;
+
+ /* Update control file using current time */
+ ControlFile->time = (pg_time_t) time(NULL);
+
/*
- * Update pg_control, using current time. Check that it still shows
- * IN_ARCHIVE_RECOVERY state and an older checkpoint, else do nothing;
- * this is a quick hack to make sure nothing really bad happens if somehow
- * we get here after the end-of-recovery checkpoint.
+ * Ensure minRecoveryPoint is past the checkpoint record while archive
+ * recovery is still running. Normally, this will have happened already
+ * while writing out dirty buffers, but not necessarily - e.g. because no
+ * buffers were dirtied. We do this because a non-exclusive base backup
+ * uses minRecoveryPoint to determine which WAL files must be included in
+ * the backup, and the file (or files) containing the checkpoint record
+ * must be included, at a minimum. Note that for an ordinary restart of
+ * recovery there's no value in having the minimum recovery point any
+ * earlier than this anyway, because redo will begin just after the
+ * checkpoint record.
*/
- LWLockAcquire(ControlFileLock, LW_EXCLUSIVE);
- if (ControlFile->state == DB_IN_ARCHIVE_RECOVERY &&
- ControlFile->checkPointCopy.redo < lastCheckPoint.redo)
+ if (ControlFile->state == DB_IN_ARCHIVE_RECOVERY)
{
- ControlFile->prevCheckPoint = ControlFile->checkPoint;
- ControlFile->checkPoint = lastCheckPointRecPtr;
- ControlFile->checkPointCopy = lastCheckPoint;
- ControlFile->time = (pg_time_t) time(NULL);
-
- /*
- * Ensure minRecoveryPoint is past the checkpoint record. Normally,
- * this will have happened already while writing out dirty buffers,
- * but not necessarily - e.g. because no buffers were dirtied. We do
- * this because a non-exclusive base backup uses minRecoveryPoint to
- * determine which WAL files must be included in the backup, and the
- * file (or files) containing the checkpoint record must be included,
- * at a minimum. Note that for an ordinary restart of recovery there's
- * no value in having the minimum recovery point any earlier than this
- * anyway, because redo will begin just after the checkpoint record.
- */
if (ControlFile->minRecoveryPoint < lastCheckPointEndPtr)
{
ControlFile->minRecoveryPoint = lastCheckPointEndPtr;
@@ -9494,9 +9494,26 @@ CreateRestartPoint(int flags)
minRecoveryPointTLI = ControlFile->minRecoveryPointTLI;
}
if (flags & CHECKPOINT_IS_SHUTDOWN)
- ControlFile->state = DB_SHUTDOWNED_IN_RECOVERY;
- UpdateControlFile();
+ ControlFile->state = DB_SHUTDOWNED_IN_RECOVERY;
}
+ else
+ {
+ /* recovery mode is not supposed to end during shutdown restartpoint */
+ Assert((flags & CHECKPOINT_IS_SHUTDOWN) == 0);
+
+ /*
+ * Aarchive recovery has ended. Crash recovery ever after should
+ * always recover to the end of WAL
+ */
+ ControlFile->minRecoveryPoint = InvalidXLogRecPtr;
+ ControlFile->minRecoveryPointTLI = 0;
+
+ /* also update local copy */
+ minRecoveryPoint = InvalidXLogRecPtr;
+ minRecoveryPointTLI = 0;
+ }
+
+ UpdateControlFile();
LWLockRelease(ControlFileLock);
/*
@@ -9579,7 +9596,7 @@ CreateRestartPoint(int flags)
xtime = GetLatestXTime();
ereport((log_checkpoints ? LOG : DEBUG2),
(errmsg("recovery restart point at %X/%X",
- (uint32) (lastCheckPoint.redo >> 32), (uint32) lastCheckPoint.redo),
+ (uint32) (RedoRecPtr >> 32), (uint32) RedoRecPtr),
xtime ? errdetail("last completed transaction was at log time %s",
timestamptz_to_str(xtime)) : 0));
--
2.27.0
----Next_Part(Wed_Mar_16_10_24_44_2022_775)----
^ permalink raw reply [nested|flat] 31+ messages in thread
* [PATCH v3] Correctly update contfol file at the end of archive recovery
@ 2022-02-25 07:35 Kyotaro Horiguchi <[email protected]>
0 siblings, 0 replies; 31+ messages in thread
From: Kyotaro Horiguchi @ 2022-02-25 07:35 UTC (permalink / raw)
CreateRestartPoint runs WAL file cleanup basing on the checkpoint just
have finished in the function. If the database has exited
DB_IN_ARCHIVE_RECOVERY state when the function is going to update
control file, the function refrains from updating the file at all then
proceeds to WAL cleanup having the latest REDO LSN, which is now
inconsistent with the control file. As the result, the succeeding
cleanup procedure overly removes WAL files against the control file
and leaves unrecoverable database until the next checkpoint finishes.
Along with that fix, we remove a dead code path for the case some
other process ran a simultaneous checkpoint. It seems like just a
preventive measure but it's no longer useful because we are sure that
checkpoint is performed only by checkpointer except single process
mode.
---
src/backend/access/transam/xlog.c | 73 +++++++++++++++++++------------
1 file changed, 45 insertions(+), 28 deletions(-)
diff --git a/src/backend/access/transam/xlog.c b/src/backend/access/transam/xlog.c
index c64febdb53..9fb66ad7d5 100644
--- a/src/backend/access/transam/xlog.c
+++ b/src/backend/access/transam/xlog.c
@@ -9434,7 +9434,7 @@ CreateRestartPoint(int flags)
/* Also update the info_lck-protected copy */
SpinLockAcquire(&XLogCtl->info_lck);
- XLogCtl->RedoRecPtr = lastCheckPoint.redo;
+ XLogCtl->RedoRecPtr = RedoRecPtr;
SpinLockRelease(&XLogCtl->info_lck);
/*
@@ -9450,7 +9450,10 @@ CreateRestartPoint(int flags)
if (log_checkpoints)
LogCheckpointStart(flags, true);
- CheckPointGuts(lastCheckPoint.redo, flags);
+ CheckPointGuts(RedoRecPtr, flags);
+
+ /* Update pg_control */
+ LWLockAcquire(ControlFileLock, LW_EXCLUSIVE);
/*
* Remember the prior checkpoint's redo pointer, used later to determine
@@ -9458,32 +9461,29 @@ CreateRestartPoint(int flags)
*/
PriorRedoPtr = ControlFile->checkPointCopy.redo;
+ Assert (PriorRedoPtr < RedoRecPtr);
+
+ ControlFile->prevCheckPoint = ControlFile->checkPoint;
+ ControlFile->checkPoint = lastCheckPointRecPtr;
+ ControlFile->checkPointCopy = lastCheckPoint;
+
+ /* Update control file using current time */
+ ControlFile->time = (pg_time_t) time(NULL);
+
/*
- * Update pg_control, using current time. Check that it still shows
- * IN_ARCHIVE_RECOVERY state and an older checkpoint, else do nothing;
- * this is a quick hack to make sure nothing really bad happens if somehow
- * we get here after the end-of-recovery checkpoint.
+ * Ensure minRecoveryPoint is past the checkpoint record while archive
+ * recovery is still running. Normally, this will have happened already
+ * while writing out dirty buffers, but not necessarily - e.g. because no
+ * buffers were dirtied. We do this because a non-exclusive base backup
+ * uses minRecoveryPoint to determine which WAL files must be included in
+ * the backup, and the file (or files) containing the checkpoint record
+ * must be included, at a minimum. Note that for an ordinary restart of
+ * recovery there's no value in having the minimum recovery point any
+ * earlier than this anyway, because redo will begin just after the
+ * checkpoint record.
*/
- LWLockAcquire(ControlFileLock, LW_EXCLUSIVE);
- if (ControlFile->state == DB_IN_ARCHIVE_RECOVERY &&
- ControlFile->checkPointCopy.redo < lastCheckPoint.redo)
+ if (ControlFile->state == DB_IN_ARCHIVE_RECOVERY)
{
- ControlFile->prevCheckPoint = ControlFile->checkPoint;
- ControlFile->checkPoint = lastCheckPointRecPtr;
- ControlFile->checkPointCopy = lastCheckPoint;
- ControlFile->time = (pg_time_t) time(NULL);
-
- /*
- * Ensure minRecoveryPoint is past the checkpoint record. Normally,
- * this will have happened already while writing out dirty buffers,
- * but not necessarily - e.g. because no buffers were dirtied. We do
- * this because a non-exclusive base backup uses minRecoveryPoint to
- * determine which WAL files must be included in the backup, and the
- * file (or files) containing the checkpoint record must be included,
- * at a minimum. Note that for an ordinary restart of recovery there's
- * no value in having the minimum recovery point any earlier than this
- * anyway, because redo will begin just after the checkpoint record.
- */
if (ControlFile->minRecoveryPoint < lastCheckPointEndPtr)
{
ControlFile->minRecoveryPoint = lastCheckPointEndPtr;
@@ -9494,9 +9494,26 @@ CreateRestartPoint(int flags)
minRecoveryPointTLI = ControlFile->minRecoveryPointTLI;
}
if (flags & CHECKPOINT_IS_SHUTDOWN)
- ControlFile->state = DB_SHUTDOWNED_IN_RECOVERY;
- UpdateControlFile();
+ ControlFile->state = DB_SHUTDOWNED_IN_RECOVERY;
}
+ else
+ {
+ /* recovery mode is not supposed to end during shutdown restartpoint */
+ Assert((flags & CHECKPOINT_IS_SHUTDOWN) == 0);
+
+ /*
+ * Aarchive recovery has ended. Crash recovery ever after should
+ * always recover to the end of WAL
+ */
+ ControlFile->minRecoveryPoint = InvalidXLogRecPtr;
+ ControlFile->minRecoveryPointTLI = 0;
+
+ /* also update local copy */
+ minRecoveryPoint = InvalidXLogRecPtr;
+ minRecoveryPointTLI = 0;
+ }
+
+ UpdateControlFile();
LWLockRelease(ControlFileLock);
/*
@@ -9579,7 +9596,7 @@ CreateRestartPoint(int flags)
xtime = GetLatestXTime();
ereport((log_checkpoints ? LOG : DEBUG2),
(errmsg("recovery restart point at %X/%X",
- (uint32) (lastCheckPoint.redo >> 32), (uint32) lastCheckPoint.redo),
+ (uint32) (RedoRecPtr >> 32), (uint32) RedoRecPtr),
xtime ? errdetail("last completed transaction was at log time %s",
timestamptz_to_str(xtime)) : 0));
--
2.27.0
----Next_Part(Fri_Feb_25_16_47_01_2022_087)----
^ permalink raw reply [nested|flat] 31+ messages in thread
* [PATCH v4] Correctly update contfol file at the end of archive recovery
@ 2022-03-04 04:18 Kyotaro Horiguchi <[email protected]>
0 siblings, 0 replies; 31+ messages in thread
From: Kyotaro Horiguchi @ 2022-03-04 04:18 UTC (permalink / raw)
CreateRestartPoint runs WAL file cleanup basing on the checkpoint just
have finished in the function. If the database has exited
DB_IN_ARCHIVE_RECOVERY state when the function is going to update
control file, the function refrains from updating the file at all then
proceeds to WAL cleanup having the latest REDO LSN, which is now
inconsistent with the control file. As the result, the succeeding
cleanup procedure overly removes WAL files against the control file
and leaves unrecoverable database until the next checkpoint finishes.
Along with that fix, we remove a dead code path for the case some
other process ran a simultaneous checkpoint. It seems like just a
preventive measure but it's no longer useful because we are sure that
checkpoint is performed only by checkpointer except single process
mode.
---
src/backend/access/transam/xlog.c | 69 ++++++++++++++++++++-----------
1 file changed, 44 insertions(+), 25 deletions(-)
diff --git a/src/backend/access/transam/xlog.c b/src/backend/access/transam/xlog.c
index ed16f279b1..dd9c564988 100644
--- a/src/backend/access/transam/xlog.c
+++ b/src/backend/access/transam/xlog.c
@@ -6900,6 +6900,9 @@ CreateRestartPoint(int flags)
XLogSegNo _logSegNo;
TimestampTz xtime;
+ /* we don't assume concurrent checkpoint/restartpoint to run */
+ Assert (!IsUnderPostmaster || MyBackendType == B_CHECKPOINTER);
+
/* Get a local copy of the last safe checkpoint record. */
SpinLockAcquire(&XLogCtl->info_lck);
lastCheckPointRecPtr = XLogCtl->lastCheckPointRecPtr;
@@ -6965,7 +6968,7 @@ CreateRestartPoint(int flags)
/* Also update the info_lck-protected copy */
SpinLockAcquire(&XLogCtl->info_lck);
- XLogCtl->RedoRecPtr = lastCheckPoint.redo;
+ XLogCtl->RedoRecPtr = RedoRecPtr;
SpinLockRelease(&XLogCtl->info_lck);
/*
@@ -6984,7 +6987,10 @@ CreateRestartPoint(int flags)
/* Update the process title */
update_checkpoint_display(flags, true, false);
- CheckPointGuts(lastCheckPoint.redo, flags);
+ CheckPointGuts(RedoRecPtr, flags);
+
+ /* Update pg_control */
+ LWLockAcquire(ControlFileLock, LW_EXCLUSIVE);
/*
* Remember the prior checkpoint's redo ptr for
@@ -6992,30 +6998,26 @@ CreateRestartPoint(int flags)
*/
PriorRedoPtr = ControlFile->checkPointCopy.redo;
+ Assert (PriorRedoPtr < RedoRecPtr);
+
+ ControlFile->checkPoint = lastCheckPointRecPtr;
+ ControlFile->checkPointCopy = lastCheckPoint;
+
/*
- * Update pg_control, using current time. Check that it still shows
- * DB_IN_ARCHIVE_RECOVERY state and an older checkpoint, else do nothing;
- * this is a quick hack to make sure nothing really bad happens if somehow
- * we get here after the end-of-recovery checkpoint.
+ * Ensure minRecoveryPoint is past the checkpoint record while archive
+ * recovery is still ongoing. Normally, this will have happened already
+ * while writing out dirty buffers, but not necessarily - e.g. because no
+ * buffers were dirtied. We do this because a non-exclusive base backup
+ * uses minRecoveryPoint to determine which WAL files must be included in
+ * the backup, and the file (or files) containing the checkpoint record
+ * must be included, at a minimum. Note that for an ordinary restart of
+ * recovery there's no value in having the minimum recovery point any
+ * earlier than this anyway, because redo will begin just after the
+ * checkpoint record. This is a quick hack to make sure nothing really bad
+ * happens if somehow we get here after the end-of-recovery checkpoint.
*/
- LWLockAcquire(ControlFileLock, LW_EXCLUSIVE);
- if (ControlFile->state == DB_IN_ARCHIVE_RECOVERY &&
- ControlFile->checkPointCopy.redo < lastCheckPoint.redo)
+ if (ControlFile->state == DB_IN_ARCHIVE_RECOVERY)
{
- ControlFile->checkPoint = lastCheckPointRecPtr;
- ControlFile->checkPointCopy = lastCheckPoint;
-
- /*
- * Ensure minRecoveryPoint is past the checkpoint record. Normally,
- * this will have happened already while writing out dirty buffers,
- * but not necessarily - e.g. because no buffers were dirtied. We do
- * this because a non-exclusive base backup uses minRecoveryPoint to
- * determine which WAL files must be included in the backup, and the
- * file (or files) containing the checkpoint record must be included,
- * at a minimum. Note that for an ordinary restart of recovery there's
- * no value in having the minimum recovery point any earlier than this
- * anyway, because redo will begin just after the checkpoint record.
- */
if (ControlFile->minRecoveryPoint < lastCheckPointEndPtr)
{
ControlFile->minRecoveryPoint = lastCheckPointEndPtr;
@@ -7027,8 +7029,25 @@ CreateRestartPoint(int flags)
}
if (flags & CHECKPOINT_IS_SHUTDOWN)
ControlFile->state = DB_SHUTDOWNED_IN_RECOVERY;
- UpdateControlFile();
}
+ else
+ {
+ /* recovery mode is not supposed to end during shutdown restartpoint */
+ Assert((flags & CHECKPOINT_IS_SHUTDOWN) == 0);
+
+ /*
+ * Aarchive recovery has ended. Crash recovery ever after should
+ * always recover to the end of WAL
+ */
+ ControlFile->minRecoveryPoint = InvalidXLogRecPtr;
+ ControlFile->minRecoveryPointTLI = 0;
+
+ /* also update local copy */
+ LocalMinRecoveryPoint = InvalidXLogRecPtr;
+ LocalMinRecoveryPointTLI = 0;
+ }
+
+ UpdateControlFile();
LWLockRelease(ControlFileLock);
/*
@@ -7105,7 +7124,7 @@ CreateRestartPoint(int flags)
xtime = GetLatestXTime();
ereport((log_checkpoints ? LOG : DEBUG2),
(errmsg("recovery restart point at %X/%X",
- LSN_FORMAT_ARGS(lastCheckPoint.redo)),
+ LSN_FORMAT_ARGS(RedoRecPtr)),
xtime ? errdetail("Last completed transaction was at log time %s.",
timestamptz_to_str(xtime)) : 0));
--
2.27.0
----Next_Part(Wed_Mar_16_10_24_44_2022_775)--
Content-Type: Text/Plain; charset=us-ascii
Content-Transfer-Encoding: 7bit
Content-Disposition: inline;
filename="v4-0001-Correctly-update-contfol-file-at-the-end-of_v14.txt"
^ permalink raw reply [nested|flat] 31+ messages in thread
* [PATCH v12 1/5] Correctly update contfol file at the end of archive recovery
@ 2022-03-04 04:18 Kyotaro Horiguchi <[email protected]>
0 siblings, 0 replies; 31+ messages in thread
From: Kyotaro Horiguchi @ 2022-03-04 04:18 UTC (permalink / raw)
CreateRestartPoint runs WAL file cleanup basing on the checkpoint just
have finished in the function. If the database has exited
DB_IN_ARCHIVE_RECOVERY state when the function is going to update
control file, the function refrains from updating the file at all then
proceeds to WAL cleanup having the latest REDO LSN, which is now
inconsistent with the control file. As the result, the succeeding
cleanup procedure overly removes WAL files against the control file
and leaves unrecoverable database until the next checkpoint finishes.
Along with that fix, we remove a dead code path for the case some
other process ran a simultaneous checkpoint. It seems like just a
preventive measure but it's no longer useful because we are sure that
checkpoint is performed only by checkpointer except single process
mode.
---
src/backend/access/transam/xlog.c | 69 ++++++++++++++++++++-----------
1 file changed, 44 insertions(+), 25 deletions(-)
diff --git a/src/backend/access/transam/xlog.c b/src/backend/access/transam/xlog.c
index 0d2bd7a357..bd962763cc 100644
--- a/src/backend/access/transam/xlog.c
+++ b/src/backend/access/transam/xlog.c
@@ -6899,6 +6899,9 @@ CreateRestartPoint(int flags)
XLogSegNo _logSegNo;
TimestampTz xtime;
+ /* we don't assume concurrent checkpoint/restartpoint to run */
+ Assert (!IsUnderPostmaster || MyBackendType == B_CHECKPOINTER);
+
/* Get a local copy of the last safe checkpoint record. */
SpinLockAcquire(&XLogCtl->info_lck);
lastCheckPointRecPtr = XLogCtl->lastCheckPointRecPtr;
@@ -6964,7 +6967,7 @@ CreateRestartPoint(int flags)
/* Also update the info_lck-protected copy */
SpinLockAcquire(&XLogCtl->info_lck);
- XLogCtl->RedoRecPtr = lastCheckPoint.redo;
+ XLogCtl->RedoRecPtr = RedoRecPtr;
SpinLockRelease(&XLogCtl->info_lck);
/*
@@ -6983,7 +6986,10 @@ CreateRestartPoint(int flags)
/* Update the process title */
update_checkpoint_display(flags, true, false);
- CheckPointGuts(lastCheckPoint.redo, flags);
+ CheckPointGuts(RedoRecPtr, flags);
+
+ /* Update pg_control */
+ LWLockAcquire(ControlFileLock, LW_EXCLUSIVE);
/*
* Remember the prior checkpoint's redo ptr for
@@ -6991,30 +6997,26 @@ CreateRestartPoint(int flags)
*/
PriorRedoPtr = ControlFile->checkPointCopy.redo;
+ Assert (PriorRedoPtr < RedoRecPtr);
+
+ ControlFile->checkPoint = lastCheckPointRecPtr;
+ ControlFile->checkPointCopy = lastCheckPoint;
+
/*
- * Update pg_control, using current time. Check that it still shows
- * DB_IN_ARCHIVE_RECOVERY state and an older checkpoint, else do nothing;
- * this is a quick hack to make sure nothing really bad happens if somehow
- * we get here after the end-of-recovery checkpoint.
+ * Ensure minRecoveryPoint is past the checkpoint record while archive
+ * recovery is still ongoing. Normally, this will have happened already
+ * while writing out dirty buffers, but not necessarily - e.g. because no
+ * buffers were dirtied. We do this because a non-exclusive base backup
+ * uses minRecoveryPoint to determine which WAL files must be included in
+ * the backup, and the file (or files) containing the checkpoint record
+ * must be included, at a minimum. Note that for an ordinary restart of
+ * recovery there's no value in having the minimum recovery point any
+ * earlier than this anyway, because redo will begin just after the
+ * checkpoint record. This is a quick hack to make sure nothing really bad
+ * happens if somehow we get here after the end-of-recovery checkpoint.
*/
- LWLockAcquire(ControlFileLock, LW_EXCLUSIVE);
- if (ControlFile->state == DB_IN_ARCHIVE_RECOVERY &&
- ControlFile->checkPointCopy.redo < lastCheckPoint.redo)
+ if (ControlFile->state == DB_IN_ARCHIVE_RECOVERY)
{
- ControlFile->checkPoint = lastCheckPointRecPtr;
- ControlFile->checkPointCopy = lastCheckPoint;
-
- /*
- * Ensure minRecoveryPoint is past the checkpoint record. Normally,
- * this will have happened already while writing out dirty buffers,
- * but not necessarily - e.g. because no buffers were dirtied. We do
- * this because a non-exclusive base backup uses minRecoveryPoint to
- * determine which WAL files must be included in the backup, and the
- * file (or files) containing the checkpoint record must be included,
- * at a minimum. Note that for an ordinary restart of recovery there's
- * no value in having the minimum recovery point any earlier than this
- * anyway, because redo will begin just after the checkpoint record.
- */
if (ControlFile->minRecoveryPoint < lastCheckPointEndPtr)
{
ControlFile->minRecoveryPoint = lastCheckPointEndPtr;
@@ -7026,8 +7028,25 @@ CreateRestartPoint(int flags)
}
if (flags & CHECKPOINT_IS_SHUTDOWN)
ControlFile->state = DB_SHUTDOWNED_IN_RECOVERY;
- UpdateControlFile();
}
+ else
+ {
+ /* recovery mode is not supposed to end during shutdown restartpoint */
+ Assert((flags & CHECKPOINT_IS_SHUTDOWN) == 0);
+
+ /*
+ * Aarchive recovery has ended. Crash recovery ever after should
+ * always recover to the end of WAL
+ */
+ ControlFile->minRecoveryPoint = InvalidXLogRecPtr;
+ ControlFile->minRecoveryPointTLI = 0;
+
+ /* also update local copy */
+ LocalMinRecoveryPoint = InvalidXLogRecPtr;
+ LocalMinRecoveryPointTLI = 0;
+ }
+
+ UpdateControlFile();
LWLockRelease(ControlFileLock);
/*
@@ -7104,7 +7123,7 @@ CreateRestartPoint(int flags)
xtime = GetLatestXTime();
ereport((log_checkpoints ? LOG : DEBUG2),
(errmsg("recovery restart point at %X/%X",
- LSN_FORMAT_ARGS(lastCheckPoint.redo)),
+ LSN_FORMAT_ARGS(RedoRecPtr)),
xtime ? errdetail("Last completed transaction was at log time %s.",
timestamptz_to_str(xtime)) : 0));
--
2.27.0
----Next_Part(Tue_Mar_15_17_23_40_2022_661)--
Content-Type: Text/X-Patch; charset=us-ascii
Content-Transfer-Encoding: 7bit
Content-Disposition: inline;
filename="v12-0002-Add-checkpoint-and-redo-LSN-to-LogCheckpointEnd-.patch"
^ permalink raw reply [nested|flat] 31+ messages in thread
* [PATCH v11 1/5] Correctly update contfol file at the end of archive recovery
@ 2022-03-04 04:18 Kyotaro Horiguchi <[email protected]>
0 siblings, 0 replies; 31+ messages in thread
From: Kyotaro Horiguchi @ 2022-03-04 04:18 UTC (permalink / raw)
CreateRestartPoint runs WAL file cleanup basing on the checkpoint just
have finished in the function. If the database has exited
DB_IN_ARCHIVE_RECOVERY state when the function is going to update
control file, the function refrains from updating the file at all then
proceeds to WAL cleanup having the latest REDO LSN, which is now
inconsistent with the control file. As the result, the succeeding
cleanup procedure overly removes WAL files against the control file
and leaves unrecoverable database until the next checkpoint finishes.
Along with that fix, we remove a dead code path for the case some
other process ran a simultaneous checkpoint. It seems like just a
preventive measure but it's no longer useful because we are sure that
checkpoint is performed only by checkpointer except single process
mode.
---
src/backend/access/transam/xlog.c | 72 ++++++++++++++++++++-----------
1 file changed, 47 insertions(+), 25 deletions(-)
diff --git a/src/backend/access/transam/xlog.c b/src/backend/access/transam/xlog.c
index 0d2bd7a357..3987aa81de 100644
--- a/src/backend/access/transam/xlog.c
+++ b/src/backend/access/transam/xlog.c
@@ -6899,6 +6899,9 @@ CreateRestartPoint(int flags)
XLogSegNo _logSegNo;
TimestampTz xtime;
+ /* we don't assume concurrent checkpoint/restartpoint to run */
+ Assert (!IsUnderPostmaster || MyBackendType == B_CHECKPOINTER);
+
/* Get a local copy of the last safe checkpoint record. */
SpinLockAcquire(&XLogCtl->info_lck);
lastCheckPointRecPtr = XLogCtl->lastCheckPointRecPtr;
@@ -6964,7 +6967,7 @@ CreateRestartPoint(int flags)
/* Also update the info_lck-protected copy */
SpinLockAcquire(&XLogCtl->info_lck);
- XLogCtl->RedoRecPtr = lastCheckPoint.redo;
+ XLogCtl->RedoRecPtr = RedoRecPtr;
SpinLockRelease(&XLogCtl->info_lck);
/*
@@ -6983,7 +6986,10 @@ CreateRestartPoint(int flags)
/* Update the process title */
update_checkpoint_display(flags, true, false);
- CheckPointGuts(lastCheckPoint.redo, flags);
+ CheckPointGuts(RedoRecPtr, flags);
+
+ /* Update pg_control */
+ LWLockAcquire(ControlFileLock, LW_EXCLUSIVE);
/*
* Remember the prior checkpoint's redo ptr for
@@ -6991,30 +6997,29 @@ CreateRestartPoint(int flags)
*/
PriorRedoPtr = ControlFile->checkPointCopy.redo;
+ Assert (PriorRedoPtr < RedoRecPtr);
+
+ ControlFile->checkPoint = lastCheckPointRecPtr;
+ ControlFile->checkPointCopy = lastCheckPoint;
+
+ /* Update control file using current time */
+ ControlFile->time = (pg_time_t) time(NULL);
+
/*
- * Update pg_control, using current time. Check that it still shows
- * DB_IN_ARCHIVE_RECOVERY state and an older checkpoint, else do nothing;
- * this is a quick hack to make sure nothing really bad happens if somehow
- * we get here after the end-of-recovery checkpoint.
+ * Ensure minRecoveryPoint is past the checkpoint record while archive
+ * recovery is still ongoing. Normally, this will have happened already
+ * while writing out dirty buffers, but not necessarily - e.g. because no
+ * buffers were dirtied. We do this because a non-exclusive base backup
+ * uses minRecoveryPoint to determine which WAL files must be included in
+ * the backup, and the file (or files) containing the checkpoint record
+ * must be included, at a minimum. Note that for an ordinary restart of
+ * recovery there's no value in having the minimum recovery point any
+ * earlier than this anyway, because redo will begin just after the
+ * checkpoint record. This is a quick hack to make sure nothing really bad
+ * happens if somehow we get here after the end-of-recovery checkpoint.
*/
- LWLockAcquire(ControlFileLock, LW_EXCLUSIVE);
- if (ControlFile->state == DB_IN_ARCHIVE_RECOVERY &&
- ControlFile->checkPointCopy.redo < lastCheckPoint.redo)
+ if (ControlFile->state == DB_IN_ARCHIVE_RECOVERY)
{
- ControlFile->checkPoint = lastCheckPointRecPtr;
- ControlFile->checkPointCopy = lastCheckPoint;
-
- /*
- * Ensure minRecoveryPoint is past the checkpoint record. Normally,
- * this will have happened already while writing out dirty buffers,
- * but not necessarily - e.g. because no buffers were dirtied. We do
- * this because a non-exclusive base backup uses minRecoveryPoint to
- * determine which WAL files must be included in the backup, and the
- * file (or files) containing the checkpoint record must be included,
- * at a minimum. Note that for an ordinary restart of recovery there's
- * no value in having the minimum recovery point any earlier than this
- * anyway, because redo will begin just after the checkpoint record.
- */
if (ControlFile->minRecoveryPoint < lastCheckPointEndPtr)
{
ControlFile->minRecoveryPoint = lastCheckPointEndPtr;
@@ -7026,8 +7031,25 @@ CreateRestartPoint(int flags)
}
if (flags & CHECKPOINT_IS_SHUTDOWN)
ControlFile->state = DB_SHUTDOWNED_IN_RECOVERY;
- UpdateControlFile();
}
+ else
+ {
+ /* recovery mode is not supposed to end during shutdown restartpoint */
+ Assert((flags & CHECKPOINT_IS_SHUTDOWN) == 0);
+
+ /*
+ * Aarchive recovery has ended. Crash recovery ever after should
+ * always recover to the end of WAL
+ */
+ ControlFile->minRecoveryPoint = InvalidXLogRecPtr;
+ ControlFile->minRecoveryPointTLI = 0;
+
+ /* also update local copy */
+ LocalMinRecoveryPoint = InvalidXLogRecPtr;
+ LocalMinRecoveryPointTLI = 0;
+ }
+
+ UpdateControlFile();
LWLockRelease(ControlFileLock);
/*
@@ -7104,7 +7126,7 @@ CreateRestartPoint(int flags)
xtime = GetLatestXTime();
ereport((log_checkpoints ? LOG : DEBUG2),
(errmsg("recovery restart point at %X/%X",
- LSN_FORMAT_ARGS(lastCheckPoint.redo)),
+ LSN_FORMAT_ARGS(RedoRecPtr)),
xtime ? errdetail("Last completed transaction was at log time %s.",
timestamptz_to_str(xtime)) : 0));
--
2.27.0
----Next_Part(Fri_Mar__4_14_10_38_2022_481)--
Content-Type: Text/X-Patch; charset=us-ascii
Content-Transfer-Encoding: 7bit
Content-Disposition: inline;
filename="v11-0002-Add-checkpoint-and-redo-LSN-to-LogCheckpointEnd-.patch"
^ permalink raw reply [nested|flat] 31+ messages in thread
* [PATCH v5] Correctly update contfol file at the end of archive recovery
@ 2022-04-27 01:41 Kyotaro Horiguchi <[email protected]>
0 siblings, 0 replies; 31+ messages in thread
From: Kyotaro Horiguchi @ 2022-04-27 01:41 UTC (permalink / raw)
CreateRestartPoint runs WAL file cleanup basing on the checkpoint just
have finished in the function. If the database has exited
DB_IN_ARCHIVE_RECOVERY state when the function is going to update
control file, the function refrains from updating the file at all then
proceeds to WAL cleanup having the latest REDO LSN, which is now
inconsistent with the control file. As the result, the succeeding
cleanup procedure overly removes WAL files against the control file
and leaves unrecoverable database until the next checkpoint finishes.
Along with that fix, we remove a dead code path for the case some
other process ran a simultaneous checkpoint. It seems like just a
preventive measure but it's no longer useful because we are sure that
checkpoint is performed only by checkpointer except single process
mode.
---
src/backend/access/transam/xlog.c | 62 ++++++++++++++++++++-----------
1 file changed, 40 insertions(+), 22 deletions(-)
diff --git a/src/backend/access/transam/xlog.c b/src/backend/access/transam/xlog.c
index 61cda56c6f..a03b8de593 100644
--- a/src/backend/access/transam/xlog.c
+++ b/src/backend/access/transam/xlog.c
@@ -6921,6 +6921,9 @@ CreateRestartPoint(int flags)
XLogSegNo _logSegNo;
TimestampTz xtime;
+ /* we don't assume concurrent checkpoint/restartpoint to run */
+ Assert (!IsUnderPostmaster || MyBackendType == B_CHECKPOINTER);
+
/* Get a local copy of the last safe checkpoint record. */
SpinLockAcquire(&XLogCtl->info_lck);
lastCheckPointRecPtr = XLogCtl->lastCheckPointRecPtr;
@@ -7007,36 +7010,34 @@ CreateRestartPoint(int flags)
CheckPointGuts(lastCheckPoint.redo, flags);
+ /* Update pg_control */
+ LWLockAcquire(ControlFileLock, LW_EXCLUSIVE);
+
/*
* Remember the prior checkpoint's redo ptr for
* UpdateCheckPointDistanceEstimate()
*/
PriorRedoPtr = ControlFile->checkPointCopy.redo;
+ Assert (PriorRedoPtr < RedoRecPtr);
+
+ ControlFile->checkPoint = lastCheckPointRecPtr;
+ ControlFile->checkPointCopy = lastCheckPoint;
+
/*
- * Update pg_control, using current time. Check that it still shows
- * DB_IN_ARCHIVE_RECOVERY state and an older checkpoint, else do nothing;
- * this is a quick hack to make sure nothing really bad happens if somehow
- * we get here after the end-of-recovery checkpoint.
+ * Ensure minRecoveryPoint is past the checkpoint record while archive
+ * recovery is still ongoing. Normally, this will have happened already
+ * while writing out dirty buffers, but not necessarily - e.g. because no
+ * buffers were dirtied. We do this because a non-exclusive base backup
+ * uses minRecoveryPoint to determine which WAL files must be included in
+ * the backup, and the file (or files) containing the checkpoint record
+ * must be included, at a minimum. Note that for an ordinary restart of
+ * recovery there's no value in having the minimum recovery point any
+ * earlier than this anyway, because redo will begin just after the
+ * checkpoint record.
*/
- LWLockAcquire(ControlFileLock, LW_EXCLUSIVE);
- if (ControlFile->state == DB_IN_ARCHIVE_RECOVERY &&
- ControlFile->checkPointCopy.redo < lastCheckPoint.redo)
+ if (ControlFile->state == DB_IN_ARCHIVE_RECOVERY)
{
- ControlFile->checkPoint = lastCheckPointRecPtr;
- ControlFile->checkPointCopy = lastCheckPoint;
-
- /*
- * Ensure minRecoveryPoint is past the checkpoint record. Normally,
- * this will have happened already while writing out dirty buffers,
- * but not necessarily - e.g. because no buffers were dirtied. We do
- * this because a backup performed in recovery uses minRecoveryPoint to
- * determine which WAL files must be included in the backup, and the
- * file (or files) containing the checkpoint record must be included,
- * at a minimum. Note that for an ordinary restart of recovery there's
- * no value in having the minimum recovery point any earlier than this
- * anyway, because redo will begin just after the checkpoint record.
- */
if (ControlFile->minRecoveryPoint < lastCheckPointEndPtr)
{
ControlFile->minRecoveryPoint = lastCheckPointEndPtr;
@@ -7048,8 +7049,25 @@ CreateRestartPoint(int flags)
}
if (flags & CHECKPOINT_IS_SHUTDOWN)
ControlFile->state = DB_SHUTDOWNED_IN_RECOVERY;
- UpdateControlFile();
}
+ else
+ {
+ /* recovery mode is not supposed to end during shutdown restartpoint */
+ Assert((flags & CHECKPOINT_IS_SHUTDOWN) == 0);
+
+ /*
+ * Aarchive recovery has ended. Crash recovery ever after should
+ * always recover to the end of WAL
+ */
+ ControlFile->minRecoveryPoint = InvalidXLogRecPtr;
+ ControlFile->minRecoveryPointTLI = 0;
+
+ /* also update local copy */
+ LocalMinRecoveryPoint = InvalidXLogRecPtr;
+ LocalMinRecoveryPointTLI = 0;
+ }
+
+ UpdateControlFile();
LWLockRelease(ControlFileLock);
/*
--
2.27.0
----Next_Part(Wed_Apr_27_10_43_53_2022_048)----
^ permalink raw reply [nested|flat] 31+ messages in thread
* [PATCH] Expose checkpoint timestamp and duration in pg_stat_checkpointer
@ 2025-11-20 07:30 BharatDB <[email protected]>
2025-11-20 12:41 ` Re: [PATCH] Expose checkpoint timestamp and duration in pg_stat_checkpointer Álvaro Herrera <[email protected]>
0 siblings, 1 reply; 31+ messages in thread
From: BharatDB @ 2025-11-20 07:30 UTC (permalink / raw)
To: Pg Hackers <[email protected]>; +Cc: Melanie Plageman <[email protected]>
Hi all,
While debugging checkpointer write behavior (related to the write-combining
discussions)[1], I recently found some of the enhancements related to
extending PostgreSQL's internal statistics . By including contextual
information to checkpoint completion logs, when `log_checkpoints` is
enabled we can now know the checkpoint type (manual, timed and immediate),
checkpoint duration and checkpoint completion timestamp through SQL for
better monitoring and analysis. I think it would be helpful to understand
more clearly about the current state of a bug and for further review on
future bugs. I had discussed the same with one of the contributors of
PostgreSQL and as per the suggestion, I am submitting a small independent
patch that adds two additional fields to the pg_stat_checkpointer log.
1. Patch features: I introduced these two fields internally as newly added
statistics and was able to surface them through SQL. The added statistics
were:
a. last_checkpoint_time : Exposes the completion timestamp of the most
recent checkpoint and is useful for monitoring checkpoint frequency and
diagnosing irregular checkpoint behavior.
b. checkpoint_total_time: Reports the total time spent in the last
completed checkpoint and helps administrators detect unexpectedly long or
stalled checkpoints.
I am attaching my observations, screenshots and patch in support for this.
Observations:
1. Terminal output for type of checkpoint occurred:
soumya@soumya:~/SoumyaSM/BharatDB/my_postgres$ psql -p 55432 -d postgres
psql (19devel)
Type "help" for help.
postgres=# SELECT pg_reload_conf();
pg_reload_conf
----------------
t
(1 row)
postgres=# \q
soumya@soumya:~/SoumyaSM/BharatDB/my_postgres$ pgbench -i -s 50 -p 55432 -d
postgres
dropping old tables...
NOTICE: table "pgbench_accounts" does not exist, skipping
NOTICE: table "pgbench_branches" does not exist, skipping
NOTICE: table "pgbench_history" does not exist, skipping
NOTICE: table "pgbench_tellers" does not exist, skipping
creating tables...
generating data (client-side)...
vacuuming...
creating primary keys...
done in 7.49 s (drop tables 0.00 s, create tables 0.01 s, client-side
generate 5.52 s, vacuum 0.20 s, primary keys 1.77 s).
soumya@soumya:~/SoumyaSM/BharatDB/my_postgres$ pgbench -c 8 -j 8 -T 120 -p
55432 -d postgres
pgbench (19devel)
starting vacuum...end.
transaction type: <builtin: TPC-B (sort of)>
scaling factor: 50
query mode: simple
number of clients: 8
number of threads: 8
maximum number of tries: 1
duration: 120 s
number of transactions actually processed: 228099
number of failed transactions: 0 (0.000%)
latency average = 4.209 ms
initial connection time = 7.762 ms
tps = 1900.858503 (without initial connection time)
soumya@soumya:~/SoumyaSM/BharatDB/my_postgres$ psql -p 55432 -d postgres
psql (19devel)
Type "help" for help.
postgres=# CHECKPOINT;
CHECKPOINT
postgres=# \q
soumya@soumya:~/SoumyaSM/BharatDB/my_postgres$ sudo grep "checkpoint
complete" "$PGDATA/logfile" | tail -1
[sudo] password for soumya:
2025-11-20 11:51:06.128 IST [18026] LOG: checkpoint complete (immediate):
wrote 7286 buffers (44.5%), wrote 4 SLRU buffers; 0 WAL file(s) added, 0
removed, 27 recycled; write=0.095 s, sync=0.034 s, total=0.279 s; sync
files=17, longest=0.004 s, average=0.002 s; distance=447382 kB,
estimate=531349 kB; lsn=0/7F4EDED8, redo lsn=0/7F4EDE80
soumya@soumya:~/SoumyaSM/BharatDB/my_postgres$
2. Terminal output for type of checkpoint duration and checkpoint
completion timestamp:
soumya@soumya:~/SoumyaSM/BharatDB/my_postgres$ psql -p 55432 -d postgres
psql (19devel)
Type "help" for help.
postgres=# SELECT checkpoint_total_time, last_checkpoint_time FROM
pg_stat_checkpointer;
checkpoint_total_time | last_checkpoint_time
-----------------------+----------------------------------
175119 | 2025-11-20 11:51:06.128918+05:30
(1 row)
postgres=# CHECKPOINT;
CHECKPOINT
postgres=# SELECT pg_sleep(1);
pg_sleep
----------
(1 row)
postgres=# SELECT checkpoint_total_time, last_checkpoint_time FROM
pg_stat_checkpointer;
checkpoint_total_time | last_checkpoint_time
-----------------------+----------------------------------
175138 | 2025-11-20 11:58:02.879149+05:30
(1 row)
postgres=# \q
soumya@soumya:~/SoumyaSM/BharatDB/my_postgres$ sudo grep "checkpoint
complete" "$PGDATA/logfile" | tail -1
2025-11-20 11:58:02.879 IST [18026] LOG: checkpoint complete (immediate):
wrote 0 buffers (0.0%), wrote 0 SLRU buffers; 0 WAL file(s) added, 0
removed, 0 recycled; write=0.001 s, sync=0.001 s, total=0.019 s; sync
files=0, longest=0.000 s, average=0.000 s; distance=0 kB, estimate=478214
kB; lsn=0/7F4EDFE0, redo lsn=0/7F4EDF88
soumya@soumya:~/SoumyaSM/BharatDB/my_postgres$
I hope this will be helpful for proceeding further. Looking forward to
more feedback.
Thanking you.
Regards,
Soumya
BharatDB
References:
[1]
https://www.postgresql.org/message-id/flat/CAAKRu_ZBzTp-o4pu1UwmpLWkFmAmP7dyGFo867HxMo-AF%2B%3DMDw%4...
Attachments:
[image/png] Screenshot from 2025-11-20 11-56-31.png (143.3K, ../../CAAh00EQCZCApECHO8jGixXGRqE=WKSsJo_yjNQODPTOy29FNYw@mail.gmail.com/3-Screenshot%20from%202025-11-20%2011-56-31.png)
download | view image
[image/png] Screenshot from 2025-11-20 12-00-05.png (68.9K, ../../CAAh00EQCZCApECHO8jGixXGRqE=WKSsJo_yjNQODPTOy29FNYw@mail.gmail.com/4-Screenshot%20from%202025-11-20%2012-00-05.png)
download | view image
[text/x-patch] 0001-Added-enhancement-related-to-checkpoint-reason-durat.patch (7.5K, ../../CAAh00EQCZCApECHO8jGixXGRqE=WKSsJo_yjNQODPTOy29FNYw@mail.gmail.com/5-0001-Added-enhancement-related-to-checkpoint-reason-durat.patch)
download | inline diff:
From 465ed2178a5437f31497ca5f5bb4a38ed0451b7a Mon Sep 17 00:00:00 2001
From: BharatDB <[email protected]>
Date: Mon, 10 Nov 2025 11:15:24 +0530
Subject: [PATCH] Added enhancement related to checkpoint reason / duration
info in logs and stats
Signed-off-by: BharatDB <[email protected]>
---
src/backend/access/transam/xlog.c | 11 +++++-
src/backend/catalog/system_views.sql | 4 ++-
.../utils/activity/pgstat_checkpointer.c | 34 +++++++++++++++++++
src/backend/utils/adt/pgstatfuncs.c | 21 ++++++++++++
src/include/catalog/pg_proc.dat | 11 ++++++
src/include/pgstat.h | 5 ++-
6 files changed, 83 insertions(+), 3 deletions(-)
diff --git a/src/backend/access/transam/xlog.c b/src/backend/access/transam/xlog.c
index ec992d2139..9217508917 100644
--- a/src/backend/access/transam/xlog.c
+++ b/src/backend/access/transam/xlog.c
@@ -6761,6 +6761,7 @@ LogCheckpointEnd(bool restartpoint, int flags)
sync_msecs = TimestampDifferenceMilliseconds(CheckpointStats.ckpt_sync_t,
CheckpointStats.ckpt_sync_end_t);
+
/* Accumulate checkpoint timing summary data, in milliseconds. */
PendingCheckpointerStats.write_time += write_msecs;
PendingCheckpointerStats.sync_time += sync_msecs;
@@ -6774,7 +6775,15 @@ LogCheckpointEnd(bool restartpoint, int flags)
total_msecs = TimestampDifferenceMilliseconds(CheckpointStats.ckpt_start_t,
CheckpointStats.ckpt_end_t);
-
+
+
+ /* Store in PendingCheckpointerStats */
+ PendingCheckpointerStats.checkpoint_total_time += (double) total_msecs;
+ PendingCheckpointerStats.last_checkpoint_time = CheckpointStats.ckpt_end_t;
+
+ /* Publishing it */
+ pgstat_report_checkpointer();
+
/*
* Timing values returned from CheckpointStats are in microseconds.
* Convert to milliseconds for consistent printing.
diff --git a/src/backend/catalog/system_views.sql b/src/backend/catalog/system_views.sql
index dec8df4f8e..903e001d95 100644
--- a/src/backend/catalog/system_views.sql
+++ b/src/backend/catalog/system_views.sql
@@ -1190,7 +1190,9 @@ CREATE VIEW pg_stat_checkpointer AS
pg_stat_get_checkpointer_sync_time() AS sync_time,
pg_stat_get_checkpointer_buffers_written() AS buffers_written,
pg_stat_get_checkpointer_slru_written() AS slru_written,
- pg_stat_get_checkpointer_stat_reset_time() AS stats_reset;
+ pg_stat_get_checkpointer_stat_reset_time() AS stats_reset,
+ pg_stat_get_checkpointer_checkpoint_total_time() AS checkpoint_total_time,
+ pg_stat_get_checkpointer_last_checkpoint_time() AS last_checkpoint_time;
CREATE VIEW pg_stat_io AS
SELECT
diff --git a/src/backend/utils/activity/pgstat_checkpointer.c b/src/backend/utils/activity/pgstat_checkpointer.c
index e65034a30a..62ef427b82 100644
--- a/src/backend/utils/activity/pgstat_checkpointer.c
+++ b/src/backend/utils/activity/pgstat_checkpointer.c
@@ -56,8 +56,14 @@ pgstat_report_checkpointer(void)
CHECKPOINTER_ACC(sync_time);
CHECKPOINTER_ACC(buffers_written);
CHECKPOINTER_ACC(slru_written);
+ CHECKPOINTER_ACC(checkpoint_total_time);
#undef CHECKPOINTER_ACC
+ /* only overwrite if we actually have a new timestamp */
+ if (PendingCheckpointerStats.last_checkpoint_time != 0)
+ stats_shmem->stats.last_checkpoint_time =
+ PendingCheckpointerStats.last_checkpoint_time;
+
pgstat_end_changecount_write(&stats_shmem->changecount);
/*
@@ -71,6 +77,28 @@ pgstat_report_checkpointer(void)
pgstat_flush_io(false);
}
+/* ------------------------------------------------------------
+ * Extended checkpointer stats reporting function
+ * ------------------------------------------------------------
+ */
+void
+pgstat_report_checkpointer_extended(long total_msecs, TimestampTz end_time)
+{
+
+ PgStat_CheckpointerStats *checkpointer_stats;
+
+
+ checkpointer_stats = pgstat_fetch_stat_checkpointer();
+ if (!checkpointer_stats)
+ return;
+
+
+ checkpointer_stats->checkpoint_total_time += total_msecs;
+ checkpointer_stats->last_checkpoint_time = end_time;
+
+}
+
+
/*
* pgstat_fetch_stat_checkpointer() -
*
@@ -136,5 +164,11 @@ pgstat_checkpointer_snapshot_cb(void)
CHECKPOINTER_COMP(sync_time);
CHECKPOINTER_COMP(buffers_written);
CHECKPOINTER_COMP(slru_written);
+ CHECKPOINTER_COMP(checkpoint_total_time);
#undef CHECKPOINTER_COMP
+
+ pgStatLocal.snapshot.checkpointer.last_checkpoint_time = stats_shmem->stats.last_checkpoint_time;
+
+ elog(LOG, "DBG snapshot_cb: copied last_checkpoint_time=%ld",
+ (long) pgStatLocal.snapshot.checkpointer.last_checkpoint_time);
}
diff --git a/src/backend/utils/adt/pgstatfuncs.c b/src/backend/utils/adt/pgstatfuncs.c
index a710508979..591ad2ac88 100644
--- a/src/backend/utils/adt/pgstatfuncs.c
+++ b/src/backend/utils/adt/pgstatfuncs.c
@@ -2292,3 +2292,24 @@ pg_stat_have_stats(PG_FUNCTION_ARGS)
PG_RETURN_BOOL(pgstat_have_entry(kind, dboid, objid));
}
+
+PG_FUNCTION_INFO_V1(pg_stat_get_checkpointer_checkpoint_total_time);
+
+Datum
+pg_stat_get_checkpointer_checkpoint_total_time(PG_FUNCTION_ARGS)
+{
+ PgStat_CheckpointerStats *stats = pgstat_fetch_stat_checkpointer();
+ PG_RETURN_FLOAT8(stats->checkpoint_total_time);
+}
+
+PG_FUNCTION_INFO_V1(pg_stat_get_checkpointer_last_checkpoint_time);
+
+Datum
+pg_stat_get_checkpointer_last_checkpoint_time(PG_FUNCTION_ARGS)
+{
+
+ PgStat_CheckpointerStats *stats = pgstat_fetch_stat_checkpointer();
+ if (!stats) PG_RETURN_NULL();
+ PG_RETURN_TIMESTAMPTZ(stats->last_checkpoint_time);
+
+}
diff --git a/src/include/catalog/pg_proc.dat b/src/include/catalog/pg_proc.dat
index 9121a382f7..a57053c4e2 100644
--- a/src/include/catalog/pg_proc.dat
+++ b/src/include/catalog/pg_proc.dat
@@ -5980,6 +5980,17 @@
proname => 'pg_stat_get_checkpointer_stat_reset_time', provolatile => 's',
proparallel => 'r', prorettype => 'timestamptz', proargtypes => '',
prosrc => 'pg_stat_get_checkpointer_stat_reset_time' },
+# New functions for checkpointer
+{ oid => '7000',
+ descr => 'total time spent in last checkpoint in milliseconds',
+ proname => 'pg_stat_get_checkpointer_checkpoint_total_time', provolatile => 's',
+ proparallel => 'r', prorettype => 'float8', proargtypes => '',
+ prosrc => 'pg_stat_get_checkpointer_checkpoint_total_time' },
+{ oid => '7001',
+ descr => 'timestamp of last checkpoint completion',
+ proname => 'pg_stat_get_checkpointer_last_checkpoint_time', provolatile => 's',
+ proparallel => 'r', prorettype => 'timestamptz', proargtypes => '',
+ prosrc => 'pg_stat_get_checkpointer_last_checkpoint_time' },
{ oid => '2772',
descr => 'statistics: number of buffers written by the bgwriter for cleaning dirty buffers',
proname => 'pg_stat_get_bgwriter_buf_written_clean', provolatile => 's',
diff --git a/src/include/pgstat.h b/src/include/pgstat.h
index 7ae503e71a..a8eb1f8add 100644
--- a/src/include/pgstat.h
+++ b/src/include/pgstat.h
@@ -263,7 +263,9 @@ typedef struct PgStat_CheckpointerStats
PgStat_Counter sync_time;
PgStat_Counter buffers_written;
PgStat_Counter slru_written;
- TimestampTz stat_reset_timestamp;
+ PgStat_Counter checkpoint_total_time; /* new: total ms of last checkpoint */
+ TimestampTz last_checkpoint_time; /* new: end time of last checkpoint */
+ TimestampTz stat_reset_timestamp;
} PgStat_CheckpointerStats;
@@ -583,6 +585,7 @@ extern PgStat_BgWriterStats *pgstat_fetch_stat_bgwriter(void);
extern void pgstat_report_checkpointer(void);
extern PgStat_CheckpointerStats *pgstat_fetch_stat_checkpointer(void);
+extern void pgstat_report_checkpointer_extended(long total_msecs, TimestampTz end_time);
/*
--
2.34.1
[text/x-patch] 0001-Enhance-checkpoint-logs-to-include-reason-manual-tim.patch (3.6K, ../../CAAh00EQCZCApECHO8jGixXGRqE=WKSsJo_yjNQODPTOy29FNYw@mail.gmail.com/6-0001-Enhance-checkpoint-logs-to-include-reason-manual-tim.patch)
download | inline diff:
From 28ac031e3484df0d293bfeabd4ec08bed961b6f2 Mon Sep 17 00:00:00 2001
From: BharatDB <[email protected]>
Date: Mon, 3 Nov 2025 16:19:09 +0530
Subject: [PATCH] Enhance checkpoint logs to include reason
(manual/timed/immediate)
Signed-off-by: BharatDB <[email protected]>
---
src/backend/access/transam/xlog.c | 24 +++++++++++++++++++-----
1 file changed, 19 insertions(+), 5 deletions(-)
diff --git a/src/backend/access/transam/xlog.c b/src/backend/access/transam/xlog.c
index fd91bcd68e..ec992d2139 100644
--- a/src/backend/access/transam/xlog.c
+++ b/src/backend/access/transam/xlog.c
@@ -56,6 +56,7 @@
#include "access/transam.h"
#include "access/twophase.h"
#include "access/xact.h"
+#include "access/xlog.h"
#include "access/xlog_internal.h"
#include "access/xlogarchive.h"
#include "access/xloginsert.h"
@@ -6732,7 +6733,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,
@@ -6740,6 +6741,17 @@ 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();
@@ -6782,12 +6794,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,
@@ -6806,12 +6819,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,
@@ -7400,7 +7414,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);
@@ -7868,7 +7882,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
^ permalink raw reply [nested|flat] 31+ messages in thread
* Re: [PATCH] Expose checkpoint timestamp and duration in pg_stat_checkpointer
2025-11-20 07:30 [PATCH] Expose checkpoint timestamp and duration in pg_stat_checkpointer BharatDB <[email protected]>
@ 2025-11-20 12:41 ` Álvaro Herrera <[email protected]>
0 siblings, 0 replies; 31+ messages in thread
From: Álvaro Herrera @ 2025-11-20 12:41 UTC (permalink / raw)
To: BharatDB <[email protected]>; +Cc: Pg Hackers <[email protected]>; Melanie Plageman <[email protected]>
On 2025-Nov-20, BharatDB wrote:
> Hi all,
Please see
https://postgr.es/m/CA+TgmoZWTLxmDXP9cKsLOhTdZXJ2BXHJK7+0w206wxGPYpXH4g@mail.gmail.com
especially point 2.
--
Álvaro Herrera
^ permalink raw reply [nested|flat] 31+ messages in thread
* [PATCH] Expose checkpoint timestamp and duration in pg_stat_checkpointer
@ 2025-11-24 06:10 Soumya S Murali <[email protected]>
2025-11-24 09:18 ` Re: [PATCH] Expose checkpoint timestamp and duration in pg_stat_checkpointer Michael Banck <[email protected]>
2025-11-26 09:50 ` Re: [PATCH] Expose checkpoint timestamp and duration in pg_stat_checkpointer Soumya S Murali <[email protected]>
0 siblings, 2 replies; 31+ messages in thread
From: Soumya S Murali @ 2025-11-24 06:10 UTC (permalink / raw)
To: [email protected]; +Cc: [email protected]
Hi all,
While debugging checkpointer write behavior, I recently found some of the
enhancements related to extending pg_stat_checkpointer by including
checkpoint type (manual/timed/immediate), last_checkpoint_time and
checkpoint_total_time information to checkpoint completion logs through SQL
when `log_checkpoints` is enabled. I am attaching my observations,
screenshots and patch in support for this.
1. Log for type of checkpoint occured:
2025-11-20 11:51:06.128 IST [18026] LOG: checkpoint complete
(immediate): wrote 7286 buffers (44.5%), wrote 4 SLRU buffers; 0 WAL
file(s) added, 0 removed, 27 recycled; write=0.095 s, sync=0.034 s,
total=0.279 s; sync files=17, longest=0.004 s, average=0.002 s;
distance=447382 kB, estimate=531349 kB; lsn=0/7F4EDED8, redo
lsn=0/7F4EDE80
2. Log for the checkpoint_total_time and last_checkpoint_time:
checkpoint_total_time | last_checkpoint_time
-----------------------+----------------------------------
175138 | 2025-11-20 11:58:02.879149+05:30
(1 row)
2025-11-20 11:58:02.879 IST [18026] LOG: checkpoint complete
(immediate): wrote 0 buffers (0.0%), wrote 0 SLRU buffers; 0 WAL
file(s) added, 0 removed, 0 recycled; write=0.001 s, sync=0.001 s,
total=0.019 s; sync files=0, longest=0.000 s, average=0.000 s;
distance=0 kB, estimate=478214 kB; lsn=0/7F4EDFE0, redo lsn=0/7F4EDF88
Looking forward to more feedback.
Regards,
Soumya
Attachments:
[text/x-patch] 0001-Added-enhancement-related-to-checkpoint-reason-durat.patch (7.5K, ../../CAMtXxw_W6w2Q1QsCvMPnoq3xCMKzH28Zjk_EmL60oP+sCTkXOw@mail.gmail.com/3-0001-Added-enhancement-related-to-checkpoint-reason-durat.patch)
download | inline diff:
From 465ed2178a5437f31497ca5f5bb4a38ed0451b7a Mon Sep 17 00:00:00 2001
From: BharatDB <[email protected]>
Date: Mon, 10 Nov 2025 11:15:24 +0530
Subject: [PATCH] Added enhancement related to checkpoint reason / duration
info in logs and stats
Signed-off-by: BharatDB <[email protected]>
---
src/backend/access/transam/xlog.c | 11 +++++-
src/backend/catalog/system_views.sql | 4 ++-
.../utils/activity/pgstat_checkpointer.c | 34 +++++++++++++++++++
src/backend/utils/adt/pgstatfuncs.c | 21 ++++++++++++
src/include/catalog/pg_proc.dat | 11 ++++++
src/include/pgstat.h | 5 ++-
6 files changed, 83 insertions(+), 3 deletions(-)
diff --git a/src/backend/access/transam/xlog.c b/src/backend/access/transam/xlog.c
index ec992d2139..9217508917 100644
--- a/src/backend/access/transam/xlog.c
+++ b/src/backend/access/transam/xlog.c
@@ -6761,6 +6761,7 @@ LogCheckpointEnd(bool restartpoint, int flags)
sync_msecs = TimestampDifferenceMilliseconds(CheckpointStats.ckpt_sync_t,
CheckpointStats.ckpt_sync_end_t);
+
/* Accumulate checkpoint timing summary data, in milliseconds. */
PendingCheckpointerStats.write_time += write_msecs;
PendingCheckpointerStats.sync_time += sync_msecs;
@@ -6774,7 +6775,15 @@ LogCheckpointEnd(bool restartpoint, int flags)
total_msecs = TimestampDifferenceMilliseconds(CheckpointStats.ckpt_start_t,
CheckpointStats.ckpt_end_t);
-
+
+
+ /* Store in PendingCheckpointerStats */
+ PendingCheckpointerStats.checkpoint_total_time += (double) total_msecs;
+ PendingCheckpointerStats.last_checkpoint_time = CheckpointStats.ckpt_end_t;
+
+ /* Publishing it */
+ pgstat_report_checkpointer();
+
/*
* Timing values returned from CheckpointStats are in microseconds.
* Convert to milliseconds for consistent printing.
diff --git a/src/backend/catalog/system_views.sql b/src/backend/catalog/system_views.sql
index dec8df4f8e..903e001d95 100644
--- a/src/backend/catalog/system_views.sql
+++ b/src/backend/catalog/system_views.sql
@@ -1190,7 +1190,9 @@ CREATE VIEW pg_stat_checkpointer AS
pg_stat_get_checkpointer_sync_time() AS sync_time,
pg_stat_get_checkpointer_buffers_written() AS buffers_written,
pg_stat_get_checkpointer_slru_written() AS slru_written,
- pg_stat_get_checkpointer_stat_reset_time() AS stats_reset;
+ pg_stat_get_checkpointer_stat_reset_time() AS stats_reset,
+ pg_stat_get_checkpointer_checkpoint_total_time() AS checkpoint_total_time,
+ pg_stat_get_checkpointer_last_checkpoint_time() AS last_checkpoint_time;
CREATE VIEW pg_stat_io AS
SELECT
diff --git a/src/backend/utils/activity/pgstat_checkpointer.c b/src/backend/utils/activity/pgstat_checkpointer.c
index e65034a30a..62ef427b82 100644
--- a/src/backend/utils/activity/pgstat_checkpointer.c
+++ b/src/backend/utils/activity/pgstat_checkpointer.c
@@ -56,8 +56,14 @@ pgstat_report_checkpointer(void)
CHECKPOINTER_ACC(sync_time);
CHECKPOINTER_ACC(buffers_written);
CHECKPOINTER_ACC(slru_written);
+ CHECKPOINTER_ACC(checkpoint_total_time);
#undef CHECKPOINTER_ACC
+ /* only overwrite if we actually have a new timestamp */
+ if (PendingCheckpointerStats.last_checkpoint_time != 0)
+ stats_shmem->stats.last_checkpoint_time =
+ PendingCheckpointerStats.last_checkpoint_time;
+
pgstat_end_changecount_write(&stats_shmem->changecount);
/*
@@ -71,6 +77,28 @@ pgstat_report_checkpointer(void)
pgstat_flush_io(false);
}
+/* ------------------------------------------------------------
+ * Extended checkpointer stats reporting function
+ * ------------------------------------------------------------
+ */
+void
+pgstat_report_checkpointer_extended(long total_msecs, TimestampTz end_time)
+{
+
+ PgStat_CheckpointerStats *checkpointer_stats;
+
+
+ checkpointer_stats = pgstat_fetch_stat_checkpointer();
+ if (!checkpointer_stats)
+ return;
+
+
+ checkpointer_stats->checkpoint_total_time += total_msecs;
+ checkpointer_stats->last_checkpoint_time = end_time;
+
+}
+
+
/*
* pgstat_fetch_stat_checkpointer() -
*
@@ -136,5 +164,11 @@ pgstat_checkpointer_snapshot_cb(void)
CHECKPOINTER_COMP(sync_time);
CHECKPOINTER_COMP(buffers_written);
CHECKPOINTER_COMP(slru_written);
+ CHECKPOINTER_COMP(checkpoint_total_time);
#undef CHECKPOINTER_COMP
+
+ pgStatLocal.snapshot.checkpointer.last_checkpoint_time = stats_shmem->stats.last_checkpoint_time;
+
+ elog(LOG, "DBG snapshot_cb: copied last_checkpoint_time=%ld",
+ (long) pgStatLocal.snapshot.checkpointer.last_checkpoint_time);
}
diff --git a/src/backend/utils/adt/pgstatfuncs.c b/src/backend/utils/adt/pgstatfuncs.c
index a710508979..591ad2ac88 100644
--- a/src/backend/utils/adt/pgstatfuncs.c
+++ b/src/backend/utils/adt/pgstatfuncs.c
@@ -2292,3 +2292,24 @@ pg_stat_have_stats(PG_FUNCTION_ARGS)
PG_RETURN_BOOL(pgstat_have_entry(kind, dboid, objid));
}
+
+PG_FUNCTION_INFO_V1(pg_stat_get_checkpointer_checkpoint_total_time);
+
+Datum
+pg_stat_get_checkpointer_checkpoint_total_time(PG_FUNCTION_ARGS)
+{
+ PgStat_CheckpointerStats *stats = pgstat_fetch_stat_checkpointer();
+ PG_RETURN_FLOAT8(stats->checkpoint_total_time);
+}
+
+PG_FUNCTION_INFO_V1(pg_stat_get_checkpointer_last_checkpoint_time);
+
+Datum
+pg_stat_get_checkpointer_last_checkpoint_time(PG_FUNCTION_ARGS)
+{
+
+ PgStat_CheckpointerStats *stats = pgstat_fetch_stat_checkpointer();
+ if (!stats) PG_RETURN_NULL();
+ PG_RETURN_TIMESTAMPTZ(stats->last_checkpoint_time);
+
+}
diff --git a/src/include/catalog/pg_proc.dat b/src/include/catalog/pg_proc.dat
index 9121a382f7..a57053c4e2 100644
--- a/src/include/catalog/pg_proc.dat
+++ b/src/include/catalog/pg_proc.dat
@@ -5980,6 +5980,17 @@
proname => 'pg_stat_get_checkpointer_stat_reset_time', provolatile => 's',
proparallel => 'r', prorettype => 'timestamptz', proargtypes => '',
prosrc => 'pg_stat_get_checkpointer_stat_reset_time' },
+# New functions for checkpointer
+{ oid => '7000',
+ descr => 'total time spent in last checkpoint in milliseconds',
+ proname => 'pg_stat_get_checkpointer_checkpoint_total_time', provolatile => 's',
+ proparallel => 'r', prorettype => 'float8', proargtypes => '',
+ prosrc => 'pg_stat_get_checkpointer_checkpoint_total_time' },
+{ oid => '7001',
+ descr => 'timestamp of last checkpoint completion',
+ proname => 'pg_stat_get_checkpointer_last_checkpoint_time', provolatile => 's',
+ proparallel => 'r', prorettype => 'timestamptz', proargtypes => '',
+ prosrc => 'pg_stat_get_checkpointer_last_checkpoint_time' },
{ oid => '2772',
descr => 'statistics: number of buffers written by the bgwriter for cleaning dirty buffers',
proname => 'pg_stat_get_bgwriter_buf_written_clean', provolatile => 's',
diff --git a/src/include/pgstat.h b/src/include/pgstat.h
index 7ae503e71a..a8eb1f8add 100644
--- a/src/include/pgstat.h
+++ b/src/include/pgstat.h
@@ -263,7 +263,9 @@ typedef struct PgStat_CheckpointerStats
PgStat_Counter sync_time;
PgStat_Counter buffers_written;
PgStat_Counter slru_written;
- TimestampTz stat_reset_timestamp;
+ PgStat_Counter checkpoint_total_time; /* new: total ms of last checkpoint */
+ TimestampTz last_checkpoint_time; /* new: end time of last checkpoint */
+ TimestampTz stat_reset_timestamp;
} PgStat_CheckpointerStats;
@@ -583,6 +585,7 @@ extern PgStat_BgWriterStats *pgstat_fetch_stat_bgwriter(void);
extern void pgstat_report_checkpointer(void);
extern PgStat_CheckpointerStats *pgstat_fetch_stat_checkpointer(void);
+extern void pgstat_report_checkpointer_extended(long total_msecs, TimestampTz end_time);
/*
--
2.34.1
[text/x-patch] 0001-Enhance-checkpoint-logs-to-include-reason-manual-tim.patch (3.6K, ../../CAMtXxw_W6w2Q1QsCvMPnoq3xCMKzH28Zjk_EmL60oP+sCTkXOw@mail.gmail.com/4-0001-Enhance-checkpoint-logs-to-include-reason-manual-tim.patch)
download | inline diff:
From 28ac031e3484df0d293bfeabd4ec08bed961b6f2 Mon Sep 17 00:00:00 2001
From: BharatDB <[email protected]>
Date: Mon, 3 Nov 2025 16:19:09 +0530
Subject: [PATCH] Enhance checkpoint logs to include reason
(manual/timed/immediate)
Signed-off-by: BharatDB <[email protected]>
---
src/backend/access/transam/xlog.c | 24 +++++++++++++++++++-----
1 file changed, 19 insertions(+), 5 deletions(-)
diff --git a/src/backend/access/transam/xlog.c b/src/backend/access/transam/xlog.c
index fd91bcd68e..ec992d2139 100644
--- a/src/backend/access/transam/xlog.c
+++ b/src/backend/access/transam/xlog.c
@@ -56,6 +56,7 @@
#include "access/transam.h"
#include "access/twophase.h"
#include "access/xact.h"
+#include "access/xlog.h"
#include "access/xlog_internal.h"
#include "access/xlogarchive.h"
#include "access/xloginsert.h"
@@ -6732,7 +6733,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,
@@ -6740,6 +6741,17 @@ 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();
@@ -6782,12 +6794,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,
@@ -6806,12 +6819,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,
@@ -7400,7 +7414,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);
@@ -7868,7 +7882,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
[image/png] Screenshot from 2025-11-20 11-56-31.png (143.3K, ../../CAMtXxw_W6w2Q1QsCvMPnoq3xCMKzH28Zjk_EmL60oP+sCTkXOw@mail.gmail.com/5-Screenshot%20from%202025-11-20%2011-56-31.png)
download | view image
[image/png] Screenshot from 2025-11-20 12-00-05.png (68.9K, ../../CAMtXxw_W6w2Q1QsCvMPnoq3xCMKzH28Zjk_EmL60oP+sCTkXOw@mail.gmail.com/6-Screenshot%20from%202025-11-20%2012-00-05.png)
download | view image
^ permalink raw reply [nested|flat] 31+ messages in thread
* Re: [PATCH] Expose checkpoint timestamp and duration in pg_stat_checkpointer
2025-11-24 06:10 [PATCH] Expose checkpoint timestamp and duration in pg_stat_checkpointer Soumya S Murali <[email protected]>
@ 2025-11-24 09:18 ` Michael Banck <[email protected]>
2025-11-24 10:07 ` Re: [PATCH] Expose checkpoint timestamp and duration in pg_stat_checkpointer Álvaro Herrera <[email protected]>
1 sibling, 1 reply; 31+ messages in thread
From: Michael Banck @ 2025-11-24 09:18 UTC (permalink / raw)
To: Soumya S Murali <[email protected]>; +Cc: [email protected]; [email protected]
Hi,
On Mon, Nov 24, 2025 at 11:40:44AM +0530, Soumya S Murali wrote:
> While debugging checkpointer write behavior, I recently found some of the
> enhancements related to extending pg_stat_checkpointer by including
> checkpoint type (manual/timed/immediate), last_checkpoint_time and
> checkpoint_total_time information to checkpoint completion logs through SQL
> when `log_checkpoints` is enabled. I am attaching my observations,
> screenshots and patch in support for this.
>
> 1. Log for type of checkpoint occured:
>
> 2025-11-20 11:51:06.128 IST [18026] LOG: checkpoint complete
> (immediate): wrote 7286 buffers (44.5%), wrote 4 SLRU buffers; 0 WAL
> file(s) added, 0 removed, 27 recycled; write=0.095 s, sync=0.034 s,
> total=0.279 s; sync files=17, longest=0.004 s, average=0.002 s;
> distance=447382 kB, estimate=531349 kB; lsn=0/7F4EDED8, redo
> lsn=0/7F4EDE80
I think that'd be useful; the checkpoint complete log line clearly has
the more interesting output, and having it state the type would make it
easier to answer question like "how many buffers did the last wal-based
checkpoint write?
> 2. Log for the checkpoint_total_time and last_checkpoint_time:
>
> checkpoint_total_time | last_checkpoint_time
> -----------------------+----------------------------------
> 175138 | 2025-11-20 11:58:02.879149+05:30
> (1 row)
Reading throught the patch, it looks like checkpoint_total_time is the
total time of the last checkpoint?
> + proparallel => 'r', prorettype => 'float8', proargtypes => '',
> + prosrc => 'pg_stat_get_checkpointer_checkpoint_total_time' },
If so, the naming is pretty confusing, last_checkpoint_duration or
something might be clearer.
In general I doubt how much those gauges (as oppposed to counters) only
pertaining to the last checkpoint are useful in pg_stat_checkpointer.
What would be the use case for those two values?
Also, as a nitpick, your patch adds unnecessary newlines and I think
stats_reset should be kept as last column in pg_stat_checkpointer as
usual.
Michael
^ permalink raw reply [nested|flat] 31+ messages in thread
* Re: [PATCH] Expose checkpoint timestamp and duration in pg_stat_checkpointer
2025-11-24 06:10 [PATCH] Expose checkpoint timestamp and duration in pg_stat_checkpointer Soumya S Murali <[email protected]>
2025-11-24 09:18 ` Re: [PATCH] Expose checkpoint timestamp and duration in pg_stat_checkpointer Michael Banck <[email protected]>
@ 2025-11-24 10:07 ` Álvaro Herrera <[email protected]>
2025-11-24 11:05 ` Re: [PATCH] Expose checkpoint timestamp and duration in pg_stat_checkpointer Michael Banck <[email protected]>
2025-11-26 10:15 ` Re: [PATCH] Expose checkpoint timestamp and duration in pg_stat_checkpointer Soumya S Murali <[email protected]>
2025-11-28 04:53 ` Re: [PATCH] Expose checkpoint timestamp and duration in pg_stat_checkpointer Soumya S Murali <[email protected]>
0 siblings, 3 replies; 31+ messages in thread
From: Álvaro Herrera @ 2025-11-24 10:07 UTC (permalink / raw)
To: Michael Banck <[email protected]>; +Cc: Soumya S Murali <[email protected]>; [email protected]; [email protected]
On 2025-Nov-24, Michael Banck wrote:
> In general I doubt how much those gauges (as oppposed to counters) only
> pertaining to the last checkpoint are useful in pg_stat_checkpointer.
> What would be the use case for those two values?
I think it's useful to know how long checkpoint has to work. It's a bit
lame to have only one duration (the last one), but at least with this
arrangement you can have external monitoring software connect to the
server, extract that value and save it somewhere else. Monitoring
systems do this all the time, and we've been waiting for a better
implementation to store monitoring data inside Postgres for years. I
think we shouldn't block this proposal just because of this issue,
because it can clearly be useful.
However, I'm not sure I'm very interested in knowing only the duration
of the checkpoint. I mean, much of the time the duration is going to be
whatever fraction of the checkpoint timeout you have as
checkpoint_completion_target, right? Which includes sleeps. So I think
you really want two durations: one is the duration itself, and the other
is what fraction of that did the checkpointer sleep in order to achieve
that duration. So you know how much time checkpointer spent trying to
get the operating system do stuff rather than just sit there waiting.
We already have that data, kinda, in write_time and sync_time, but those
are cumulative rather than just for the last one. (I guess you can have
the monitoring system compute the deltas as it finds each new
checkpoint.) I'm not sure how good this system is.
In the past, I looked at a couple of monitoring dashboards offered by
cloud vendors, searching for anything valuable in terms of checkpoints.
What I saw was very disappointing -- mostly just "how many checkpoints
per minute", which is mostly flat zero with periodic spikes. Totally
useless. Does anybody know if some vendor has good charts for this?
Also, if we were to add this new proposed duration, how could these
charts improve?
--
Álvaro Herrera Breisgau, Deutschland — https://www.EnterpriseDB.com/
"How strange it is to find the words "Perl" and "saner" in such close
proximity, with no apparent sense of irony. I doubt that Larry himself
could have managed it." (ncm, http://lwn.net/Articles/174769/)
^ permalink raw reply [nested|flat] 31+ messages in thread
* Re: [PATCH] Expose checkpoint timestamp and duration in pg_stat_checkpointer
2025-11-24 06:10 [PATCH] Expose checkpoint timestamp and duration in pg_stat_checkpointer Soumya S Murali <[email protected]>
2025-11-24 09:18 ` Re: [PATCH] Expose checkpoint timestamp and duration in pg_stat_checkpointer Michael Banck <[email protected]>
2025-11-24 10:07 ` Re: [PATCH] Expose checkpoint timestamp and duration in pg_stat_checkpointer Álvaro Herrera <[email protected]>
@ 2025-11-24 11:05 ` Michael Banck <[email protected]>
2 siblings, 0 replies; 31+ messages in thread
From: Michael Banck @ 2025-11-24 11:05 UTC (permalink / raw)
To: Álvaro Herrera <[email protected]>; +Cc: Soumya S Murali <[email protected]>; [email protected]; [email protected]
Hi,
On Mon, Nov 24, 2025 at 11:07:41AM +0100, Álvaro Herrera wrote:
> On 2025-Nov-24, Michael Banck wrote:
>
> > In general I doubt how much those gauges (as oppposed to counters) only
> > pertaining to the last checkpoint are useful in pg_stat_checkpointer.
> > What would be the use case for those two values?
>
> I think it's useful to know how long checkpoint has to work. It's a bit
> lame to have only one duration (the last one), but at least with this
> arrangement you can have external monitoring software connect to the
> server, extract that value and save it somewhere else. Monitoring
> systems do this all the time, and we've been waiting for a better
> implementation to store monitoring data inside Postgres for years. I
> think we shouldn't block this proposal just because of this issue,
> because it can clearly be useful.
I don't know - what happens if the monitoring systems reads those values
every minute, but then suddenly Postgres checkpoints every 20 seconds
due to a traffic spike? It would just not see those additional
checkpoints in this case, no?
What monitoring systems do (have to do) is query write_time + sync_time
as total_time in pg_stat_checkpointer and store that along with the
timestamp of the query. Then you (maybe awkwardly) generate a graph of
the checkpoint durations over time.
> However, I'm not sure I'm very interested in knowing only the duration
> of the checkpoint. I mean, much of the time the duration is going to be
> whatever fraction of the checkpoint timeout you have as
> checkpoint_completion_target, right? Which includes sleeps.
Yeah, that is the other thing I was wondering about, but did not mention
in my mail, good point.
> So I think you really want two durations: one is the duration itself,
> and the other is what fraction of that did the checkpointer sleep in
> order to achieve that duration. So you know how much time
> checkpointer spent trying to get the operating system do stuff rather
> than just sit there waiting. We already have that data, kinda, in
> write_time and sync_time, but those are cumulative rather than just
> for the last one.
I think that we either have "last timestamp whatever" or "total", but I
think we don't have "last duration" anywhere?
> (I guess you can have the monitoring system compute
> the deltas as it finds each new checkpoint.) I'm not sure how good
> this system is.
Right, this is what I meant above. But from what I see on PG18,
total_time just seems tbe write_time + sync_time, do we have the sleep
somewhere?
> In the past, I looked at a couple of monitoring dashboards offered by
> cloud vendors, searching for anything valuable in terms of checkpoints.
> What I saw was very disappointing -- mostly just "how many checkpoints
> per minute", which is mostly flat zero with periodic spikes. Totally
> useless. Does anybody know if some vendor has good charts for this?
> Also, if we were to add this new proposed duration, how could these
> charts improve?
I don't have a good answer here.
Michael
^ permalink raw reply [nested|flat] 31+ messages in thread
* Re: [PATCH] Expose checkpoint timestamp and duration in pg_stat_checkpointer
2025-11-24 06:10 [PATCH] Expose checkpoint timestamp and duration in pg_stat_checkpointer Soumya S Murali <[email protected]>
2025-11-24 09:18 ` Re: [PATCH] Expose checkpoint timestamp and duration in pg_stat_checkpointer Michael Banck <[email protected]>
2025-11-24 10:07 ` Re: [PATCH] Expose checkpoint timestamp and duration in pg_stat_checkpointer Álvaro Herrera <[email protected]>
@ 2025-11-26 10:15 ` Soumya S Murali <[email protected]>
2025-11-26 17:23 ` Re: [PATCH] Expose checkpoint timestamp and duration in pg_stat_checkpointer Juan José Santamaría Flecha <[email protected]>
2 siblings, 1 reply; 31+ messages in thread
From: Soumya S Murali @ 2025-11-26 10:15 UTC (permalink / raw)
To: Álvaro Herrera <[email protected]>; +Cc: Michael Banck <[email protected]>; [email protected]; [email protected]
On Mon, Nov 24, 2025 at 3:37 PM Álvaro Herrera <[email protected]> wrote:
>
> On 2025-Nov-24, Michael Banck wrote:
>
> > In general I doubt how much those gauges (as oppposed to counters) only
> > pertaining to the last checkpoint are useful in pg_stat_checkpointer.
> > What would be the use case for those two values?
>
> I think it's useful to know how long checkpoint has to work. It's a bit
> lame to have only one duration (the last one), but at least with this
> arrangement you can have external monitoring software connect to the
> server, extract that value and save it somewhere else. Monitoring
> systems do this all the time, and we've been waiting for a better
> implementation to store monitoring data inside Postgres for years. I
> think we shouldn't block this proposal just because of this issue,
> because it can clearly be useful.
>
> However, I'm not sure I'm very interested in knowing only the duration
> of the checkpoint. I mean, much of the time the duration is going to be
> whatever fraction of the checkpoint timeout you have as
> checkpoint_completion_target, right? Which includes sleeps. So I think
> you really want two durations: one is the duration itself, and the other
> is what fraction of that did the checkpointer sleep in order to achieve
> that duration. So you know how much time checkpointer spent trying to
> get the operating system do stuff rather than just sit there waiting.
> We already have that data, kinda, in write_time and sync_time, but those
> are cumulative rather than just for the last one. (I guess you can have
> the monitoring system compute the deltas as it finds each new
> checkpoint.) I'm not sure how good this system is.
Thank you for the detailed thoughts. I agree that having only the last
checkpoint’s duration is limited, but it still gives monitoring tools
a concrete value they can sample and store over time, which is better
than relying only on counters and logs. I will try whether separating
total duration and actual active write/sync time (vs. sleep time) can
be exposed in a more clearer way, as that seems useful for deeper
diagnosis.
> In the past, I looked at a couple of monitoring dashboards offered by
> cloud vendors, searching for anything valuable in terms of checkpoints.
> What I saw was very disappointing -- mostly just "how many checkpoints
> per minute", which is mostly flat zero with periodic spikes. Totally
> useless. Does anybody know if some vendor has good charts for this?
> Also, if we were to add this new proposed duration, how could these
> charts improve?
I will look into this in more depth. Will let you know if I find
something concrete.
Regards
Soumya
^ permalink raw reply [nested|flat] 31+ messages in thread
* Re: [PATCH] Expose checkpoint timestamp and duration in pg_stat_checkpointer
2025-11-24 06:10 [PATCH] Expose checkpoint timestamp and duration in pg_stat_checkpointer Soumya S Murali <[email protected]>
2025-11-24 09:18 ` Re: [PATCH] Expose checkpoint timestamp and duration in pg_stat_checkpointer Michael Banck <[email protected]>
2025-11-24 10:07 ` Re: [PATCH] Expose checkpoint timestamp and duration in pg_stat_checkpointer Álvaro Herrera <[email protected]>
2025-11-26 10:15 ` Re: [PATCH] Expose checkpoint timestamp and duration in pg_stat_checkpointer Soumya S Murali <[email protected]>
@ 2025-11-26 17:23 ` Juan José Santamaría Flecha <[email protected]>
2025-11-26 17:41 ` Re: [PATCH] Expose checkpoint timestamp and duration in pg_stat_checkpointer Michael Banck <[email protected]>
2025-11-27 11:39 ` Re: [PATCH] Expose checkpoint timestamp and duration in pg_stat_checkpointer Soumya S Murali <[email protected]>
0 siblings, 2 replies; 31+ messages in thread
From: Juan José Santamaría Flecha @ 2025-11-26 17:23 UTC (permalink / raw)
To: Soumya S Murali <[email protected]>; +Cc: Álvaro Herrera <[email protected]>; Michael Banck <[email protected]>; PostgreSQL Hackers <[email protected]>; [email protected]
El mié, 26 nov 2025, 11:14, Soumya S Murali <[email protected]>
escribió:
> On Mon, Nov 24, 2025 at 3:37 PM Álvaro Herrera <[email protected]>
> wrote:
>
> > In the past, I looked at a couple of monitoring dashboards offered by
> > cloud vendors, searching for anything valuable in terms of checkpoints.
> > What I saw was very disappointing -- mostly just "how many checkpoints
> > per minute", which is mostly flat zero with periodic spikes. Totally
> > useless. Does anybody know if some vendor has good charts for this?
> > Also, if we were to add this new proposed duration, how could these
> > charts improve?
>
> I will look into this in more depth. Will let you know if I find
> something concrete.
>
There is a "Checkpoints" section in the pgbadger reports, and that's
probably the most widely used tool.
Regards
Juan José Santamaría Flecha
>
^ permalink raw reply [nested|flat] 31+ messages in thread
* Re: [PATCH] Expose checkpoint timestamp and duration in pg_stat_checkpointer
2025-11-24 06:10 [PATCH] Expose checkpoint timestamp and duration in pg_stat_checkpointer Soumya S Murali <[email protected]>
2025-11-24 09:18 ` Re: [PATCH] Expose checkpoint timestamp and duration in pg_stat_checkpointer Michael Banck <[email protected]>
2025-11-24 10:07 ` Re: [PATCH] Expose checkpoint timestamp and duration in pg_stat_checkpointer Álvaro Herrera <[email protected]>
2025-11-26 10:15 ` Re: [PATCH] Expose checkpoint timestamp and duration in pg_stat_checkpointer Soumya S Murali <[email protected]>
2025-11-26 17:23 ` Re: [PATCH] Expose checkpoint timestamp and duration in pg_stat_checkpointer Juan José Santamaría Flecha <[email protected]>
@ 2025-11-26 17:41 ` Michael Banck <[email protected]>
1 sibling, 0 replies; 31+ messages in thread
From: Michael Banck @ 2025-11-26 17:41 UTC (permalink / raw)
To: Juan José Santamaría Flecha <[email protected]>; +Cc: Soumya S Murali <[email protected]>; Álvaro Herrera <[email protected]>; PostgreSQL Hackers <[email protected]>; [email protected]
Hi,
On Wed, Nov 26, 2025 at 06:23:08PM +0100, Juan José Santamaría Flecha wrote:
> El mié, 26 nov 2025, 11:14, Soumya S Murali <[email protected]>
> escribió:
> There is a "Checkpoints" section in the pgbadger reports, and that's
> probably the most widely used tool.
That one parses the Postgres logs, so is unaffected by the changes to
pg_stat_checkpointer discussed here.
Michael
^ permalink raw reply [nested|flat] 31+ messages in thread
* Re: [PATCH] Expose checkpoint timestamp and duration in pg_stat_checkpointer
2025-11-24 06:10 [PATCH] Expose checkpoint timestamp and duration in pg_stat_checkpointer Soumya S Murali <[email protected]>
2025-11-24 09:18 ` Re: [PATCH] Expose checkpoint timestamp and duration in pg_stat_checkpointer Michael Banck <[email protected]>
2025-11-24 10:07 ` Re: [PATCH] Expose checkpoint timestamp and duration in pg_stat_checkpointer Álvaro Herrera <[email protected]>
2025-11-26 10:15 ` Re: [PATCH] Expose checkpoint timestamp and duration in pg_stat_checkpointer Soumya S Murali <[email protected]>
2025-11-26 17:23 ` Re: [PATCH] Expose checkpoint timestamp and duration in pg_stat_checkpointer Juan José Santamaría Flecha <[email protected]>
@ 2025-11-27 11:39 ` Soumya S Murali <[email protected]>
1 sibling, 0 replies; 31+ messages in thread
From: Soumya S Murali @ 2025-11-27 11:39 UTC (permalink / raw)
To: Michael Banck <[email protected]>; [email protected]; +Cc: Álvaro Herrera <[email protected]>; PostgreSQL Hackers <[email protected]>; [email protected]
Hi all,
On Wed, Nov 26, 2025 at 11:11 PM Michael Banck <[email protected]> wrote:
>
> Hi,
>
> On Wed, Nov 26, 2025 at 06:23:08PM +0100, Juan José Santamaría Flecha wrote:
> > El mié, 26 nov 2025, 11:14, Soumya S Murali <[email protected]>
> > escribió:
> > There is a "Checkpoints" section in the pgbadger reports, and that's
> > probably the most widely used tool.
>
> That one parses the Postgres logs, so is unaffected by the changes to
> pg_stat_checkpointer discussed here.
Thank you for the suggestions. I will refer to how pgbadger visualizes
checkpoints and also will check whether any other monitoring tools
provide meaningful checkpoint charts. If I find anything useful, I’ll
share it.
Regards,
Soumya
^ permalink raw reply [nested|flat] 31+ messages in thread
* Re: [PATCH] Expose checkpoint timestamp and duration in pg_stat_checkpointer
2025-11-24 06:10 [PATCH] Expose checkpoint timestamp and duration in pg_stat_checkpointer Soumya S Murali <[email protected]>
2025-11-24 09:18 ` Re: [PATCH] Expose checkpoint timestamp and duration in pg_stat_checkpointer Michael Banck <[email protected]>
2025-11-24 10:07 ` Re: [PATCH] Expose checkpoint timestamp and duration in pg_stat_checkpointer Álvaro Herrera <[email protected]>
@ 2025-11-28 04:53 ` Soumya S Murali <[email protected]>
2025-11-28 08:08 ` Re: [PATCH] Expose checkpoint timestamp and duration in pg_stat_checkpointer Michael Banck <[email protected]>
2025-12-01 05:35 ` Re: [PATCH] Expose checkpoint timestamp and duration in pg_stat_checkpointer Soumya S Murali <[email protected]>
2 siblings, 2 replies; 31+ messages in thread
From: Soumya S Murali @ 2025-11-28 04:53 UTC (permalink / raw)
To: Michael Banck <[email protected]>; Álvaro Herrera <[email protected]>; +Cc: [email protected]; [email protected]; [email protected]
Hi all,
I have updated the code based on the feedback received to my earlier
mails and prepared a patch for further review. In this patch, I have
renamed the checkpoint_total_time to last_checkpoint_duration,
stats_reset has been kept as the last column following the usual
pattern, last_checkpoint_duration and last_checkpoint_time will now be
overwritten per checkpoint and also have removed unnecessary lines as
per the usual format. I had successfully verified the checkpointer
duration with different write loads and I am attaching the
observations for further reference.
pgbench -c 8 -j 8 -T 30 -p 55432 postgres
pgbench (19devel)
starting vacuum...end.
transaction type: <builtin: TPC-B (sort of)>
scaling factor: 50
query mode: simple
number of clients: 8
number of threads: 8
maximum number of tries: 1
duration: 30 s
number of transactions actually processed: 55936
number of failed transactions: 0 (0.000%)
latency average = 4.290 ms
initial connection time = 7.107 ms
tps = 1864.846690 (without initial connection time)
pgbench -c 16 -j 8 -T 60 -p 55432 postgres
pgbench (19devel)
starting vacuum...end.
transaction type: <builtin: TPC-B (sort of)>
scaling factor: 50
query mode: simple
number of clients: 16
number of threads: 8
maximum number of tries: 1
duration: 60 s
number of transactions actually processed: 196974
number of failed transactions: 0 (0.000%)
latency average = 4.873 ms
initial connection time = 12.535 ms
tps = 3283.407286 (without initial connection time)
postgres=# SELECT last_checkpoint_duration, last_checkpoint_time,
write_time, sync_time, buffers_written FROM pg_stat_checkpoint
er;
last_checkpoint_duration | last_checkpoint_time |
write_time | sync_time | buffers_written
--------------------------+----------------------------------+------------+-----------+-----------------
23940 | 2025-11-28 10:02:29.298905+05:30 |
104873 | 811 | 3468
(1 row)
CHECKPOINT
sleep 1
postgres=# SELECT last_checkpoint_duration, last_checkpoint_time,
write_time, sync_time, buffers_written FROM pg_stat_checkpointer;
last_checkpoint_duration | last_checkpoint_time |
write_time | sync_time | buffers_written
--------------------------+----------------------------------+------------+-----------+-----------------
332 | 2025-11-28 10:03:57.828072+05:30 |
104979 | 857 | 10453
(1 row)
2025-11-28 10:03:57.828 IST [11343] LOG: checkpoint complete
(immediate): wrote 6985 buffers (42.6%), wrote 11 SLRU buffers; 0 WAL
file(s) added, 0 removed, 32 recycled; write=0.106 s, sync=0.046 s,
total=0.332 s; sync files=23, longest=0.004 s, average=0.002 s;
distance=538440 kB, estimate=540445 kB; lsn=0/84DDA138, redo
lsn=0/84DDA0E0
I hope these observations are helpful for further analysis. Thank you
for the earlier reviews and helpful suggestions. Looking forward to
more feedback.
Regards,
Soumya
Attachments:
[application/x-patch] 0001-Improve-checkpoint-logging-and-expose-last-checkpoin.patch (6.6K, ../../CAMtXxw_v046f8OtNXNQ7z930gQhbrevM0SMFvY2ar7LG9uDnMw@mail.gmail.com/2-0001-Improve-checkpoint-logging-and-expose-last-checkpoin.patch)
download | inline diff:
From 5ac32acb618b563f3e8088afe9f026651c820b8b Mon Sep 17 00:00:00 2001
From: BharatDB <[email protected]>
Date: Thu, 27 Nov 2025 16:43:00 +0530
Subject: [PATCH] Improve checkpoint logging and expose last checkpoint
duration in pg_stat_checkpointer
Signed-off-by: BharatDB <[email protected]>
---
src/backend/access/transam/xlog.c | 2 +-
src/backend/catalog/system_views.sql | 6 ++--
.../utils/activity/pgstat_checkpointer.c | 32 +++----------------
src/backend/utils/adt/pgstatfuncs.c | 8 +++--
src/include/catalog/pg_proc.dat | 4 +--
src/include/pgstat.h | 2 +-
6 files changed, 17 insertions(+), 37 deletions(-)
diff --git a/src/backend/access/transam/xlog.c b/src/backend/access/transam/xlog.c
index 9217508917..4a45f4f708 100644
--- a/src/backend/access/transam/xlog.c
+++ b/src/backend/access/transam/xlog.c
@@ -6778,7 +6778,7 @@ LogCheckpointEnd(bool restartpoint, int flags)
/* Store in PendingCheckpointerStats */
- PendingCheckpointerStats.checkpoint_total_time += (double) total_msecs;
+ PendingCheckpointerStats.last_checkpoint_duration = (double) total_msecs;
PendingCheckpointerStats.last_checkpoint_time = CheckpointStats.ckpt_end_t;
/* Publishing it */
diff --git a/src/backend/catalog/system_views.sql b/src/backend/catalog/system_views.sql
index 903e001d95..a90f64494f 100644
--- a/src/backend/catalog/system_views.sql
+++ b/src/backend/catalog/system_views.sql
@@ -1190,9 +1190,9 @@ CREATE VIEW pg_stat_checkpointer AS
pg_stat_get_checkpointer_sync_time() AS sync_time,
pg_stat_get_checkpointer_buffers_written() AS buffers_written,
pg_stat_get_checkpointer_slru_written() AS slru_written,
- pg_stat_get_checkpointer_stat_reset_time() AS stats_reset,
- pg_stat_get_checkpointer_checkpoint_total_time() AS checkpoint_total_time,
- pg_stat_get_checkpointer_last_checkpoint_time() AS last_checkpoint_time;
+ pg_stat_get_checkpointer_last_checkpoint_duration() AS last_checkpoint_duration,
+ pg_stat_get_checkpointer_last_checkpoint_time() AS last_checkpoint_time,
+ pg_stat_get_checkpointer_stat_reset_time() AS stats_reset;
CREATE VIEW pg_stat_io AS
SELECT
diff --git a/src/backend/utils/activity/pgstat_checkpointer.c b/src/backend/utils/activity/pgstat_checkpointer.c
index 62ef427b82..ec51874af7 100644
--- a/src/backend/utils/activity/pgstat_checkpointer.c
+++ b/src/backend/utils/activity/pgstat_checkpointer.c
@@ -56,10 +56,13 @@ pgstat_report_checkpointer(void)
CHECKPOINTER_ACC(sync_time);
CHECKPOINTER_ACC(buffers_written);
CHECKPOINTER_ACC(slru_written);
- CHECKPOINTER_ACC(checkpoint_total_time);
#undef CHECKPOINTER_ACC
/* only overwrite if we actually have a new timestamp */
+ if (PendingCheckpointerStats.last_checkpoint_duration > 0)
+ stats_shmem->stats.last_checkpoint_duration =
+ PendingCheckpointerStats.last_checkpoint_duration;
+
if (PendingCheckpointerStats.last_checkpoint_time != 0)
stats_shmem->stats.last_checkpoint_time =
PendingCheckpointerStats.last_checkpoint_time;
@@ -77,28 +80,6 @@ pgstat_report_checkpointer(void)
pgstat_flush_io(false);
}
-/* ------------------------------------------------------------
- * Extended checkpointer stats reporting function
- * ------------------------------------------------------------
- */
-void
-pgstat_report_checkpointer_extended(long total_msecs, TimestampTz end_time)
-{
-
- PgStat_CheckpointerStats *checkpointer_stats;
-
-
- checkpointer_stats = pgstat_fetch_stat_checkpointer();
- if (!checkpointer_stats)
- return;
-
-
- checkpointer_stats->checkpoint_total_time += total_msecs;
- checkpointer_stats->last_checkpoint_time = end_time;
-
-}
-
-
/*
* pgstat_fetch_stat_checkpointer() -
*
@@ -164,11 +145,8 @@ pgstat_checkpointer_snapshot_cb(void)
CHECKPOINTER_COMP(sync_time);
CHECKPOINTER_COMP(buffers_written);
CHECKPOINTER_COMP(slru_written);
- CHECKPOINTER_COMP(checkpoint_total_time);
+ CHECKPOINTER_COMP(last_checkpoint_duration);
#undef CHECKPOINTER_COMP
pgStatLocal.snapshot.checkpointer.last_checkpoint_time = stats_shmem->stats.last_checkpoint_time;
-
- elog(LOG, "DBG snapshot_cb: copied last_checkpoint_time=%ld",
- (long) pgStatLocal.snapshot.checkpointer.last_checkpoint_time);
}
diff --git a/src/backend/utils/adt/pgstatfuncs.c b/src/backend/utils/adt/pgstatfuncs.c
index 591ad2ac88..57a1853ab1 100644
--- a/src/backend/utils/adt/pgstatfuncs.c
+++ b/src/backend/utils/adt/pgstatfuncs.c
@@ -2293,13 +2293,15 @@ pg_stat_have_stats(PG_FUNCTION_ARGS)
PG_RETURN_BOOL(pgstat_have_entry(kind, dboid, objid));
}
-PG_FUNCTION_INFO_V1(pg_stat_get_checkpointer_checkpoint_total_time);
+PG_FUNCTION_INFO_V1(pg_stat_get_checkpointer_last_checkpoint_duration);
Datum
-pg_stat_get_checkpointer_checkpoint_total_time(PG_FUNCTION_ARGS)
+pg_stat_get_checkpointer_last_checkpoint_duration(PG_FUNCTION_ARGS)
{
PgStat_CheckpointerStats *stats = pgstat_fetch_stat_checkpointer();
- PG_RETURN_FLOAT8(stats->checkpoint_total_time);
+ if (!stats)
+ PG_RETURN_NULL();
+ PG_RETURN_FLOAT8(stats->last_checkpoint_duration);
}
PG_FUNCTION_INFO_V1(pg_stat_get_checkpointer_last_checkpoint_time);
diff --git a/src/include/catalog/pg_proc.dat b/src/include/catalog/pg_proc.dat
index a57053c4e2..043bf854bc 100644
--- a/src/include/catalog/pg_proc.dat
+++ b/src/include/catalog/pg_proc.dat
@@ -5983,9 +5983,9 @@
# New functions for checkpointer
{ oid => '7000',
descr => 'total time spent in last checkpoint in milliseconds',
- proname => 'pg_stat_get_checkpointer_checkpoint_total_time', provolatile => 's',
+ proname => 'pg_stat_get_checkpointer_last_checkpoint_duration', provolatile => 's',
proparallel => 'r', prorettype => 'float8', proargtypes => '',
- prosrc => 'pg_stat_get_checkpointer_checkpoint_total_time' },
+ prosrc => 'pg_stat_get_checkpointer_last_checkpoint_duration' },
{ oid => '7001',
descr => 'timestamp of last checkpoint completion',
proname => 'pg_stat_get_checkpointer_last_checkpoint_time', provolatile => 's',
diff --git a/src/include/pgstat.h b/src/include/pgstat.h
index a8eb1f8add..73688041c8 100644
--- a/src/include/pgstat.h
+++ b/src/include/pgstat.h
@@ -263,7 +263,7 @@ typedef struct PgStat_CheckpointerStats
PgStat_Counter sync_time;
PgStat_Counter buffers_written;
PgStat_Counter slru_written;
- PgStat_Counter checkpoint_total_time; /* new: total ms of last checkpoint */
+ PgStat_Counter last_checkpoint_duration; /* new: total ms of last checkpoint */
TimestampTz last_checkpoint_time; /* new: end time of last checkpoint */
TimestampTz stat_reset_timestamp;
} PgStat_CheckpointerStats;
--
2.34.1
^ permalink raw reply [nested|flat] 31+ messages in thread
* Re: [PATCH] Expose checkpoint timestamp and duration in pg_stat_checkpointer
2025-11-24 06:10 [PATCH] Expose checkpoint timestamp and duration in pg_stat_checkpointer Soumya S Murali <[email protected]>
2025-11-24 09:18 ` Re: [PATCH] Expose checkpoint timestamp and duration in pg_stat_checkpointer Michael Banck <[email protected]>
2025-11-24 10:07 ` Re: [PATCH] Expose checkpoint timestamp and duration in pg_stat_checkpointer Álvaro Herrera <[email protected]>
2025-11-28 04:53 ` Re: [PATCH] Expose checkpoint timestamp and duration in pg_stat_checkpointer Soumya S Murali <[email protected]>
@ 2025-11-28 08:08 ` Michael Banck <[email protected]>
1 sibling, 0 replies; 31+ messages in thread
From: Michael Banck @ 2025-11-28 08:08 UTC (permalink / raw)
To: Soumya S Murali <[email protected]>; +Cc: Álvaro Herrera <[email protected]>; [email protected]; [email protected]; [email protected]
Hi,
On Fri, Nov 28, 2025 at 10:23:54AM +0530, Soumya S Murali wrote:
> I have updated the code based on the feedback received to my earlier
> mails and prepared a patch for further review.
I think the logging change and the pg_stat_checkpointer changes are
different enough that they should be separate patches. If not just
because the logging change seems to not have had any non-positive
feedback.
> In this patch, I have renamed the checkpoint_total_time to
> last_checkpoint_duration, stats_reset has been kept as the last column
> following the usual pattern, last_checkpoint_duration and
> last_checkpoint_time will now be overwritten per checkpoint and also
> have removed unnecessary lines as per the usual format. I had
> successfully verified the checkpointer duration with different write
> loads and I am attaching the observations for further reference.
I am still not convinced of the usefulness of those changes to
pg_stat_checkpointer, but some feedback on the patch:
diff --git a/src/backend/access/transam/xlog.c b/src/backend/access/transam/xlog.c
index 9217508917..4a45f4f708 100644
--- a/src/backend/access/transam/xlog.c
+++ b/src/backend/access/transam/xlog.c
@@ -6778,7 +6778,7 @@ LogCheckpointEnd(bool restartpoint, int flags)
/* Store in PendingCheckpointerStats */
- PendingCheckpointerStats.checkpoint_total_time += (double) total_msecs;
+ PendingCheckpointerStats.last_checkpoint_duration = (double) total_msecs;
PendingCheckpointerStats.last_checkpoint_time = CheckpointStats.ckpt_end_t;
[...]
diff --git a/src/include/pgstat.h b/src/include/pgstat.h
index a8eb1f8add..73688041c8 100644
--- a/src/include/pgstat.h
+++ b/src/include/pgstat.h
@@ -263,7 +263,7 @@ typedef struct PgStat_CheckpointerStats
PgStat_Counter sync_time;
PgStat_Counter buffers_written;
PgStat_Counter slru_written;
- PgStat_Counter checkpoint_total_time; /* new: total ms of last checkpoint */
+ PgStat_Counter last_checkpoint_duration; /* new: total ms of last checkpoint */
TimestampTz last_checkpoint_time; /* new: end time of last checkpoint */
TimestampTz stat_reset_timestamp;
} PgStat_CheckpointerStats;
This looks like an incremental patch based on your original one? It is
customary to send the full, updated, patch again.
Michael
^ permalink raw reply [nested|flat] 31+ messages in thread
* Re: [PATCH] Expose checkpoint timestamp and duration in pg_stat_checkpointer
2025-11-24 06:10 [PATCH] Expose checkpoint timestamp and duration in pg_stat_checkpointer Soumya S Murali <[email protected]>
2025-11-24 09:18 ` Re: [PATCH] Expose checkpoint timestamp and duration in pg_stat_checkpointer Michael Banck <[email protected]>
2025-11-24 10:07 ` Re: [PATCH] Expose checkpoint timestamp and duration in pg_stat_checkpointer Álvaro Herrera <[email protected]>
2025-11-28 04:53 ` Re: [PATCH] Expose checkpoint timestamp and duration in pg_stat_checkpointer Soumya S Murali <[email protected]>
@ 2025-12-01 05:35 ` Soumya S Murali <[email protected]>
2025-12-01 08:15 ` Re: [PATCH] Expose checkpoint timestamp and duration in pg_stat_checkpointer Michael Banck <[email protected]>
2025-12-04 05:13 ` Re: [PATCH] Expose checkpoint timestamp and duration in pg_stat_checkpointer Soumya S Murali <[email protected]>
1 sibling, 2 replies; 31+ messages in thread
From: Soumya S Murali @ 2025-12-01 05:35 UTC (permalink / raw)
To: Michael Banck <[email protected]>; +Cc: Álvaro Herrera <[email protected]>; [email protected]; [email protected]; [email protected]
Hi all,
> On Fri, Nov 28, 2025 at 10:23:54AM +0530, Soumya S Murali wrote:
> > I have updated the code based on the feedback received to my earlier
> > mails and prepared a patch for further review.
>
> I think the logging change and the pg_stat_checkpointer changes are
> different enough that they should be separate patches. If not just
> because the logging change seems to not have had any non-positive
> feedback.
Thank you for the review and for the clarification. I understand the
point about separating the logging change and the pg_stat_checkpointer
additions. As per the suggestion, I will make sure to split them into
two independent patches before sending the updated one.
> > In this patch, I have renamed the checkpoint_total_time to
> > last_checkpoint_duration, stats_reset has been kept as the last column
> > following the usual pattern, last_checkpoint_duration and
> > last_checkpoint_time will now be overwritten per checkpoint and also
> > have removed unnecessary lines as per the usual format. I had
> > successfully verified the checkpointer duration with different write
> > loads and I am attaching the observations for further reference.
>
> I am still not convinced of the usefulness of those changes to
> pg_stat_checkpointer, but some feedback on the patch:
According to my understanding, The monitoring systems can already poll
pg_stat_checkpointer at a reasonable frequency but with the checkpoint
duration values exposed, I think it will be easier to compute - the
checkpoint deltas, fluctuations in duration, notice unusualities and
the timing instabilities in WAL-driven checkpoints etc. These may seem
simple but are useful signals that many existing monitoring dashboards
lack today.
> diff --git a/src/backend/access/transam/xlog.c b/src/backend/access/transam/xlog.c
> index 9217508917..4a45f4f708 100644
> --- a/src/backend/access/transam/xlog.c
> +++ b/src/backend/access/transam/xlog.c
> @@ -6778,7 +6778,7 @@ LogCheckpointEnd(bool restartpoint, int flags)
>
>
> /* Store in PendingCheckpointerStats */
> - PendingCheckpointerStats.checkpoint_total_time += (double) total_msecs;
> + PendingCheckpointerStats.last_checkpoint_duration = (double) total_msecs;
> PendingCheckpointerStats.last_checkpoint_time = CheckpointStats.ckpt_end_t;
>
> [...]
>
> diff --git a/src/include/pgstat.h b/src/include/pgstat.h
> index a8eb1f8add..73688041c8 100644
> --- a/src/include/pgstat.h
> +++ b/src/include/pgstat.h
> @@ -263,7 +263,7 @@ typedef struct PgStat_CheckpointerStats
> PgStat_Counter sync_time;
> PgStat_Counter buffers_written;
> PgStat_Counter slru_written;
> - PgStat_Counter checkpoint_total_time; /* new: total ms of last checkpoint */
> + PgStat_Counter last_checkpoint_duration; /* new: total ms of last checkpoint */
> TimestampTz last_checkpoint_time; /* new: end time of last checkpoint */
> TimestampTz stat_reset_timestamp;
> } PgStat_CheckpointerStats;
>
> This looks like an incremental patch based on your original one? It is
> customary to send the full, updated, patch again.
>
>
> Michael
Ok noted. I will resend a full updated patch set soon and will make
sure every updation goes as per the intended flow.
Thank you for the guidance. Looking forward to more feedback.
Regards,
Soumya
^ permalink raw reply [nested|flat] 31+ messages in thread
* Re: [PATCH] Expose checkpoint timestamp and duration in pg_stat_checkpointer
2025-11-24 06:10 [PATCH] Expose checkpoint timestamp and duration in pg_stat_checkpointer Soumya S Murali <[email protected]>
2025-11-24 09:18 ` Re: [PATCH] Expose checkpoint timestamp and duration in pg_stat_checkpointer Michael Banck <[email protected]>
2025-11-24 10:07 ` Re: [PATCH] Expose checkpoint timestamp and duration in pg_stat_checkpointer Álvaro Herrera <[email protected]>
2025-11-28 04:53 ` Re: [PATCH] Expose checkpoint timestamp and duration in pg_stat_checkpointer Soumya S Murali <[email protected]>
2025-12-01 05:35 ` Re: [PATCH] Expose checkpoint timestamp and duration in pg_stat_checkpointer Soumya S Murali <[email protected]>
@ 2025-12-01 08:15 ` Michael Banck <[email protected]>
1 sibling, 0 replies; 31+ messages in thread
From: Michael Banck @ 2025-12-01 08:15 UTC (permalink / raw)
To: Soumya S Murali <[email protected]>; +Cc: Álvaro Herrera <[email protected]>; [email protected]; [email protected]; [email protected]
Hi,
On Mon, Dec 01, 2025 at 11:05:19AM +0530, Soumya S Murali wrote:
> > On Fri, Nov 28, 2025 at 10:23:54AM +0530, Soumya S Murali wrote:
> > I am still not convinced of the usefulness of those changes to
> > pg_stat_checkpointer, but some feedback on the patch:
>
> According to my understanding, The monitoring systems can already poll
> pg_stat_checkpointer at a reasonable frequency but with the checkpoint
> duration values exposed, I think it will be easier to compute - the
> checkpoint deltas, fluctuations in duration, notice unusualities and
> the timing instabilities in WAL-driven checkpoints etc. These may seem
> simple but are useful signals that many existing monitoring dashboards
> lack today.
How would such a computation look like? Maybe if you give an example, it
would be easier to understand how this would make things better/more
robust.
I mentioned up-thread that one problem would be multiple checkpoints
having happened between two monitoring runs, where the monitoring system
sees the duration of the last checkpoint, but maybe more than one
happened. Should they keep track of the number of overall checkpoints
and adjust in that case?
To be more general: we don't store the last duration anywhere else (as
far as I can see, happy to be prove wrong), why is this essential for
checkpoint duration, and not other things? Or to put it another way: why
does the patch change it for checkpoint but not all the other places?
Michael
^ permalink raw reply [nested|flat] 31+ messages in thread
* Re: [PATCH] Expose checkpoint timestamp and duration in pg_stat_checkpointer
2025-11-24 06:10 [PATCH] Expose checkpoint timestamp and duration in pg_stat_checkpointer Soumya S Murali <[email protected]>
2025-11-24 09:18 ` Re: [PATCH] Expose checkpoint timestamp and duration in pg_stat_checkpointer Michael Banck <[email protected]>
2025-11-24 10:07 ` Re: [PATCH] Expose checkpoint timestamp and duration in pg_stat_checkpointer Álvaro Herrera <[email protected]>
2025-11-28 04:53 ` Re: [PATCH] Expose checkpoint timestamp and duration in pg_stat_checkpointer Soumya S Murali <[email protected]>
2025-12-01 05:35 ` Re: [PATCH] Expose checkpoint timestamp and duration in pg_stat_checkpointer Soumya S Murali <[email protected]>
@ 2025-12-04 05:13 ` Soumya S Murali <[email protected]>
2026-05-15 06:27 ` Re: [PATCH] Expose checkpoint timestamp and duration in pg_stat_checkpointer Soumya S Murali <[email protected]>
1 sibling, 1 reply; 31+ messages in thread
From: Soumya S Murali @ 2025-12-04 05:13 UTC (permalink / raw)
To: Michael Banck <[email protected]>; +Cc: Álvaro Herrera <[email protected]>; [email protected]; [email protected]; [email protected]
Hi all,
Thank you for the review and kind feedback.
On Mon, Dec 1, 2025 at 1:45 PM Michael Banck <[email protected]> wrote:
>
> Hi,
>
> On Mon, Dec 01, 2025 at 11:05:19AM +0530, Soumya S Murali wrote:
> > > On Fri, Nov 28, 2025 at 10:23:54AM +0530, Soumya S Murali wrote:
> > > I am still not convinced of the usefulness of those changes to
> > > pg_stat_checkpointer, but some feedback on the patch:
> >
> > According to my understanding, The monitoring systems can already poll
> > pg_stat_checkpointer at a reasonable frequency but with the checkpoint
> > duration values exposed, I think it will be easier to compute - the
> > checkpoint deltas, fluctuations in duration, notice unusualities and
> > the timing instabilities in WAL-driven checkpoints etc. These may seem
> > simple but are useful signals that many existing monitoring dashboards
> > lack today.
>
> How would such a computation look like? Maybe if you give an example, it
> would be easier to understand how this would make things better/more
> robust.
Consider a monitoring agent polls pg_stat_checkpointer every 30
seconds, It will read total write_time, total sync_time, counters and
the last checkpoint duration and timestamp (as in my proposal). Even
if multiple checkpoints happen between two samples, having the last
duration and last timestamp allows the monitoring system to spot
sudden slow checkpoints. For eg:- Imagine if the
last_checkpoint_duration suddenly jumps from approx (300 ms to 5000
ms), the monitoring system can alert immediately, even if multiple
checkpoints happened in between. But this is hard to find out purely
from cumulative write_time/sync_time without doing complex delta
calculations. And also If the timestamp shows checkpoints happening
much closer together than expected, the tool can alert it as “unusual
high checkpoint frequency” indicating any of the cases like an
aggressive WAL-producing workload errors, checkpoint_completion_target
not being met or I/O layer becoming saturated. This type of detection
becomes easier when the last checkpoint’s end time is visible
directly.
> I mentioned up-thread that one problem would be multiple checkpoints
> having happened between two monitoring runs, where the monitoring system
> sees the duration of the last checkpoint, but maybe more than one
> happened. Should they keep track of the number of overall checkpoints
> and adjust in that case?
>
> To be more general: we don't store the last duration anywhere else (as
> far as I can see, happy to be prove wrong), why is this essential for
> checkpoint duration, and not other things? Or to put it another way: why
> does the patch change it for checkpoint but not all the other places?
>
>
> Michael
You are right that the last duration has not been stored anywhere else
so far and it is a fact that most pg_stat views expose only cumulative
counters. The reason this patch focuses specifically on checkpoints is
that checkpoint timing is one of the few parameters where a single
reading of an event can directly indicate instability and other
irregularities. A single unusual long checkpoint often implies some of
the conditions like backend stalls, WAL flush bottlenecks, extended
buffer recycling, slowdowns in bgwriter or checkpointer I/O
instabilities. So storing the last checkpoint duration is indeed a
small extension, but it offers a direct signal that many monitoring
dashboards currently lack.
I hope this explanation will be helpful to understand more clearly
regarding the patch. Looking forward to more feedback.
Regards,
Soumya
^ permalink raw reply [nested|flat] 31+ messages in thread
* Re: [PATCH] Expose checkpoint timestamp and duration in pg_stat_checkpointer
2025-11-24 06:10 [PATCH] Expose checkpoint timestamp and duration in pg_stat_checkpointer Soumya S Murali <[email protected]>
2025-11-24 09:18 ` Re: [PATCH] Expose checkpoint timestamp and duration in pg_stat_checkpointer Michael Banck <[email protected]>
2025-11-24 10:07 ` Re: [PATCH] Expose checkpoint timestamp and duration in pg_stat_checkpointer Álvaro Herrera <[email protected]>
2025-11-28 04:53 ` Re: [PATCH] Expose checkpoint timestamp and duration in pg_stat_checkpointer Soumya S Murali <[email protected]>
2025-12-01 05:35 ` Re: [PATCH] Expose checkpoint timestamp and duration in pg_stat_checkpointer Soumya S Murali <[email protected]>
2025-12-04 05:13 ` Re: [PATCH] Expose checkpoint timestamp and duration in pg_stat_checkpointer Soumya S Murali <[email protected]>
@ 2026-05-15 06:27 ` Soumya S Murali <[email protected]>
0 siblings, 0 replies; 31+ messages in thread
From: Soumya S Murali @ 2026-05-15 06:27 UTC (permalink / raw)
To: Michael Banck <[email protected]>; +Cc: Álvaro Herrera <[email protected]>; [email protected]; [email protected]; [email protected]
Hi all,
I would like to revive this patch, as the discussion has been inactive
for some time. Based on earlier feedback, I wanted to briefly restate
the motivation of exposing the last checkpoint duration and timestamp
that provides a direct signal of recent checkpoint behavior, which is
currently hard to infer reliably from cumulative statistics especially
when multiple checkpoints occur between monitoring intervals. This is
intended to complement existing cumulative fields, not replacing them
and helps detect sudden spikes in checkpoint duration or unusually
frequent checkpoints more easily.
If there is interest in this direction, I can rebase the patch on
current HEAD and incorporate any suggested changes.
Looking forward to more feedback and thoughts on this.
Regards,
Soumya
^ permalink raw reply [nested|flat] 31+ messages in thread
* Re: [PATCH] Expose checkpoint timestamp and duration in pg_stat_checkpointer
2025-11-24 06:10 [PATCH] Expose checkpoint timestamp and duration in pg_stat_checkpointer Soumya S Murali <[email protected]>
@ 2025-11-26 09:50 ` Soumya S Murali <[email protected]>
1 sibling, 0 replies; 31+ messages in thread
From: Soumya S Murali @ 2025-11-26 09:50 UTC (permalink / raw)
To: Michael Banck <[email protected]>; +Cc: [email protected]; [email protected]
On Mon, Nov 24, 2025 at 2:48 PM Michael Banck <[email protected]> wrote:
>
> Hi,
>
> On Mon, Nov 24, 2025 at 11:40:44AM +0530, Soumya S Murali wrote:
> > While debugging checkpointer write behavior, I recently found some of the
> > enhancements related to extending pg_stat_checkpointer by including
> > checkpoint type (manual/timed/immediate), last_checkpoint_time and
> > checkpoint_total_time information to checkpoint completion logs through SQL
> > when `log_checkpoints` is enabled. I am attaching my observations,
> > screenshots and patch in support for this.
> >
> > 1. Log for type of checkpoint occured:
> >
> > 2025-11-20 11:51:06.128 IST [18026] LOG: checkpoint complete
> > (immediate): wrote 7286 buffers (44.5%), wrote 4 SLRU buffers; 0 WAL
> > file(s) added, 0 removed, 27 recycled; write=0.095 s, sync=0.034 s,
> > total=0.279 s; sync files=17, longest=0.004 s, average=0.002 s;
> > distance=447382 kB, estimate=531349 kB; lsn=0/7F4EDED8, redo
> > lsn=0/7F4EDE80
>
> I think that'd be useful; the checkpoint complete log line clearly has
> the more interesting output, and having it state the type would make it
> easier to answer question like "how many buffers did the last wal-based
> checkpoint write?
Thank you for the feedback and glad to hear that exposing the
checkpoint type in the completion log seems useful. My main motivation
was exactly this kind of analysis: being able to know the buffer write
patterns with the type of checkpoint that triggered them.
> > 2. Log for the checkpoint_total_time and last_checkpoint_time:
> >
> > checkpoint_total_time | last_checkpoint_time
> > -----------------------+----------------------------------
> > 175138 | 2025-11-20 11:58:02.879149+05:30
> > (1 row)
>
> Reading throught the patch, it looks like checkpoint_total_time is the
> total time of the last checkpoint?
>
> > + proparallel => 'r', prorettype => 'float8', proargtypes => '',
> > + prosrc => 'pg_stat_get_checkpointer_checkpoint_total_time' },
>
> If so, the naming is pretty confusing, last_checkpoint_duration or
> something might be clearer.
>
> In general I doubt how much those gauges (as oppposed to counters) only
> pertaining to the last checkpoint are useful in pg_stat_checkpointer.
> What would be the use case for those two values?
>
> Also, as a nitpick, your patch adds unnecessary newlines and I think
> stats_reset should be kept as last column in pg_stat_checkpointer as
> usual.
>
>
> Michael
Yes, the field is intended to represent the duration of the most
recently completed checkpoint, and I agree that renaming it to
last_checkpoint_duration would make the purpose more clear. Even
though it is a single value, it can still help monitoring tools
capture and store each duration over time, so I’ll refine the naming,
remove the unnecessary newlines, and keep stats_reset as the last
column as suggested.
Regards
Soumya
^ permalink raw reply [nested|flat] 31+ messages in thread
* [PATCH v1 1/2] Revert "Teach DSM registry to ERROR if attaching to an uninitialized entry."
@ 2025-11-24 17:03 Nathan Bossart <[email protected]>
0 siblings, 0 replies; 31+ messages in thread
From: Nathan Bossart @ 2025-11-24 17:03 UTC (permalink / raw)
This reverts commit 1165a933aab1355757a43cfd9193b6cce06f573b.
---
src/backend/storage/ipc/dsm_registry.c | 34 +++-----------------------
1 file changed, 4 insertions(+), 30 deletions(-)
diff --git a/src/backend/storage/ipc/dsm_registry.c b/src/backend/storage/ipc/dsm_registry.c
index 7eba8a8cffb..a926b9c3f32 100644
--- a/src/backend/storage/ipc/dsm_registry.c
+++ b/src/backend/storage/ipc/dsm_registry.c
@@ -93,7 +93,6 @@ typedef struct DSMRegistryEntry
{
char name[NAMEDATALEN];
DSMREntryType type;
- bool initialized;
union
{
NamedDSMState dsm;
@@ -217,7 +216,6 @@ GetNamedDSMSegment(const char *name, size_t size,
dsm_segment *seg;
entry->type = DSMR_ENTRY_TYPE_DSM;
- entry->initialized = false;
/* Initialize the segment. */
seg = dsm_create(size, 0);
@@ -230,21 +228,13 @@ GetNamedDSMSegment(const char *name, size_t size,
if (init_callback)
(*init_callback) (ret);
-
- entry->initialized = true;
}
else if (entry->type != DSMR_ENTRY_TYPE_DSM)
ereport(ERROR,
- (errmsg("requested DSM segment \"%s\" does not match type of existing entry",
- name)));
- else if (!entry->initialized)
- ereport(ERROR,
- (errmsg("requested DSM segment \"%s\" failed initialization",
- name)));
+ (errmsg("requested DSM segment does not match type of existing entry")));
else if (entry->dsm.size != size)
ereport(ERROR,
- (errmsg("requested DSM segment \"%s\" does not match size of existing entry",
- name)));
+ (errmsg("requested DSM segment size does not match size of existing segment")));
else
{
NamedDSMState *state = &entry->dsm;
@@ -307,7 +297,6 @@ GetNamedDSA(const char *name, bool *found)
NamedDSAState *state = &entry->dsa;
entry->type = DSMR_ENTRY_TYPE_DSA;
- entry->initialized = false;
/* Initialize the LWLock tranche for the DSA. */
state->tranche = LWLockNewTrancheId(name);
@@ -319,17 +308,10 @@ GetNamedDSA(const char *name, bool *found)
/* Store handle for other backends to use. */
state->handle = dsa_get_handle(ret);
-
- entry->initialized = true;
}
else if (entry->type != DSMR_ENTRY_TYPE_DSA)
ereport(ERROR,
- (errmsg("requested DSA \"%s\" does not match type of existing entry",
- name)));
- else if (!entry->initialized)
- ereport(ERROR,
- (errmsg("requested DSA \"%s\" failed initialization",
- name)));
+ (errmsg("requested DSA does not match type of existing entry")));
else
{
NamedDSAState *state = &entry->dsa;
@@ -390,7 +372,6 @@ GetNamedDSHash(const char *name, const dshash_parameters *params, bool *found)
dsa_area *dsa;
entry->type = DSMR_ENTRY_TYPE_DSH;
- entry->initialized = false;
/* Initialize the LWLock tranche for the hash table. */
dsh_state->tranche = LWLockNewTrancheId(name);
@@ -408,17 +389,10 @@ GetNamedDSHash(const char *name, const dshash_parameters *params, bool *found)
/* Store handles for other backends to use. */
dsh_state->dsa_handle = dsa_get_handle(dsa);
dsh_state->dsh_handle = dshash_get_hash_table_handle(ret);
-
- entry->initialized = true;
}
else if (entry->type != DSMR_ENTRY_TYPE_DSH)
ereport(ERROR,
- (errmsg("requested DSHash \"%s\" does not match type of existing entry",
- name)));
- else if (!entry->initialized)
- ereport(ERROR,
- (errmsg("requested DSHash \"%s\" failed initialization",
- name)));
+ (errmsg("requested DSHash does not match type of existing entry")));
else
{
NamedDSHState *dsh_state = &entry->dsh;
--
2.39.5 (Apple Git-154)
--RrQwG/d5bOC9SOJ1
Content-Type: text/plain; charset=us-ascii
Content-Disposition: attachment;
filename=v1-0002-handle-ERRORs-in-DSM-registry-functions.patch
^ permalink raw reply [nested|flat] 31+ messages in thread
end of thread, other threads:[~2026-05-15 06:27 UTC | newest]
Thread overview: 31+ messages (download: mbox mbox.gz follow: Atom feed)
-- links below jump to the message on this page --
2022-02-14 04:04 [PATCH v2] Correctly update contfol file at the end of archive recovery Kyotaro Horiguchi <[email protected]>
2022-02-14 04:04 [PATCH v2] Correctly update contfol file at the end of archive recovery Kyotaro Horiguchi <[email protected]>
2022-02-14 04:04 [PATCH v2] Correctly update contfol file at the end of archive recovery Kyotaro Horiguchi <[email protected]>
2022-02-25 05:46 [PATCH v2] Correctly update contfol file at the end of archive recovery Kyotaro Horiguchi <[email protected]>
2022-02-25 05:46 [PATCH v2] Correctly update contfol file at the end of archive recovery Kyotaro Horiguchi <[email protected]>
2022-02-25 06:04 [PATCH v3] Correctly update contfol file at the end of archive recovery Kyotaro Horiguchi <[email protected]>
2022-02-25 06:04 [PATCH v3] Correctly update contfol file at the end of archive recovery Kyotaro Horiguchi <[email protected]>
2022-02-25 07:35 [PATCH v3] Correctly update contfol file at the end of archive recovery Kyotaro Horiguchi <[email protected]>
2022-02-25 07:35 [PATCH v3] Correctly update contfol file at the end of archive recovery Kyotaro Horiguchi <[email protected]>
2022-03-04 04:18 [PATCH v4] Correctly update contfol file at the end of archive recovery Kyotaro Horiguchi <[email protected]>
2022-03-04 04:18 [PATCH v12 1/5] Correctly update contfol file at the end of archive recovery Kyotaro Horiguchi <[email protected]>
2022-03-04 04:18 [PATCH v11 1/5] Correctly update contfol file at the end of archive recovery Kyotaro Horiguchi <[email protected]>
2022-04-27 01:41 [PATCH v5] Correctly update contfol file at the end of archive recovery Kyotaro Horiguchi <[email protected]>
2025-11-20 07:30 [PATCH] Expose checkpoint timestamp and duration in pg_stat_checkpointer BharatDB <[email protected]>
2025-11-20 12:41 ` Re: [PATCH] Expose checkpoint timestamp and duration in pg_stat_checkpointer Álvaro Herrera <[email protected]>
2025-11-24 06:10 [PATCH] Expose checkpoint timestamp and duration in pg_stat_checkpointer Soumya S Murali <[email protected]>
2025-11-24 09:18 ` Re: [PATCH] Expose checkpoint timestamp and duration in pg_stat_checkpointer Michael Banck <[email protected]>
2025-11-24 10:07 ` Re: [PATCH] Expose checkpoint timestamp and duration in pg_stat_checkpointer Álvaro Herrera <[email protected]>
2025-11-24 11:05 ` Re: [PATCH] Expose checkpoint timestamp and duration in pg_stat_checkpointer Michael Banck <[email protected]>
2025-11-26 10:15 ` Re: [PATCH] Expose checkpoint timestamp and duration in pg_stat_checkpointer Soumya S Murali <[email protected]>
2025-11-26 17:23 ` Re: [PATCH] Expose checkpoint timestamp and duration in pg_stat_checkpointer Juan José Santamaría Flecha <[email protected]>
2025-11-26 17:41 ` Re: [PATCH] Expose checkpoint timestamp and duration in pg_stat_checkpointer Michael Banck <[email protected]>
2025-11-27 11:39 ` Re: [PATCH] Expose checkpoint timestamp and duration in pg_stat_checkpointer Soumya S Murali <[email protected]>
2025-11-28 04:53 ` Re: [PATCH] Expose checkpoint timestamp and duration in pg_stat_checkpointer Soumya S Murali <[email protected]>
2025-11-28 08:08 ` Re: [PATCH] Expose checkpoint timestamp and duration in pg_stat_checkpointer Michael Banck <[email protected]>
2025-12-01 05:35 ` Re: [PATCH] Expose checkpoint timestamp and duration in pg_stat_checkpointer Soumya S Murali <[email protected]>
2025-12-01 08:15 ` Re: [PATCH] Expose checkpoint timestamp and duration in pg_stat_checkpointer Michael Banck <[email protected]>
2025-12-04 05:13 ` Re: [PATCH] Expose checkpoint timestamp and duration in pg_stat_checkpointer Soumya S Murali <[email protected]>
2026-05-15 06:27 ` Re: [PATCH] Expose checkpoint timestamp and duration in pg_stat_checkpointer Soumya S Murali <[email protected]>
2025-11-26 09:50 ` Re: [PATCH] Expose checkpoint timestamp and duration in pg_stat_checkpointer Soumya S Murali <[email protected]>
2025-11-24 17:03 [PATCH v1 1/2] Revert "Teach DSM registry to ERROR if attaching to an uninitialized entry." Nathan Bossart <[email protected]>
This inbox is served by agora; see mirroring instructions
for how to clone and mirror all data and code used for this inbox