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
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
