add checkpoint stats of snapshot and mapping files of pg_logical dir

From 3ae6f0082dd6ae5ba9c8b53e242d111811f12516 Mon Sep 17 00:00:00 2001
From: Bharath Rupireddy <bharath.rupireddyforpostgres@gmail.com>
Date: Sun, 13 Mar 2022 08:19:07 +0000
Subject: [PATCH v2] add checkpoint stats of snapshot and mapping files of
 pg_logical dir

At times, there can be many snapshot and mapping files under
pg_logical dir that the checkpoint might have to delete/fsync
based on the cutoff LSN which can increase the checkpoint time.
Add stats related to these files to better understand the delays
or time spent by the checkpointer processing them.

Also, emitting snapshot and mapping files stats in case of
restartpoint doesn't make sense for now as logical decoding isn't
supported on standbys.
---
 src/backend/access/heap/rewriteheap.c       |  8 ++++
 src/backend/access/transam/xlog.c           | 41 +++++++++++++++++++--
 src/backend/replication/logical/snapbuild.c |  5 +++
 src/include/access/xlog.h                   | 16 ++++++++
 4 files changed, 67 insertions(+), 3 deletions(-)

diff --git a/src/backend/access/heap/rewriteheap.c b/src/backend/access/heap/rewriteheap.c
index 2a53826736..9f3c2f510b 100644
--- a/src/backend/access/heap/rewriteheap.c
+++ b/src/backend/access/heap/rewriteheap.c
@@ -1210,6 +1210,8 @@ CheckPointLogicalRewriteHeap(void)
 	if (cutoff != InvalidXLogRecPtr && redo < cutoff)
 		cutoff = redo;
 
+	CheckpointStats.repl_map_cutoff_lsn = cutoff;
+
 	mappings_dir = AllocateDir("pg_logical/mappings");
 	while ((mapping_de = ReadDir(mappings_dir, "pg_logical/mappings")) != NULL)
 	{
@@ -1247,6 +1249,9 @@ CheckPointLogicalRewriteHeap(void)
 				ereport(ERROR,
 						(errcode_for_file_access(),
 						 errmsg("could not remove file \"%s\": %m", path)));
+
+			CheckpointStats.repl_map_files_rmvd_cnt++;
+			CheckpointStats.repl_map_files_rmvd_sz += statbuf.st_size;
 		}
 		else
 		{
@@ -1280,6 +1285,9 @@ CheckPointLogicalRewriteHeap(void)
 						(errcode_for_file_access(),
 						 errmsg("could not close file \"%s\": %m", path)));
 		}
+
+		CheckpointStats.repl_map_files_syncd_cnt++;
+		CheckpointStats.repl_map_files_syncd_sz += statbuf.st_size;
 	}
 	FreeDir(mappings_dir);
 
diff --git a/src/backend/access/transam/xlog.c b/src/backend/access/transam/xlog.c
index 0d2bd7a357..70e1971b21 100644
--- a/src/backend/access/transam/xlog.c
+++ b/src/backend/access/transam/xlog.c
@@ -6077,7 +6077,9 @@ LogCheckpointEnd(bool restartpoint)
 				sync_msecs,
 				total_msecs,
 				longest_msecs,
-				average_msecs;
+				average_msecs,
+				repl_snap_msecs,
+				repl_map_msecs;
 	uint64		average_sync_time;
 
 	CheckpointStats.ckpt_end_t = GetCurrentTimestamp();
@@ -6114,6 +6116,20 @@ LogCheckpointEnd(bool restartpoint)
 			CheckpointStats.ckpt_sync_rels;
 	average_msecs = (long) ((average_sync_time + 999) / 1000);
 
+	/*
+	 * XXX let's not emit snapshot and mapping files stats in case of
+	 * restartpoint as logical decoding isn't supported on standbys yet,
+	 * however it needs to be revisited when it is supported.
+	 */
+	if (!restartpoint)
+	{
+		repl_snap_msecs = TimestampDifferenceMilliseconds(CheckpointStats.repl_snap_start_t,
+														  CheckpointStats.repl_snap_end_t);
+
+		repl_map_msecs = TimestampDifferenceMilliseconds(CheckpointStats.repl_map_start_t,
+														 CheckpointStats.repl_map_end_t);
+	}
+
 	if (restartpoint)
 		ereport(LOG,
 				(errmsg("restartpoint complete: wrote %d buffers (%.1f%%); "
@@ -6140,7 +6156,9 @@ LogCheckpointEnd(bool restartpoint)
 						"%d WAL file(s) added, %d removed, %d recycled; "
 						"write=%ld.%03d s, sync=%ld.%03d s, total=%ld.%03d s; "
 						"sync files=%d, longest=%ld.%03d s, average=%ld.%03d s; "
-						"distance=%d kB, estimate=%d kB",
+						"distance=%d kB, estimate=%d kB; "
+						"snapbuild snapshot file(s) removed=" UINT64_FORMAT ", size=%zu bytes, time=%ld.%03d s, cutoff LSN=%X/%X; "
+						"logical rewrite mapping file(s) removed=" UINT64_FORMAT ", size=%zu bytes, synced=" UINT64_FORMAT ", size=%zu bytes, time=%ld.%03d s, cutoff LSN=%X/%X",
 						CheckpointStats.ckpt_bufs_written,
 						(double) CheckpointStats.ckpt_bufs_written * 100 / NBuffers,
 						CheckpointStats.ckpt_segs_added,
@@ -6153,7 +6171,17 @@ LogCheckpointEnd(bool restartpoint)
 						longest_msecs / 1000, (int) (longest_msecs % 1000),
 						average_msecs / 1000, (int) (average_msecs % 1000),
 						(int) (PrevCheckPointDistance / 1024.0),
-						(int) (CheckPointDistanceEstimate / 1024.0))));
+						(int) (CheckPointDistanceEstimate / 1024.0),
+						CheckpointStats.repl_snap_files_rmvd_cnt,
+						CheckpointStats.repl_snap_files_rmvd_sz,
+						repl_snap_msecs / 1000, (int) (repl_snap_msecs % 1000),
+						LSN_FORMAT_ARGS(CheckpointStats.repl_snap_cutoff_lsn),
+						CheckpointStats.repl_map_files_rmvd_cnt,
+						CheckpointStats.repl_map_files_rmvd_sz,
+						CheckpointStats.repl_map_files_syncd_cnt,
+						CheckpointStats.repl_map_files_syncd_sz,
+						repl_map_msecs / 1000, (int) (repl_map_msecs % 1000),
+						LSN_FORMAT_ARGS(CheckpointStats.repl_map_cutoff_lsn))));
 }
 
 /*
@@ -6809,8 +6837,15 @@ CheckPointGuts(XLogRecPtr checkPointRedo, int flags)
 {
 	CheckPointRelationMap();
 	CheckPointReplicationSlots();
+
+	CheckpointStats.repl_snap_start_t = GetCurrentTimestamp();
 	CheckPointSnapBuild();
+	CheckpointStats.repl_snap_end_t = GetCurrentTimestamp();
+
+	CheckpointStats.repl_map_start_t = GetCurrentTimestamp();
 	CheckPointLogicalRewriteHeap();
+	CheckpointStats.repl_map_end_t = GetCurrentTimestamp();
+
 	CheckPointReplicationOrigin();
 
 	/* Write out all dirty data in SLRUs and the main buffer pool */
diff --git a/src/backend/replication/logical/snapbuild.c b/src/backend/replication/logical/snapbuild.c
index 83fca8a77d..5e7d8d9dea 100644
--- a/src/backend/replication/logical/snapbuild.c
+++ b/src/backend/replication/logical/snapbuild.c
@@ -1941,6 +1941,8 @@ CheckPointSnapBuild(void)
 	if (redo < cutoff)
 		cutoff = redo;
 
+	CheckpointStats.repl_snap_cutoff_lsn = cutoff;
+
 	snap_dir = AllocateDir("pg_logical/snapshots");
 	while ((snap_de = ReadDir(snap_dir, "pg_logical/snapshots")) != NULL)
 	{
@@ -1997,6 +1999,9 @@ CheckPointSnapBuild(void)
 								path)));
 				continue;
 			}
+
+			CheckpointStats.repl_snap_files_rmvd_cnt++;
+			CheckpointStats.repl_snap_files_rmvd_sz += statbuf.st_size;
 		}
 	}
 	FreeDir(snap_dir);
diff --git a/src/include/access/xlog.h b/src/include/access/xlog.h
index 09f6464331..40cda7f4bb 100644
--- a/src/include/access/xlog.h
+++ b/src/include/access/xlog.h
@@ -172,6 +172,22 @@ typedef struct CheckpointStatsData
 									 * times, which is not necessarily the
 									 * same as the total elapsed time for the
 									 * entire sync phase. */
+
+	/* Statistics of snapshot files under "pg_logical/snapshots" */
+	Size repl_snap_files_rmvd_sz;
+	uint64 repl_snap_files_rmvd_cnt;
+	XLogRecPtr repl_snap_cutoff_lsn;
+	TimestampTz	repl_snap_start_t;
+	TimestampTz	repl_snap_end_t;
+
+	/* Statistics of map files under "pg_logical/mappings" */
+	Size repl_map_files_syncd_sz;
+	uint64 repl_map_files_syncd_cnt;
+	Size repl_map_files_rmvd_sz;
+	uint64 repl_map_files_rmvd_cnt;
+	XLogRecPtr repl_map_cutoff_lsn;
+	TimestampTz	repl_map_start_t;
+	TimestampTz	repl_map_end_t;
 } CheckpointStatsData;
 
 extern CheckpointStatsData CheckpointStats;
-- 
2.25.1

From 08b47249abfeddf7f06191d4bcd223f0c5597016 Mon Sep 17 00:00:00 2001
From: Bharath Rupireddy <bharath.rupireddyforpostgres@gmail.com>
Date: Mon, 14 Mar 2022 11:22:15 +0000
Subject: [PATCH v3] Add checkpoint stats of snapshot and mapping files of
 pg_logical dir

At times, there can be many snapshot and mapping files under
pg_logical dir that the checkpoint might have to delete/fsync
based on the cutoff LSN which can increase the checkpoint time.
Add stats related to these files to better understand the delays
or time spent by the checkpointer processing them.

Add these new log message only when necessary i.e. at least one
snapshot or mapping files is processed during the checkpoint, that
to as a separate log messages to not clutter existing "checkpoint/
restartpoint complete" log message.
---
 src/backend/access/heap/rewriteheap.c       |  8 ++++
 src/backend/access/transam/xlog.c           | 44 +++++++++++++++++++++
 src/backend/replication/logical/snapbuild.c |  5 +++
 src/include/access/xlog.h                   | 16 ++++++++
 4 files changed, 73 insertions(+)

diff --git a/src/backend/access/heap/rewriteheap.c b/src/backend/access/heap/rewriteheap.c
index 2a53826736..9f3c2f510b 100644
--- a/src/backend/access/heap/rewriteheap.c
+++ b/src/backend/access/heap/rewriteheap.c
@@ -1210,6 +1210,8 @@ CheckPointLogicalRewriteHeap(void)
 	if (cutoff != InvalidXLogRecPtr && redo < cutoff)
 		cutoff = redo;
 
+	CheckpointStats.repl_map_cutoff_lsn = cutoff;
+
 	mappings_dir = AllocateDir("pg_logical/mappings");
 	while ((mapping_de = ReadDir(mappings_dir, "pg_logical/mappings")) != NULL)
 	{
@@ -1247,6 +1249,9 @@ CheckPointLogicalRewriteHeap(void)
 				ereport(ERROR,
 						(errcode_for_file_access(),
 						 errmsg("could not remove file \"%s\": %m", path)));
+
+			CheckpointStats.repl_map_files_rmvd_cnt++;
+			CheckpointStats.repl_map_files_rmvd_sz += statbuf.st_size;
 		}
 		else
 		{
@@ -1280,6 +1285,9 @@ CheckPointLogicalRewriteHeap(void)
 						(errcode_for_file_access(),
 						 errmsg("could not close file \"%s\": %m", path)));
 		}
+
+		CheckpointStats.repl_map_files_syncd_cnt++;
+		CheckpointStats.repl_map_files_syncd_sz += statbuf.st_size;
 	}
 	FreeDir(mappings_dir);
 
diff --git a/src/backend/access/transam/xlog.c b/src/backend/access/transam/xlog.c
index 0d2bd7a357..fe92c3f53c 100644
--- a/src/backend/access/transam/xlog.c
+++ b/src/backend/access/transam/xlog.c
@@ -6154,6 +6154,43 @@ LogCheckpointEnd(bool restartpoint)
 						average_msecs / 1000, (int) (average_msecs % 1000),
 						(int) (PrevCheckPointDistance / 1024.0),
 						(int) (CheckPointDistanceEstimate / 1024.0))));
+
+	/*
+	 * Let's emit snapshot and mapping files stats only when necessary, that to
+	 * as separate log messages, to not clutter server logs.
+	 */
+	if (CheckpointStats.repl_snap_files_rmvd_cnt > 0)
+	{
+		long t_msecs;
+
+		t_msecs = TimestampDifferenceMilliseconds(CheckpointStats.repl_snap_start_t,
+												  CheckpointStats.repl_snap_end_t);
+
+		ereport(LOG,
+				(errmsg("snapbuild snapshot file(s) removed=" UINT64_FORMAT ", size=%zu bytes, time=%ld.%03d s, cutoff LSN=%X/%X",
+						CheckpointStats.repl_snap_files_rmvd_cnt,
+						CheckpointStats.repl_snap_files_rmvd_sz,
+						t_msecs / 1000, (int) (t_msecs % 1000),
+						LSN_FORMAT_ARGS(CheckpointStats.repl_snap_cutoff_lsn))));
+	}
+
+	if (CheckpointStats.repl_map_files_rmvd_cnt > 0 ||
+		CheckpointStats.repl_map_files_syncd_cnt > 0)
+	{
+		long t_msecs;
+
+		t_msecs = TimestampDifferenceMilliseconds(CheckpointStats.repl_map_start_t,
+												  CheckpointStats.repl_map_end_t);
+
+		ereport(LOG,
+				(errmsg("logical rewrite mapping file(s) removed=" UINT64_FORMAT ", size=%zu bytes, synced=" UINT64_FORMAT ", size=%zu bytes, time=%ld.%03d s, cutoff LSN=%X/%X",
+						CheckpointStats.repl_map_files_rmvd_cnt,
+						CheckpointStats.repl_map_files_rmvd_sz,
+						CheckpointStats.repl_map_files_syncd_cnt,
+						CheckpointStats.repl_map_files_syncd_sz,
+						t_msecs / 1000, (int) (t_msecs % 1000),
+						LSN_FORMAT_ARGS(CheckpointStats.repl_map_cutoff_lsn))));
+	}
 }
 
 /*
@@ -6809,8 +6846,15 @@ CheckPointGuts(XLogRecPtr checkPointRedo, int flags)
 {
 	CheckPointRelationMap();
 	CheckPointReplicationSlots();
+
+	CheckpointStats.repl_snap_start_t = GetCurrentTimestamp();
 	CheckPointSnapBuild();
+	CheckpointStats.repl_snap_end_t = GetCurrentTimestamp();
+
+	CheckpointStats.repl_map_start_t = GetCurrentTimestamp();
 	CheckPointLogicalRewriteHeap();
+	CheckpointStats.repl_map_end_t = GetCurrentTimestamp();
+
 	CheckPointReplicationOrigin();
 
 	/* Write out all dirty data in SLRUs and the main buffer pool */
diff --git a/src/backend/replication/logical/snapbuild.c b/src/backend/replication/logical/snapbuild.c
index 83fca8a77d..5e7d8d9dea 100644
--- a/src/backend/replication/logical/snapbuild.c
+++ b/src/backend/replication/logical/snapbuild.c
@@ -1941,6 +1941,8 @@ CheckPointSnapBuild(void)
 	if (redo < cutoff)
 		cutoff = redo;
 
+	CheckpointStats.repl_snap_cutoff_lsn = cutoff;
+
 	snap_dir = AllocateDir("pg_logical/snapshots");
 	while ((snap_de = ReadDir(snap_dir, "pg_logical/snapshots")) != NULL)
 	{
@@ -1997,6 +1999,9 @@ CheckPointSnapBuild(void)
 								path)));
 				continue;
 			}
+
+			CheckpointStats.repl_snap_files_rmvd_cnt++;
+			CheckpointStats.repl_snap_files_rmvd_sz += statbuf.st_size;
 		}
 	}
 	FreeDir(snap_dir);
diff --git a/src/include/access/xlog.h b/src/include/access/xlog.h
index 09f6464331..40cda7f4bb 100644
--- a/src/include/access/xlog.h
+++ b/src/include/access/xlog.h
@@ -172,6 +172,22 @@ typedef struct CheckpointStatsData
 									 * times, which is not necessarily the
 									 * same as the total elapsed time for the
 									 * entire sync phase. */
+
+	/* Statistics of snapshot files under "pg_logical/snapshots" */
+	Size repl_snap_files_rmvd_sz;
+	uint64 repl_snap_files_rmvd_cnt;
+	XLogRecPtr repl_snap_cutoff_lsn;
+	TimestampTz	repl_snap_start_t;
+	TimestampTz	repl_snap_end_t;
+
+	/* Statistics of map files under "pg_logical/mappings" */
+	Size repl_map_files_syncd_sz;
+	uint64 repl_map_files_syncd_cnt;
+	Size repl_map_files_rmvd_sz;
+	uint64 repl_map_files_rmvd_cnt;
+	XLogRecPtr repl_map_cutoff_lsn;
+	TimestampTz	repl_map_start_t;
+	TimestampTz	repl_map_end_t;
 } CheckpointStatsData;
 
 extern CheckpointStatsData CheckpointStats;
-- 
2.25.1

From caa4ab307a2daaf6cc495aaea78d34dbd66faa2f Mon Sep 17 00:00:00 2001
From: Bharath Rupireddy <bharath.rupireddyforpostgres@gmail.com>
Date: Thu, 17 Mar 2022 13:06:30 +0000
Subject: [PATCH v444] Add checkpoint stats of snapshot and mapping files of
 pg_logical dir

At times, there can be many snapshot and mapping files under
pg_logical dir that the checkpoint might have to delete/fsync
based on the cutoff LSN which can increase the checkpoint time.
Add stats related to these files to better understand the delays
or time spent by the checkpointer processing them.

Add these new log message only when necessary i.e. at least one
snapshot or mapping files is processed during the checkpoint.
---
 src/backend/access/heap/rewriteheap.c       | 30 +++++++++++++++++++++
 src/backend/replication/logical/snapbuild.c | 25 +++++++++++++++++
 2 files changed, 55 insertions(+)

diff --git a/src/backend/access/heap/rewriteheap.c b/src/backend/access/heap/rewriteheap.c
index 2a53826736..471ad4c5e8 100644
--- a/src/backend/access/heap/rewriteheap.c
+++ b/src/backend/access/heap/rewriteheap.c
@@ -1196,6 +1196,13 @@ CheckPointLogicalRewriteHeap(void)
 	DIR		   *mappings_dir;
 	struct dirent *mapping_de;
 	char		path[MAXPGPATH + 20];
+	uint64	files_rmvd_cnt = 0;
+	uint64	files_syncd_cnt = 0;
+	TimestampTz	start_t;
+	TimestampTz	end_t;
+
+	if (log_checkpoints)
+		start_t = GetCurrentTimestamp();
 
 	/*
 	 * We start of with a minimum of the last redo pointer. No new decoding
@@ -1247,6 +1254,9 @@ CheckPointLogicalRewriteHeap(void)
 				ereport(ERROR,
 						(errcode_for_file_access(),
 						 errmsg("could not remove file \"%s\": %m", path)));
+
+			if (log_checkpoints)
+				files_rmvd_cnt++;
 		}
 		else
 		{
@@ -1280,9 +1290,29 @@ CheckPointLogicalRewriteHeap(void)
 						(errcode_for_file_access(),
 						 errmsg("could not close file \"%s\": %m", path)));
 		}
+
+		if (log_checkpoints)
+			files_syncd_cnt++;
 	}
 	FreeDir(mappings_dir);
 
 	/* persist directory entries to disk */
 	fsync_fname("pg_logical/mappings", true);
+
+	/* let's emit these stats only when necessary */
+	if (log_checkpoints &&
+		(files_rmvd_cnt > 0 || files_syncd_cnt > 0))
+	{
+		long t_msecs;
+
+		end_t = GetCurrentTimestamp();
+		t_msecs = TimestampDifferenceMilliseconds(start_t, end_t);
+
+		ereport(LOG,
+				(errmsg("logical decoding rewrite mapping file(s) removed=" UINT64_FORMAT ", synced=" UINT64_FORMAT ", time=%ld.%03d s, cutoff LSN=%X/%X",
+						files_rmvd_cnt,
+						files_syncd_cnt,
+						t_msecs / 1000, (int) (t_msecs % 1000),
+						LSN_FORMAT_ARGS(cutoff))));
+	}
 }
diff --git a/src/backend/replication/logical/snapbuild.c b/src/backend/replication/logical/snapbuild.c
index 83fca8a77d..e6556ca1b6 100644
--- a/src/backend/replication/logical/snapbuild.c
+++ b/src/backend/replication/logical/snapbuild.c
@@ -1926,6 +1926,12 @@ CheckPointSnapBuild(void)
 	DIR		   *snap_dir;
 	struct dirent *snap_de;
 	char		path[MAXPGPATH + 21];
+	uint64	files_rmvd_cnt = 0;
+	TimestampTz	start_t;
+	TimestampTz	end_t;
+
+	if (log_checkpoints)
+		start_t = GetCurrentTimestamp();
 
 	/*
 	 * We start off with a minimum of the last redo pointer. No new
@@ -1997,7 +2003,26 @@ CheckPointSnapBuild(void)
 								path)));
 				continue;
 			}
+
+			if (log_checkpoints)
+				files_rmvd_cnt++;
 		}
 	}
 	FreeDir(snap_dir);
+
+	/* let's emit these stats only when necessary */
+	if (log_checkpoints &&
+		files_rmvd_cnt > 0)
+	{
+		long t_msecs;
+
+		end_t = GetCurrentTimestamp();
+		t_msecs = TimestampDifferenceMilliseconds(start_t, end_t);
+
+		ereport(LOG,
+				(errmsg("logical decoding snapshot file(s) removed=" UINT64_FORMAT ", time=%ld.%03d s, cutoff LSN=%X/%X",
+						files_rmvd_cnt,
+						t_msecs / 1000, (int) (t_msecs % 1000),
+						LSN_FORMAT_ARGS(cutoff))));
+	}
 }
-- 
2.25.1

From 3bbc4f09c0b8249ce76ea19b3a422e1f765978a1 Mon Sep 17 00:00:00 2001
From: Bharath Rupireddy <bharath.rupireddyforpostgres@gmail.com>
Date: Thu, 17 Mar 2022 12:53:00 +0000
Subject: [PATCH v44] Add checkpoint stats of snapshot and mapping files of
 pg_logical dir

At times, there can be many snapshot and mapping files under
pg_logical dir that the checkpoint might have to delete/fsync
based on the cutoff LSN which can increase the checkpoint time.
Add stats related to these files to better understand the delays
or time spent by the checkpointer processing them.

Add these new log message only when necessary i.e. at least one
snapshot or mapping files is processed during the checkpoint.
---
 src/backend/access/heap/rewriteheap.c       |  6 +++
 src/backend/access/transam/xlog.c           | 42 +++++++++++++++++++++
 src/backend/replication/logical/snapbuild.c |  4 ++
 src/include/access/xlog.h                   | 13 +++++++
 4 files changed, 65 insertions(+)

diff --git a/src/backend/access/heap/rewriteheap.c b/src/backend/access/heap/rewriteheap.c
index 2a53826736..59cc3fa567 100644
--- a/src/backend/access/heap/rewriteheap.c
+++ b/src/backend/access/heap/rewriteheap.c
@@ -1210,6 +1210,8 @@ CheckPointLogicalRewriteHeap(void)
 	if (cutoff != InvalidXLogRecPtr && redo < cutoff)
 		cutoff = redo;
 
+	CheckpointStats.repl_map_cutoff_lsn = cutoff;
+
 	mappings_dir = AllocateDir("pg_logical/mappings");
 	while ((mapping_de = ReadDir(mappings_dir, "pg_logical/mappings")) != NULL)
 	{
@@ -1247,6 +1249,8 @@ CheckPointLogicalRewriteHeap(void)
 				ereport(ERROR,
 						(errcode_for_file_access(),
 						 errmsg("could not remove file \"%s\": %m", path)));
+
+			CheckpointStats.repl_map_files_rmvd_cnt++;
 		}
 		else
 		{
@@ -1280,6 +1284,8 @@ CheckPointLogicalRewriteHeap(void)
 						(errcode_for_file_access(),
 						 errmsg("could not close file \"%s\": %m", path)));
 		}
+
+		CheckpointStats.repl_map_files_syncd_cnt++;
 	}
 	FreeDir(mappings_dir);
 
diff --git a/src/backend/access/transam/xlog.c b/src/backend/access/transam/xlog.c
index f436471b27..1dd31d4cc5 100644
--- a/src/backend/access/transam/xlog.c
+++ b/src/backend/access/transam/xlog.c
@@ -6115,6 +6115,41 @@ LogCheckpointEnd(bool restartpoint)
 			CheckpointStats.ckpt_sync_rels;
 	average_msecs = (long) ((average_sync_time + 999) / 1000);
 
+	/*
+	 * Let's emit snapshot and mapping files stats only when necessary, that to
+	 * as separate log messages, to not clutter the "checkpoint/restartpoint
+	 * complete" message.
+	 */
+	if (CheckpointStats.repl_snap_files_rmvd_cnt > 0)
+	{
+		long t_msecs;
+
+		t_msecs = TimestampDifferenceMilliseconds(CheckpointStats.repl_snap_start_t,
+												  CheckpointStats.repl_snap_end_t);
+
+		ereport(LOG,
+				(errmsg("logical decoding snapshot file(s) removed=" UINT64_FORMAT ", time=%ld.%03d s, cutoff LSN=%X/%X",
+						CheckpointStats.repl_snap_files_rmvd_cnt,
+						t_msecs / 1000, (int) (t_msecs % 1000),
+						LSN_FORMAT_ARGS(CheckpointStats.repl_snap_cutoff_lsn))));
+	}
+
+	if (CheckpointStats.repl_map_files_rmvd_cnt > 0 ||
+		CheckpointStats.repl_map_files_syncd_cnt > 0)
+	{
+		long t_msecs;
+
+		t_msecs = TimestampDifferenceMilliseconds(CheckpointStats.repl_map_start_t,
+												  CheckpointStats.repl_map_end_t);
+
+		ereport(LOG,
+				(errmsg("logical decoding rewrite mapping file(s) removed=" UINT64_FORMAT ", synced=" UINT64_FORMAT ", time=%ld.%03d s, cutoff LSN=%X/%X",
+						CheckpointStats.repl_map_files_rmvd_cnt,
+						CheckpointStats.repl_map_files_syncd_cnt,
+						t_msecs / 1000, (int) (t_msecs % 1000),
+						LSN_FORMAT_ARGS(CheckpointStats.repl_map_cutoff_lsn))));
+	}
+
 	if (restartpoint)
 		ereport(LOG,
 				(errmsg("restartpoint complete: wrote %d buffers (%.1f%%); "
@@ -6811,8 +6846,15 @@ CheckPointGuts(XLogRecPtr checkPointRedo, int flags)
 {
 	CheckPointRelationMap();
 	CheckPointReplicationSlots();
+
+	CheckpointStats.repl_snap_start_t = GetCurrentTimestamp();
 	CheckPointSnapBuild();
+	CheckpointStats.repl_snap_end_t = GetCurrentTimestamp();
+
+	CheckpointStats.repl_map_start_t = GetCurrentTimestamp();
 	CheckPointLogicalRewriteHeap();
+	CheckpointStats.repl_map_end_t = GetCurrentTimestamp();
+
 	CheckPointReplicationOrigin();
 
 	/* Write out all dirty data in SLRUs and the main buffer pool */
diff --git a/src/backend/replication/logical/snapbuild.c b/src/backend/replication/logical/snapbuild.c
index 83fca8a77d..e652acfbe6 100644
--- a/src/backend/replication/logical/snapbuild.c
+++ b/src/backend/replication/logical/snapbuild.c
@@ -1941,6 +1941,8 @@ CheckPointSnapBuild(void)
 	if (redo < cutoff)
 		cutoff = redo;
 
+	CheckpointStats.repl_snap_cutoff_lsn = cutoff;
+
 	snap_dir = AllocateDir("pg_logical/snapshots");
 	while ((snap_de = ReadDir(snap_dir, "pg_logical/snapshots")) != NULL)
 	{
@@ -1997,6 +1999,8 @@ CheckPointSnapBuild(void)
 								path)));
 				continue;
 			}
+
+			CheckpointStats.repl_snap_files_rmvd_cnt++;
 		}
 	}
 	FreeDir(snap_dir);
diff --git a/src/include/access/xlog.h b/src/include/access/xlog.h
index 09f6464331..32f8116388 100644
--- a/src/include/access/xlog.h
+++ b/src/include/access/xlog.h
@@ -172,6 +172,19 @@ typedef struct CheckpointStatsData
 									 * times, which is not necessarily the
 									 * same as the total elapsed time for the
 									 * entire sync phase. */
+
+	/* Statistics of snapshot files under "pg_logical/snapshots" */
+	uint64 repl_snap_files_rmvd_cnt;
+	XLogRecPtr repl_snap_cutoff_lsn;
+	TimestampTz	repl_snap_start_t;
+	TimestampTz	repl_snap_end_t;
+
+	/* Statistics of map files under "pg_logical/mappings" */
+	uint64 repl_map_files_syncd_cnt;
+	uint64 repl_map_files_rmvd_cnt;
+	XLogRecPtr repl_map_cutoff_lsn;
+	TimestampTz	repl_map_start_t;
+	TimestampTz	repl_map_end_t;
 } CheckpointStatsData;
 
 extern CheckpointStatsData CheckpointStats;
-- 
2.25.1

From f4170e961cb9dbb2fe135f71645d163a3d2a9ef1 Mon Sep 17 00:00:00 2001
From: Bharath Rupireddy <bharath.rupireddyforpostgres@gmail.com>
Date: Thu, 17 Mar 2022 12:47:27 +0000
Subject: [PATCH v4] Add checkpoint stats of snapshot and mapping files of
 pg_logical dir

At times, there can be many snapshot and mapping files under
pg_logical dir that the checkpoint might have to delete/fsync
based on the cutoff LSN which can increase the checkpoint time.
Add stats related to these files to better understand the delays
or time spent by the checkpointer processing them.

Add these new log message only when necessary i.e. at least one
snapshot or mapping files is processed during the checkpoint
---
 src/backend/access/heap/rewriteheap.c       |   6 +
 src/backend/access/transam/xlog.c           | 305 +++++++++++++++++---
 src/backend/replication/logical/snapbuild.c |   4 +
 src/include/access/xlog.h                   |  13 +
 4 files changed, 290 insertions(+), 38 deletions(-)

diff --git a/src/backend/access/heap/rewriteheap.c b/src/backend/access/heap/rewriteheap.c
index 2a53826736..59cc3fa567 100644
--- a/src/backend/access/heap/rewriteheap.c
+++ b/src/backend/access/heap/rewriteheap.c
@@ -1210,6 +1210,8 @@ CheckPointLogicalRewriteHeap(void)
 	if (cutoff != InvalidXLogRecPtr && redo < cutoff)
 		cutoff = redo;
 
+	CheckpointStats.repl_map_cutoff_lsn = cutoff;
+
 	mappings_dir = AllocateDir("pg_logical/mappings");
 	while ((mapping_de = ReadDir(mappings_dir, "pg_logical/mappings")) != NULL)
 	{
@@ -1247,6 +1249,8 @@ CheckPointLogicalRewriteHeap(void)
 				ereport(ERROR,
 						(errcode_for_file_access(),
 						 errmsg("could not remove file \"%s\": %m", path)));
+
+			CheckpointStats.repl_map_files_rmvd_cnt++;
 		}
 		else
 		{
@@ -1280,6 +1284,8 @@ CheckPointLogicalRewriteHeap(void)
 						(errcode_for_file_access(),
 						 errmsg("could not close file \"%s\": %m", path)));
 		}
+
+		CheckpointStats.repl_map_files_syncd_cnt++;
 	}
 	FreeDir(mappings_dir);
 
diff --git a/src/backend/access/transam/xlog.c b/src/backend/access/transam/xlog.c
index f436471b27..55866120db 100644
--- a/src/backend/access/transam/xlog.c
+++ b/src/backend/access/transam/xlog.c
@@ -6116,45 +6116,267 @@ LogCheckpointEnd(bool restartpoint)
 	average_msecs = (long) ((average_sync_time + 999) / 1000);
 
 	if (restartpoint)
-		ereport(LOG,
-				(errmsg("restartpoint complete: wrote %d buffers (%.1f%%); "
-						"%d WAL file(s) added, %d removed, %d recycled; "
-						"write=%ld.%03d s, sync=%ld.%03d s, total=%ld.%03d s; "
-						"sync files=%d, longest=%ld.%03d s, average=%ld.%03d s; "
-						"distance=%d kB, estimate=%d kB",
-						CheckpointStats.ckpt_bufs_written,
-						(double) CheckpointStats.ckpt_bufs_written * 100 / NBuffers,
-						CheckpointStats.ckpt_segs_added,
-						CheckpointStats.ckpt_segs_removed,
-						CheckpointStats.ckpt_segs_recycled,
-						write_msecs / 1000, (int) (write_msecs % 1000),
-						sync_msecs / 1000, (int) (sync_msecs % 1000),
-						total_msecs / 1000, (int) (total_msecs % 1000),
-						CheckpointStats.ckpt_sync_rels,
-						longest_msecs / 1000, (int) (longest_msecs % 1000),
-						average_msecs / 1000, (int) (average_msecs % 1000),
-						(int) (PrevCheckPointDistance / 1024.0),
-						(int) (CheckPointDistanceEstimate / 1024.0))));
+	{
+		if (CheckpointStats.repl_snap_files_rmvd_cnt > 0 &&
+			(CheckpointStats.repl_map_files_rmvd_cnt ||
+			 CheckpointStats.repl_map_files_syncd_cnt > 0))
+		{
+			long	snap_msecs;
+			long	map_msecs;
+
+			snap_msecs = TimestampDifferenceMilliseconds(CheckpointStats.repl_snap_start_t,
+														 CheckpointStats.repl_snap_end_t);
+
+			map_msecs = TimestampDifferenceMilliseconds(CheckpointStats.repl_map_start_t,
+														 CheckpointStats.repl_map_end_t);
+
+			ereport(LOG,
+					(errmsg("restartpoint complete: wrote %d buffers (%.1f%%); "
+							"%d WAL file(s) added, %d removed, %d recycled; "
+							"write=%ld.%03d s, sync=%ld.%03d s, total=%ld.%03d s; "
+							"sync files=%d, longest=%ld.%03d s, average=%ld.%03d s; "
+							"distance=%d kB, estimate=%d kB; "
+							"logical decoding snapshot file(s) removed=" UINT64_FORMAT ", time=%ld.%03d s, cutoff LSN=%X/%X; "
+							"logical decoding rewrite mapping file(s) removed=" UINT64_FORMAT ", synced=" UINT64_FORMAT ", time=%ld.%03d s, cutoff LSN=%X/%X",
+							CheckpointStats.ckpt_bufs_written,
+							(double) CheckpointStats.ckpt_bufs_written * 100 / NBuffers,
+							CheckpointStats.ckpt_segs_added,
+							CheckpointStats.ckpt_segs_removed,
+							CheckpointStats.ckpt_segs_recycled,
+							write_msecs / 1000, (int) (write_msecs % 1000),
+							sync_msecs / 1000, (int) (sync_msecs % 1000),
+							total_msecs / 1000, (int) (total_msecs % 1000),
+							CheckpointStats.ckpt_sync_rels,
+							longest_msecs / 1000, (int) (longest_msecs % 1000),
+							average_msecs / 1000, (int) (average_msecs % 1000),
+							(int) (PrevCheckPointDistance / 1024.0),
+							(int) (CheckPointDistanceEstimate / 1024.0),
+							CheckpointStats.repl_snap_files_rmvd_cnt,
+							snap_msecs / 1000, (int) (snap_msecs % 1000),
+							LSN_FORMAT_ARGS(CheckpointStats.repl_snap_cutoff_lsn),
+							CheckpointStats.repl_map_files_rmvd_cnt,
+							CheckpointStats.repl_map_files_syncd_cnt,
+							map_msecs / 1000, (int) (map_msecs % 1000),
+							LSN_FORMAT_ARGS(CheckpointStats.repl_map_cutoff_lsn))));
+		}
+		else if (CheckpointStats.repl_snap_files_rmvd_cnt > 0)
+		{
+			long	snap_msecs;
+
+			snap_msecs = TimestampDifferenceMilliseconds(CheckpointStats.repl_snap_start_t,
+														 CheckpointStats.repl_snap_end_t);
+
+			ereport(LOG,
+					(errmsg("restartpoint complete: wrote %d buffers (%.1f%%); "
+							"%d WAL file(s) added, %d removed, %d recycled; "
+							"write=%ld.%03d s, sync=%ld.%03d s, total=%ld.%03d s; "
+							"sync files=%d, longest=%ld.%03d s, average=%ld.%03d s; "
+							"distance=%d kB, estimate=%d kB; "
+							"logical decoding snapshot file(s) removed=" UINT64_FORMAT ", time=%ld.%03d s, cutoff LSN=%X/%X",
+							CheckpointStats.ckpt_bufs_written,
+							(double) CheckpointStats.ckpt_bufs_written * 100 / NBuffers,
+							CheckpointStats.ckpt_segs_added,
+							CheckpointStats.ckpt_segs_removed,
+							CheckpointStats.ckpt_segs_recycled,
+							write_msecs / 1000, (int) (write_msecs % 1000),
+							sync_msecs / 1000, (int) (sync_msecs % 1000),
+							total_msecs / 1000, (int) (total_msecs % 1000),
+							CheckpointStats.ckpt_sync_rels,
+							longest_msecs / 1000, (int) (longest_msecs % 1000),
+							average_msecs / 1000, (int) (average_msecs % 1000),
+							(int) (PrevCheckPointDistance / 1024.0),
+							(int) (CheckPointDistanceEstimate / 1024.0),
+							CheckpointStats.repl_snap_files_rmvd_cnt,
+							snap_msecs / 1000, (int) (snap_msecs % 1000),
+							LSN_FORMAT_ARGS(CheckpointStats.repl_snap_cutoff_lsn))));
+		}
+		else if (CheckpointStats.repl_map_files_rmvd_cnt ||
+				 CheckpointStats.repl_map_files_syncd_cnt > 0)
+		{
+			long	map_msecs;
+
+			map_msecs = TimestampDifferenceMilliseconds(CheckpointStats.repl_map_start_t,
+														 CheckpointStats.repl_map_end_t);
+
+			ereport(LOG,
+					(errmsg("restartpoint complete: wrote %d buffers (%.1f%%); "
+							"%d WAL file(s) added, %d removed, %d recycled; "
+							"write=%ld.%03d s, sync=%ld.%03d s, total=%ld.%03d s; "
+							"sync files=%d, longest=%ld.%03d s, average=%ld.%03d s; "
+							"distance=%d kB, estimate=%d kB; "
+							"logical decoding rewrite mapping file(s) removed=" UINT64_FORMAT ", synced=" UINT64_FORMAT ", time=%ld.%03d s, cutoff LSN=%X/%X",
+							CheckpointStats.ckpt_bufs_written,
+							(double) CheckpointStats.ckpt_bufs_written * 100 / NBuffers,
+							CheckpointStats.ckpt_segs_added,
+							CheckpointStats.ckpt_segs_removed,
+							CheckpointStats.ckpt_segs_recycled,
+							write_msecs / 1000, (int) (write_msecs % 1000),
+							sync_msecs / 1000, (int) (sync_msecs % 1000),
+							total_msecs / 1000, (int) (total_msecs % 1000),
+							CheckpointStats.ckpt_sync_rels,
+							longest_msecs / 1000, (int) (longest_msecs % 1000),
+							average_msecs / 1000, (int) (average_msecs % 1000),
+							(int) (PrevCheckPointDistance / 1024.0),
+							(int) (CheckPointDistanceEstimate / 1024.0),
+							CheckpointStats.repl_map_files_rmvd_cnt,
+							CheckpointStats.repl_map_files_syncd_cnt,
+							map_msecs / 1000, (int) (map_msecs % 1000),
+							LSN_FORMAT_ARGS(CheckpointStats.repl_map_cutoff_lsn))));
+		}
+		else
+		{
+			ereport(LOG,
+					(errmsg("restartpoint complete: wrote %d buffers (%.1f%%); "
+							"%d WAL file(s) added, %d removed, %d recycled; "
+							"write=%ld.%03d s, sync=%ld.%03d s, total=%ld.%03d s; "
+							"sync files=%d, longest=%ld.%03d s, average=%ld.%03d s; "
+							"distance=%d kB, estimate=%d kB",
+							CheckpointStats.ckpt_bufs_written,
+							(double) CheckpointStats.ckpt_bufs_written * 100 / NBuffers,
+							CheckpointStats.ckpt_segs_added,
+							CheckpointStats.ckpt_segs_removed,
+							CheckpointStats.ckpt_segs_recycled,
+							write_msecs / 1000, (int) (write_msecs % 1000),
+							sync_msecs / 1000, (int) (sync_msecs % 1000),
+							total_msecs / 1000, (int) (total_msecs % 1000),
+							CheckpointStats.ckpt_sync_rels,
+							longest_msecs / 1000, (int) (longest_msecs % 1000),
+							average_msecs / 1000, (int) (average_msecs % 1000),
+							(int) (PrevCheckPointDistance / 1024.0),
+							(int) (CheckPointDistanceEstimate / 1024.0))));
+		}
+	}
 	else
-		ereport(LOG,
-				(errmsg("checkpoint complete: wrote %d buffers (%.1f%%); "
-						"%d WAL file(s) added, %d removed, %d recycled; "
-						"write=%ld.%03d s, sync=%ld.%03d s, total=%ld.%03d s; "
-						"sync files=%d, longest=%ld.%03d s, average=%ld.%03d s; "
-						"distance=%d kB, estimate=%d kB",
-						CheckpointStats.ckpt_bufs_written,
-						(double) CheckpointStats.ckpt_bufs_written * 100 / NBuffers,
-						CheckpointStats.ckpt_segs_added,
-						CheckpointStats.ckpt_segs_removed,
-						CheckpointStats.ckpt_segs_recycled,
-						write_msecs / 1000, (int) (write_msecs % 1000),
-						sync_msecs / 1000, (int) (sync_msecs % 1000),
-						total_msecs / 1000, (int) (total_msecs % 1000),
-						CheckpointStats.ckpt_sync_rels,
-						longest_msecs / 1000, (int) (longest_msecs % 1000),
-						average_msecs / 1000, (int) (average_msecs % 1000),
-						(int) (PrevCheckPointDistance / 1024.0),
-						(int) (CheckPointDistanceEstimate / 1024.0))));
+	{
+		if (CheckpointStats.repl_snap_files_rmvd_cnt > 0 &&
+			(CheckpointStats.repl_map_files_rmvd_cnt ||
+			 CheckpointStats.repl_map_files_syncd_cnt > 0))
+		{
+			long	snap_msecs;
+			long	map_msecs;
+
+			snap_msecs = TimestampDifferenceMilliseconds(CheckpointStats.repl_snap_start_t,
+														 CheckpointStats.repl_snap_end_t);
+
+			map_msecs = TimestampDifferenceMilliseconds(CheckpointStats.repl_map_start_t,
+														 CheckpointStats.repl_map_end_t);
+
+			ereport(LOG,
+					(errmsg("checkpoint complete: wrote %d buffers (%.1f%%); "
+							"%d WAL file(s) added, %d removed, %d recycled; "
+							"write=%ld.%03d s, sync=%ld.%03d s, total=%ld.%03d s; "
+							"sync files=%d, longest=%ld.%03d s, average=%ld.%03d s; "
+							"distance=%d kB, estimate=%d kB; "
+							"logical decoding snapshot file(s) removed=" UINT64_FORMAT ", time=%ld.%03d s, cutoff LSN=%X/%X; "
+							"logical decoding rewrite mapping file(s) removed=" UINT64_FORMAT ", synced=" UINT64_FORMAT ", time=%ld.%03d s, cutoff LSN=%X/%X",
+							CheckpointStats.ckpt_bufs_written,
+							(double) CheckpointStats.ckpt_bufs_written * 100 / NBuffers,
+							CheckpointStats.ckpt_segs_added,
+							CheckpointStats.ckpt_segs_removed,
+							CheckpointStats.ckpt_segs_recycled,
+							write_msecs / 1000, (int) (write_msecs % 1000),
+							sync_msecs / 1000, (int) (sync_msecs % 1000),
+							total_msecs / 1000, (int) (total_msecs % 1000),
+							CheckpointStats.ckpt_sync_rels,
+							longest_msecs / 1000, (int) (longest_msecs % 1000),
+							average_msecs / 1000, (int) (average_msecs % 1000),
+							(int) (PrevCheckPointDistance / 1024.0),
+							(int) (CheckPointDistanceEstimate / 1024.0),
+							CheckpointStats.repl_snap_files_rmvd_cnt,
+							snap_msecs / 1000, (int) (snap_msecs % 1000),
+							LSN_FORMAT_ARGS(CheckpointStats.repl_snap_cutoff_lsn),
+							CheckpointStats.repl_map_files_rmvd_cnt,
+							CheckpointStats.repl_map_files_syncd_cnt,
+							map_msecs / 1000, (int) (map_msecs % 1000),
+							LSN_FORMAT_ARGS(CheckpointStats.repl_map_cutoff_lsn))));
+		}
+		else if (CheckpointStats.repl_snap_files_rmvd_cnt > 0)
+		{
+			long	snap_msecs;
+
+			snap_msecs = TimestampDifferenceMilliseconds(CheckpointStats.repl_snap_start_t,
+														 CheckpointStats.repl_snap_end_t);
+
+			ereport(LOG,
+					(errmsg("checkpoint complete: wrote %d buffers (%.1f%%); "
+							"%d WAL file(s) added, %d removed, %d recycled; "
+							"write=%ld.%03d s, sync=%ld.%03d s, total=%ld.%03d s; "
+							"sync files=%d, longest=%ld.%03d s, average=%ld.%03d s; "
+							"distance=%d kB, estimate=%d kB; "
+							"logical decoding snapshot file(s) removed=" UINT64_FORMAT ", time=%ld.%03d s, cutoff LSN=%X/%X",
+							CheckpointStats.ckpt_bufs_written,
+							(double) CheckpointStats.ckpt_bufs_written * 100 / NBuffers,
+							CheckpointStats.ckpt_segs_added,
+							CheckpointStats.ckpt_segs_removed,
+							CheckpointStats.ckpt_segs_recycled,
+							write_msecs / 1000, (int) (write_msecs % 1000),
+							sync_msecs / 1000, (int) (sync_msecs % 1000),
+							total_msecs / 1000, (int) (total_msecs % 1000),
+							CheckpointStats.ckpt_sync_rels,
+							longest_msecs / 1000, (int) (longest_msecs % 1000),
+							average_msecs / 1000, (int) (average_msecs % 1000),
+							(int) (PrevCheckPointDistance / 1024.0),
+							(int) (CheckPointDistanceEstimate / 1024.0),
+							CheckpointStats.repl_snap_files_rmvd_cnt,
+							snap_msecs / 1000, (int) (snap_msecs % 1000),
+							LSN_FORMAT_ARGS(CheckpointStats.repl_snap_cutoff_lsn))));
+		}
+		else if (CheckpointStats.repl_map_files_rmvd_cnt ||
+				 CheckpointStats.repl_map_files_syncd_cnt > 0)
+		{
+			long	map_msecs;
+
+			map_msecs = TimestampDifferenceMilliseconds(CheckpointStats.repl_map_start_t,
+														 CheckpointStats.repl_map_end_t);
+
+			ereport(LOG,
+					(errmsg("checkpoint complete: wrote %d buffers (%.1f%%); "
+							"%d WAL file(s) added, %d removed, %d recycled; "
+							"write=%ld.%03d s, sync=%ld.%03d s, total=%ld.%03d s; "
+							"sync files=%d, longest=%ld.%03d s, average=%ld.%03d s; "
+							"distance=%d kB, estimate=%d kB; "
+							"logical decoding rewrite mapping file(s) removed=" UINT64_FORMAT ", synced=" UINT64_FORMAT ", time=%ld.%03d s, cutoff LSN=%X/%X",
+							CheckpointStats.ckpt_bufs_written,
+							(double) CheckpointStats.ckpt_bufs_written * 100 / NBuffers,
+							CheckpointStats.ckpt_segs_added,
+							CheckpointStats.ckpt_segs_removed,
+							CheckpointStats.ckpt_segs_recycled,
+							write_msecs / 1000, (int) (write_msecs % 1000),
+							sync_msecs / 1000, (int) (sync_msecs % 1000),
+							total_msecs / 1000, (int) (total_msecs % 1000),
+							CheckpointStats.ckpt_sync_rels,
+							longest_msecs / 1000, (int) (longest_msecs % 1000),
+							average_msecs / 1000, (int) (average_msecs % 1000),
+							(int) (PrevCheckPointDistance / 1024.0),
+							(int) (CheckPointDistanceEstimate / 1024.0),
+							CheckpointStats.repl_map_files_rmvd_cnt,
+							CheckpointStats.repl_map_files_syncd_cnt,
+							map_msecs / 1000, (int) (map_msecs % 1000),
+							LSN_FORMAT_ARGS(CheckpointStats.repl_map_cutoff_lsn))));
+		}
+		else
+		{
+			ereport(LOG,
+					(errmsg("checkpoint complete: wrote %d buffers (%.1f%%); "
+							"%d WAL file(s) added, %d removed, %d recycled; "
+							"write=%ld.%03d s, sync=%ld.%03d s, total=%ld.%03d s; "
+							"sync files=%d, longest=%ld.%03d s, average=%ld.%03d s; "
+							"distance=%d kB, estimate=%d kB",
+							CheckpointStats.ckpt_bufs_written,
+							(double) CheckpointStats.ckpt_bufs_written * 100 / NBuffers,
+							CheckpointStats.ckpt_segs_added,
+							CheckpointStats.ckpt_segs_removed,
+							CheckpointStats.ckpt_segs_recycled,
+							write_msecs / 1000, (int) (write_msecs % 1000),
+							sync_msecs / 1000, (int) (sync_msecs % 1000),
+							total_msecs / 1000, (int) (total_msecs % 1000),
+							CheckpointStats.ckpt_sync_rels,
+							longest_msecs / 1000, (int) (longest_msecs % 1000),
+							average_msecs / 1000, (int) (average_msecs % 1000),
+							(int) (PrevCheckPointDistance / 1024.0),
+							(int) (CheckPointDistanceEstimate / 1024.0))));
+		}
+	}
 }
 
 /*
@@ -6811,8 +7033,15 @@ CheckPointGuts(XLogRecPtr checkPointRedo, int flags)
 {
 	CheckPointRelationMap();
 	CheckPointReplicationSlots();
+
+	CheckpointStats.repl_snap_start_t = GetCurrentTimestamp();
 	CheckPointSnapBuild();
+	CheckpointStats.repl_snap_end_t = GetCurrentTimestamp();
+
+	CheckpointStats.repl_map_start_t = GetCurrentTimestamp();
 	CheckPointLogicalRewriteHeap();
+	CheckpointStats.repl_map_end_t = GetCurrentTimestamp();
+
 	CheckPointReplicationOrigin();
 
 	/* Write out all dirty data in SLRUs and the main buffer pool */
diff --git a/src/backend/replication/logical/snapbuild.c b/src/backend/replication/logical/snapbuild.c
index 83fca8a77d..e652acfbe6 100644
--- a/src/backend/replication/logical/snapbuild.c
+++ b/src/backend/replication/logical/snapbuild.c
@@ -1941,6 +1941,8 @@ CheckPointSnapBuild(void)
 	if (redo < cutoff)
 		cutoff = redo;
 
+	CheckpointStats.repl_snap_cutoff_lsn = cutoff;
+
 	snap_dir = AllocateDir("pg_logical/snapshots");
 	while ((snap_de = ReadDir(snap_dir, "pg_logical/snapshots")) != NULL)
 	{
@@ -1997,6 +1999,8 @@ CheckPointSnapBuild(void)
 								path)));
 				continue;
 			}
+
+			CheckpointStats.repl_snap_files_rmvd_cnt++;
 		}
 	}
 	FreeDir(snap_dir);
diff --git a/src/include/access/xlog.h b/src/include/access/xlog.h
index 09f6464331..32f8116388 100644
--- a/src/include/access/xlog.h
+++ b/src/include/access/xlog.h
@@ -172,6 +172,19 @@ typedef struct CheckpointStatsData
 									 * times, which is not necessarily the
 									 * same as the total elapsed time for the
 									 * entire sync phase. */
+
+	/* Statistics of snapshot files under "pg_logical/snapshots" */
+	uint64 repl_snap_files_rmvd_cnt;
+	XLogRecPtr repl_snap_cutoff_lsn;
+	TimestampTz	repl_snap_start_t;
+	TimestampTz	repl_snap_end_t;
+
+	/* Statistics of map files under "pg_logical/mappings" */
+	uint64 repl_map_files_syncd_cnt;
+	uint64 repl_map_files_rmvd_cnt;
+	XLogRecPtr repl_map_cutoff_lsn;
+	TimestampTz	repl_map_start_t;
+	TimestampTz	repl_map_end_t;
 } CheckpointStatsData;
 
 extern CheckpointStatsData CheckpointStats;
-- 
2.25.1

From acde82f8a9990e519819aaa2e9c1a2f32441a135 Mon Sep 17 00:00:00 2001
From: Bharath Rupireddy <bharath.rupireddyforpostgres@gmail.com>
Date: Fri, 18 Mar 2022 07:48:32 +0000
Subject: [PATCH v5] Add checkpoint stats of snapshot and mapping files of
 pg_logical dir

At times, there can be many snapshot and mapping files under
pg_logical dir that the checkpoint might have to delete/fsync
based on the cutoff LSN which can increase the checkpoint time.
Add stats related to these files to better understand the delays
or time spent by the checkpointer processing them.

Add these new log message only when necessary i.e. at least one
snapshot or mapping files is processed during the checkpoint.
---
 src/backend/access/heap/rewriteheap.c       |   6 +
 src/backend/access/transam/xlog.c           | 119 +++++++++++++-------
 src/backend/replication/logical/snapbuild.c |   4 +
 src/include/access/xlog.h                   |  13 +++
 4 files changed, 104 insertions(+), 38 deletions(-)

diff --git a/src/backend/access/heap/rewriteheap.c b/src/backend/access/heap/rewriteheap.c
index 2a53826736..59cc3fa567 100644
--- a/src/backend/access/heap/rewriteheap.c
+++ b/src/backend/access/heap/rewriteheap.c
@@ -1210,6 +1210,8 @@ CheckPointLogicalRewriteHeap(void)
 	if (cutoff != InvalidXLogRecPtr && redo < cutoff)
 		cutoff = redo;
 
+	CheckpointStats.repl_map_cutoff_lsn = cutoff;
+
 	mappings_dir = AllocateDir("pg_logical/mappings");
 	while ((mapping_de = ReadDir(mappings_dir, "pg_logical/mappings")) != NULL)
 	{
@@ -1247,6 +1249,8 @@ CheckPointLogicalRewriteHeap(void)
 				ereport(ERROR,
 						(errcode_for_file_access(),
 						 errmsg("could not remove file \"%s\": %m", path)));
+
+			CheckpointStats.repl_map_files_rmvd_cnt++;
 		}
 		else
 		{
@@ -1280,6 +1284,8 @@ CheckPointLogicalRewriteHeap(void)
 						(errcode_for_file_access(),
 						 errmsg("could not close file \"%s\": %m", path)));
 		}
+
+		CheckpointStats.repl_map_files_syncd_cnt++;
 	}
 	FreeDir(mappings_dir);
 
diff --git a/src/backend/access/transam/xlog.c b/src/backend/access/transam/xlog.c
index f436471b27..1fb97e09c2 100644
--- a/src/backend/access/transam/xlog.c
+++ b/src/backend/access/transam/xlog.c
@@ -6080,6 +6080,7 @@ LogCheckpointEnd(bool restartpoint)
 				longest_msecs,
 				average_msecs;
 	uint64		average_sync_time;
+	StringInfoData logmsg;
 
 	CheckpointStats.ckpt_end_t = GetCurrentTimestamp();
 
@@ -6115,46 +6116,81 @@ LogCheckpointEnd(bool restartpoint)
 			CheckpointStats.ckpt_sync_rels;
 	average_msecs = (long) ((average_sync_time + 999) / 1000);
 
+	initStringInfo(&logmsg);
+
 	if (restartpoint)
-		ereport(LOG,
-				(errmsg("restartpoint complete: wrote %d buffers (%.1f%%); "
-						"%d WAL file(s) added, %d removed, %d recycled; "
-						"write=%ld.%03d s, sync=%ld.%03d s, total=%ld.%03d s; "
-						"sync files=%d, longest=%ld.%03d s, average=%ld.%03d s; "
-						"distance=%d kB, estimate=%d kB",
-						CheckpointStats.ckpt_bufs_written,
-						(double) CheckpointStats.ckpt_bufs_written * 100 / NBuffers,
-						CheckpointStats.ckpt_segs_added,
-						CheckpointStats.ckpt_segs_removed,
-						CheckpointStats.ckpt_segs_recycled,
-						write_msecs / 1000, (int) (write_msecs % 1000),
-						sync_msecs / 1000, (int) (sync_msecs % 1000),
-						total_msecs / 1000, (int) (total_msecs % 1000),
-						CheckpointStats.ckpt_sync_rels,
-						longest_msecs / 1000, (int) (longest_msecs % 1000),
-						average_msecs / 1000, (int) (average_msecs % 1000),
-						(int) (PrevCheckPointDistance / 1024.0),
-						(int) (CheckPointDistanceEstimate / 1024.0))));
+		appendStringInfo(&logmsg,
+						_("restartpoint complete: wrote %d buffers (%.1f%%); "
+						  "%d WAL file(s) added, %d removed, %d recycled; "
+						  "write=%ld.%03d s, sync=%ld.%03d s, total=%ld.%03d s; "
+						  "sync files=%d, longest=%ld.%03d s, average=%ld.%03d s; "
+						  "distance=%d kB, estimate=%d kB"),
+						  CheckpointStats.ckpt_bufs_written,
+						  (double) CheckpointStats.ckpt_bufs_written * 100 / NBuffers,
+						  CheckpointStats.ckpt_segs_added,
+						  CheckpointStats.ckpt_segs_removed,
+						  CheckpointStats.ckpt_segs_recycled,
+						  write_msecs / 1000, (int) (write_msecs % 1000),
+						  sync_msecs / 1000, (int) (sync_msecs % 1000),
+						  total_msecs / 1000, (int) (total_msecs % 1000),
+						  CheckpointStats.ckpt_sync_rels,
+						  longest_msecs / 1000, (int) (longest_msecs % 1000),
+						  average_msecs / 1000, (int) (average_msecs % 1000),
+						  (int) (PrevCheckPointDistance / 1024.0),
+						  (int) (CheckPointDistanceEstimate / 1024.0));
 	else
-		ereport(LOG,
-				(errmsg("checkpoint complete: wrote %d buffers (%.1f%%); "
-						"%d WAL file(s) added, %d removed, %d recycled; "
-						"write=%ld.%03d s, sync=%ld.%03d s, total=%ld.%03d s; "
-						"sync files=%d, longest=%ld.%03d s, average=%ld.%03d s; "
-						"distance=%d kB, estimate=%d kB",
-						CheckpointStats.ckpt_bufs_written,
-						(double) CheckpointStats.ckpt_bufs_written * 100 / NBuffers,
-						CheckpointStats.ckpt_segs_added,
-						CheckpointStats.ckpt_segs_removed,
-						CheckpointStats.ckpt_segs_recycled,
-						write_msecs / 1000, (int) (write_msecs % 1000),
-						sync_msecs / 1000, (int) (sync_msecs % 1000),
-						total_msecs / 1000, (int) (total_msecs % 1000),
-						CheckpointStats.ckpt_sync_rels,
-						longest_msecs / 1000, (int) (longest_msecs % 1000),
-						average_msecs / 1000, (int) (average_msecs % 1000),
-						(int) (PrevCheckPointDistance / 1024.0),
-						(int) (CheckPointDistanceEstimate / 1024.0))));
+		appendStringInfo(&logmsg,
+						_("checkpoint complete: wrote %d buffers (%.1f%%); "
+						  "%d WAL file(s) added, %d removed, %d recycled; "
+						  "write=%ld.%03d s, sync=%ld.%03d s, total=%ld.%03d s; "
+						  "sync files=%d, longest=%ld.%03d s, average=%ld.%03d s; "
+						  "distance=%d kB, estimate=%d kB"),
+						  CheckpointStats.ckpt_bufs_written,
+						  (double) CheckpointStats.ckpt_bufs_written * 100 / NBuffers,
+						  CheckpointStats.ckpt_segs_added,
+						  CheckpointStats.ckpt_segs_removed,
+						  CheckpointStats.ckpt_segs_recycled,
+						  write_msecs / 1000, (int) (write_msecs % 1000),
+						  sync_msecs / 1000, (int) (sync_msecs % 1000),
+						  total_msecs / 1000, (int) (total_msecs % 1000),
+						  CheckpointStats.ckpt_sync_rels,
+						  longest_msecs / 1000, (int) (longest_msecs % 1000),
+						  average_msecs / 1000, (int) (average_msecs % 1000),
+						  (int) (PrevCheckPointDistance / 1024.0),
+						  (int) (CheckPointDistanceEstimate / 1024.0));
+
+	if (CheckpointStats.repl_snap_files_rmvd_cnt > 0)
+	{
+		long t_msecs;
+
+		t_msecs = TimestampDifferenceMilliseconds(CheckpointStats.repl_snap_start_t,
+												  CheckpointStats.repl_snap_end_t);
+
+		appendStringInfo(&logmsg,
+						_("; logical decoding snapshot file(s) removed=" UINT64_FORMAT ", time=%ld.%03d s, cutoff LSN=%X/%X"),
+						  CheckpointStats.repl_snap_files_rmvd_cnt,
+						  t_msecs / 1000, (int) (t_msecs % 1000),
+						  LSN_FORMAT_ARGS(CheckpointStats.repl_snap_cutoff_lsn));
+	}
+
+	if (CheckpointStats.repl_map_files_rmvd_cnt ||
+		CheckpointStats.repl_map_files_syncd_cnt > 0)
+	{
+		long t_msecs;
+
+		t_msecs = TimestampDifferenceMilliseconds(CheckpointStats.repl_snap_start_t,
+												  CheckpointStats.repl_snap_end_t);
+
+		appendStringInfo(&logmsg,
+						_("; logical decoding rewrite mapping file(s) removed=" UINT64_FORMAT ", synced=" UINT64_FORMAT ", time=%ld.%03d s, cutoff LSN=%X/%X"),
+						  CheckpointStats.repl_map_files_rmvd_cnt,
+						  CheckpointStats.repl_map_files_syncd_cnt,
+						  t_msecs / 1000, (int) (t_msecs % 1000),
+						  LSN_FORMAT_ARGS(CheckpointStats.repl_map_cutoff_lsn));
+	}
+
+	ereport(LOG, errmsg_internal("%s", logmsg.data));
+	pfree(logmsg.data);
 }
 
 /*
@@ -6811,8 +6847,15 @@ CheckPointGuts(XLogRecPtr checkPointRedo, int flags)
 {
 	CheckPointRelationMap();
 	CheckPointReplicationSlots();
+
+	CheckpointStats.repl_snap_start_t = GetCurrentTimestamp();
 	CheckPointSnapBuild();
+	CheckpointStats.repl_snap_end_t = GetCurrentTimestamp();
+
+	CheckpointStats.repl_map_start_t = GetCurrentTimestamp();
 	CheckPointLogicalRewriteHeap();
+	CheckpointStats.repl_map_end_t = GetCurrentTimestamp();
+
 	CheckPointReplicationOrigin();
 
 	/* Write out all dirty data in SLRUs and the main buffer pool */
diff --git a/src/backend/replication/logical/snapbuild.c b/src/backend/replication/logical/snapbuild.c
index 83fca8a77d..e652acfbe6 100644
--- a/src/backend/replication/logical/snapbuild.c
+++ b/src/backend/replication/logical/snapbuild.c
@@ -1941,6 +1941,8 @@ CheckPointSnapBuild(void)
 	if (redo < cutoff)
 		cutoff = redo;
 
+	CheckpointStats.repl_snap_cutoff_lsn = cutoff;
+
 	snap_dir = AllocateDir("pg_logical/snapshots");
 	while ((snap_de = ReadDir(snap_dir, "pg_logical/snapshots")) != NULL)
 	{
@@ -1997,6 +1999,8 @@ CheckPointSnapBuild(void)
 								path)));
 				continue;
 			}
+
+			CheckpointStats.repl_snap_files_rmvd_cnt++;
 		}
 	}
 	FreeDir(snap_dir);
diff --git a/src/include/access/xlog.h b/src/include/access/xlog.h
index 09f6464331..32f8116388 100644
--- a/src/include/access/xlog.h
+++ b/src/include/access/xlog.h
@@ -172,6 +172,19 @@ typedef struct CheckpointStatsData
 									 * times, which is not necessarily the
 									 * same as the total elapsed time for the
 									 * entire sync phase. */
+
+	/* Statistics of snapshot files under "pg_logical/snapshots" */
+	uint64 repl_snap_files_rmvd_cnt;
+	XLogRecPtr repl_snap_cutoff_lsn;
+	TimestampTz	repl_snap_start_t;
+	TimestampTz	repl_snap_end_t;
+
+	/* Statistics of map files under "pg_logical/mappings" */
+	uint64 repl_map_files_syncd_cnt;
+	uint64 repl_map_files_rmvd_cnt;
+	XLogRecPtr repl_map_cutoff_lsn;
+	TimestampTz	repl_map_start_t;
+	TimestampTz	repl_map_end_t;
 } CheckpointStatsData;
 
 extern CheckpointStatsData CheckpointStats;
-- 
2.25.1

From b54ca9f187b9dfb94b03e7a107f01df30e789925 Mon Sep 17 00:00:00 2001
From: Bharath Rupireddy <bharath.rupireddyforpostgres@gmail.com>
Date: Mon, 21 Mar 2022 05:37:54 +0000
Subject: [PATCH v6] Deduplicate checkpoint/restartpoint complete message

---
 src/backend/access/transam/xlog.c | 66 +++++++++++++------------------
 1 file changed, 28 insertions(+), 38 deletions(-)

diff --git a/src/backend/access/transam/xlog.c b/src/backend/access/transam/xlog.c
index 4ac3871c74..b5a6e0cd61 100644
--- a/src/backend/access/transam/xlog.c
+++ b/src/backend/access/transam/xlog.c
@@ -6094,6 +6094,7 @@ LogCheckpointEnd(bool restartpoint)
 				longest_msecs,
 				average_msecs;
 	uint64		average_sync_time;
+	StringInfoData logmsg;
 
 	CheckpointStats.ckpt_end_t = GetCurrentTimestamp();
 
@@ -6129,46 +6130,35 @@ LogCheckpointEnd(bool restartpoint)
 			CheckpointStats.ckpt_sync_rels;
 	average_msecs = (long) ((average_sync_time + 999) / 1000);
 
+	initStringInfo(&logmsg);
+
 	if (restartpoint)
-		ereport(LOG,
-				(errmsg("restartpoint complete: wrote %d buffers (%.1f%%); "
-						"%d WAL file(s) added, %d removed, %d recycled; "
-						"write=%ld.%03d s, sync=%ld.%03d s, total=%ld.%03d s; "
-						"sync files=%d, longest=%ld.%03d s, average=%ld.%03d s; "
-						"distance=%d kB, estimate=%d kB",
-						CheckpointStats.ckpt_bufs_written,
-						(double) CheckpointStats.ckpt_bufs_written * 100 / NBuffers,
-						CheckpointStats.ckpt_segs_added,
-						CheckpointStats.ckpt_segs_removed,
-						CheckpointStats.ckpt_segs_recycled,
-						write_msecs / 1000, (int) (write_msecs % 1000),
-						sync_msecs / 1000, (int) (sync_msecs % 1000),
-						total_msecs / 1000, (int) (total_msecs % 1000),
-						CheckpointStats.ckpt_sync_rels,
-						longest_msecs / 1000, (int) (longest_msecs % 1000),
-						average_msecs / 1000, (int) (average_msecs % 1000),
-						(int) (PrevCheckPointDistance / 1024.0),
-						(int) (CheckPointDistanceEstimate / 1024.0))));
+		appendStringInfo(&logmsg, _("restartpoint complete: "));
 	else
-		ereport(LOG,
-				(errmsg("checkpoint complete: wrote %d buffers (%.1f%%); "
-						"%d WAL file(s) added, %d removed, %d recycled; "
-						"write=%ld.%03d s, sync=%ld.%03d s, total=%ld.%03d s; "
-						"sync files=%d, longest=%ld.%03d s, average=%ld.%03d s; "
-						"distance=%d kB, estimate=%d kB",
-						CheckpointStats.ckpt_bufs_written,
-						(double) CheckpointStats.ckpt_bufs_written * 100 / NBuffers,
-						CheckpointStats.ckpt_segs_added,
-						CheckpointStats.ckpt_segs_removed,
-						CheckpointStats.ckpt_segs_recycled,
-						write_msecs / 1000, (int) (write_msecs % 1000),
-						sync_msecs / 1000, (int) (sync_msecs % 1000),
-						total_msecs / 1000, (int) (total_msecs % 1000),
-						CheckpointStats.ckpt_sync_rels,
-						longest_msecs / 1000, (int) (longest_msecs % 1000),
-						average_msecs / 1000, (int) (average_msecs % 1000),
-						(int) (PrevCheckPointDistance / 1024.0),
-						(int) (CheckPointDistanceEstimate / 1024.0))));
+		appendStringInfo(&logmsg, _("checkpoint complete: "));
+
+	appendStringInfo(&logmsg,
+					 _("wrote %d buffers (%.1f%%); "
+					  "%d WAL file(s) added, %d removed, %d recycled; "
+					  "write=%ld.%03d s, sync=%ld.%03d s, total=%ld.%03d s; "
+					  "sync files=%d, longest=%ld.%03d s, average=%ld.%03d s; "
+					  "distance=%d kB, estimate=%d kB"),
+					   CheckpointStats.ckpt_bufs_written,
+					   (double) CheckpointStats.ckpt_bufs_written * 100 / NBuffers,
+					   CheckpointStats.ckpt_segs_added,
+					   CheckpointStats.ckpt_segs_removed,
+					   CheckpointStats.ckpt_segs_recycled,
+					   write_msecs / 1000, (int) (write_msecs % 1000),
+					   sync_msecs / 1000, (int) (sync_msecs % 1000),
+					   total_msecs / 1000, (int) (total_msecs % 1000),
+					   CheckpointStats.ckpt_sync_rels,
+					   longest_msecs / 1000, (int) (longest_msecs % 1000),
+					   average_msecs / 1000, (int) (average_msecs % 1000),
+					   (int) (PrevCheckPointDistance / 1024.0),
+					   (int) (CheckPointDistanceEstimate / 1024.0));
+
+	ereport(LOG, errmsg_internal("%s", logmsg.data));
+	pfree(logmsg.data);
 }
 
 /*
-- 
2.25.1

From f75d712cb569543400bbb22487d73f9ace0027eb Mon Sep 17 00:00:00 2001
From: Bharath Rupireddy <bharath.rupireddyforpostgres@gmail.com>
Date: Mon, 21 Mar 2022 05:45:07 +0000
Subject: [PATCH v6] Add checkpoint stats of snapshot and mapping files of
 pg_logical dir

At times, there can be many snapshot and mapping files under
pg_logical dir that the checkpoint might have to delete/fsync
based on the cutoff LSN which can increase the checkpoint time.
Add stats related to these files to better understand the delays
or time spent by the checkpointer processing them.

Add these new log message only when necessary i.e. at least one
snapshot or mapping files is processed during the checkpoint.
---
 src/backend/access/heap/rewriteheap.c       |  6 ++++
 src/backend/access/transam/xlog.c           | 37 +++++++++++++++++++++
 src/backend/replication/logical/snapbuild.c |  4 +++
 src/include/access/xlog.h                   | 13 ++++++++
 4 files changed, 60 insertions(+)

diff --git a/src/backend/access/heap/rewriteheap.c b/src/backend/access/heap/rewriteheap.c
index 2a53826736..59cc3fa567 100644
--- a/src/backend/access/heap/rewriteheap.c
+++ b/src/backend/access/heap/rewriteheap.c
@@ -1210,6 +1210,8 @@ CheckPointLogicalRewriteHeap(void)
 	if (cutoff != InvalidXLogRecPtr && redo < cutoff)
 		cutoff = redo;
 
+	CheckpointStats.repl_map_cutoff_lsn = cutoff;
+
 	mappings_dir = AllocateDir("pg_logical/mappings");
 	while ((mapping_de = ReadDir(mappings_dir, "pg_logical/mappings")) != NULL)
 	{
@@ -1247,6 +1249,8 @@ CheckPointLogicalRewriteHeap(void)
 				ereport(ERROR,
 						(errcode_for_file_access(),
 						 errmsg("could not remove file \"%s\": %m", path)));
+
+			CheckpointStats.repl_map_files_rmvd_cnt++;
 		}
 		else
 		{
@@ -1280,6 +1284,8 @@ CheckPointLogicalRewriteHeap(void)
 						(errcode_for_file_access(),
 						 errmsg("could not close file \"%s\": %m", path)));
 		}
+
+		CheckpointStats.repl_map_files_syncd_cnt++;
 	}
 	FreeDir(mappings_dir);
 
diff --git a/src/backend/access/transam/xlog.c b/src/backend/access/transam/xlog.c
index b5a6e0cd61..5b752de46e 100644
--- a/src/backend/access/transam/xlog.c
+++ b/src/backend/access/transam/xlog.c
@@ -6157,6 +6157,36 @@ LogCheckpointEnd(bool restartpoint)
 					   (int) (PrevCheckPointDistance / 1024.0),
 					   (int) (CheckPointDistanceEstimate / 1024.0));
 
+	if (CheckpointStats.repl_snap_files_rmvd_cnt > 0)
+	{
+		long t_msecs;
+
+		t_msecs = TimestampDifferenceMilliseconds(CheckpointStats.repl_snap_start_t,
+												  CheckpointStats.repl_snap_end_t);
+
+		appendStringInfo(&logmsg,
+						_("; logical decoding snapshot file(s) removed=%lu, time=%ld.%03d s, cutoff LSN=%X/%X"),
+						  CheckpointStats.repl_snap_files_rmvd_cnt,
+						  t_msecs / 1000, (int) (t_msecs % 1000),
+						  LSN_FORMAT_ARGS(CheckpointStats.repl_snap_cutoff_lsn));
+	}
+
+	if (CheckpointStats.repl_map_files_rmvd_cnt ||
+		CheckpointStats.repl_map_files_syncd_cnt > 0)
+	{
+		long t_msecs;
+
+		t_msecs = TimestampDifferenceMilliseconds(CheckpointStats.repl_snap_start_t,
+												  CheckpointStats.repl_snap_end_t);
+
+		appendStringInfo(&logmsg,
+						_("; logical decoding rewrite mapping file(s) removed=%lu, synced=%lu, time=%ld.%03d s, cutoff LSN=%X/%X"),
+						  CheckpointStats.repl_map_files_rmvd_cnt,
+						  CheckpointStats.repl_map_files_syncd_cnt,
+						  t_msecs / 1000, (int) (t_msecs % 1000),
+						  LSN_FORMAT_ARGS(CheckpointStats.repl_map_cutoff_lsn));
+	}
+
 	ereport(LOG, errmsg_internal("%s", logmsg.data));
 	pfree(logmsg.data);
 }
@@ -6815,8 +6845,15 @@ CheckPointGuts(XLogRecPtr checkPointRedo, int flags)
 {
 	CheckPointRelationMap();
 	CheckPointReplicationSlots();
+
+	CheckpointStats.repl_snap_start_t = GetCurrentTimestamp();
 	CheckPointSnapBuild();
+	CheckpointStats.repl_snap_end_t = GetCurrentTimestamp();
+
+	CheckpointStats.repl_map_start_t = GetCurrentTimestamp();
 	CheckPointLogicalRewriteHeap();
+	CheckpointStats.repl_map_end_t = GetCurrentTimestamp();
+
 	CheckPointReplicationOrigin();
 
 	/* Write out all dirty data in SLRUs and the main buffer pool */
diff --git a/src/backend/replication/logical/snapbuild.c b/src/backend/replication/logical/snapbuild.c
index 83fca8a77d..e652acfbe6 100644
--- a/src/backend/replication/logical/snapbuild.c
+++ b/src/backend/replication/logical/snapbuild.c
@@ -1941,6 +1941,8 @@ CheckPointSnapBuild(void)
 	if (redo < cutoff)
 		cutoff = redo;
 
+	CheckpointStats.repl_snap_cutoff_lsn = cutoff;
+
 	snap_dir = AllocateDir("pg_logical/snapshots");
 	while ((snap_de = ReadDir(snap_dir, "pg_logical/snapshots")) != NULL)
 	{
@@ -1997,6 +1999,8 @@ CheckPointSnapBuild(void)
 								path)));
 				continue;
 			}
+
+			CheckpointStats.repl_snap_files_rmvd_cnt++;
 		}
 	}
 	FreeDir(snap_dir);
diff --git a/src/include/access/xlog.h b/src/include/access/xlog.h
index 09f6464331..32f8116388 100644
--- a/src/include/access/xlog.h
+++ b/src/include/access/xlog.h
@@ -172,6 +172,19 @@ typedef struct CheckpointStatsData
 									 * times, which is not necessarily the
 									 * same as the total elapsed time for the
 									 * entire sync phase. */
+
+	/* Statistics of snapshot files under "pg_logical/snapshots" */
+	uint64 repl_snap_files_rmvd_cnt;
+	XLogRecPtr repl_snap_cutoff_lsn;
+	TimestampTz	repl_snap_start_t;
+	TimestampTz	repl_snap_end_t;
+
+	/* Statistics of map files under "pg_logical/mappings" */
+	uint64 repl_map_files_syncd_cnt;
+	uint64 repl_map_files_rmvd_cnt;
+	XLogRecPtr repl_map_cutoff_lsn;
+	TimestampTz	repl_map_start_t;
+	TimestampTz	repl_map_end_t;
 } CheckpointStatsData;
 
 extern CheckpointStatsData CheckpointStats;
-- 
2.25.1

From c9f92f39da7f79d4f4296af4e44957066eb61992 Mon Sep 17 00:00:00 2001
From: Bharath Rupireddy <bharath.rupireddyforpostgres@gmail.com>
Date: Wed, 23 Mar 2022 03:29:03 +0000
Subject: [PATCH v7] Deduplicate checkpoint/restartpoint starting/complete
 message

---
 src/backend/access/transam/xlog.c | 97 +++++++++++--------------------
 1 file changed, 33 insertions(+), 64 deletions(-)

diff --git a/src/backend/access/transam/xlog.c b/src/backend/access/transam/xlog.c
index 4ac3871c74..364f07bee9 100644
--- a/src/backend/access/transam/xlog.c
+++ b/src/backend/access/transam/xlog.c
@@ -6056,30 +6056,18 @@ ShutdownXLOG(int code, Datum arg)
 static void
 LogCheckpointStart(int flags, bool restartpoint)
 {
-	if (restartpoint)
-		ereport(LOG,
-		/* translator: the placeholders show checkpoint options */
-				(errmsg("restartpoint starting:%s%s%s%s%s%s%s%s",
-						(flags & CHECKPOINT_IS_SHUTDOWN) ? " shutdown" : "",
-						(flags & CHECKPOINT_END_OF_RECOVERY) ? " end-of-recovery" : "",
-						(flags & CHECKPOINT_IMMEDIATE) ? " immediate" : "",
-						(flags & CHECKPOINT_FORCE) ? " force" : "",
-						(flags & CHECKPOINT_WAIT) ? " wait" : "",
-						(flags & CHECKPOINT_CAUSE_XLOG) ? " wal" : "",
-						(flags & CHECKPOINT_CAUSE_TIME) ? " time" : "",
-						(flags & CHECKPOINT_FLUSH_ALL) ? " flush-all" : "")));
-	else
-		ereport(LOG,
-		/* translator: the placeholders show checkpoint options */
-				(errmsg("checkpoint starting:%s%s%s%s%s%s%s%s",
-						(flags & CHECKPOINT_IS_SHUTDOWN) ? " shutdown" : "",
-						(flags & CHECKPOINT_END_OF_RECOVERY) ? " end-of-recovery" : "",
-						(flags & CHECKPOINT_IMMEDIATE) ? " immediate" : "",
-						(flags & CHECKPOINT_FORCE) ? " force" : "",
-						(flags & CHECKPOINT_WAIT) ? " wait" : "",
-						(flags & CHECKPOINT_CAUSE_XLOG) ? " wal" : "",
-						(flags & CHECKPOINT_CAUSE_TIME) ? " time" : "",
-						(flags & CHECKPOINT_FLUSH_ALL) ? " flush-all" : "")));
+	ereport(LOG,
+	/* translator: the placeholders after first %s show restartpoint/checkpoint options */
+			(errmsg("%s starting:%s%s%s%s%s%s%s%s",
+					restartpoint ? _("restartpoint") : _("checkpoint"),
+					(flags & CHECKPOINT_IS_SHUTDOWN) ? " shutdown" : "",
+					(flags & CHECKPOINT_END_OF_RECOVERY) ? " end-of-recovery" : "",
+					(flags & CHECKPOINT_IMMEDIATE) ? " immediate" : "",
+					(flags & CHECKPOINT_FORCE) ? " force" : "",
+					(flags & CHECKPOINT_WAIT) ? " wait" : "",
+					(flags & CHECKPOINT_CAUSE_XLOG) ? " wal" : "",
+					(flags & CHECKPOINT_CAUSE_TIME) ? " time" : "",
+					(flags & CHECKPOINT_FLUSH_ALL) ? " flush-all" : "")));
 }
 
 /*
@@ -6129,46 +6117,27 @@ LogCheckpointEnd(bool restartpoint)
 			CheckpointStats.ckpt_sync_rels;
 	average_msecs = (long) ((average_sync_time + 999) / 1000);
 
-	if (restartpoint)
-		ereport(LOG,
-				(errmsg("restartpoint complete: wrote %d buffers (%.1f%%); "
-						"%d WAL file(s) added, %d removed, %d recycled; "
-						"write=%ld.%03d s, sync=%ld.%03d s, total=%ld.%03d s; "
-						"sync files=%d, longest=%ld.%03d s, average=%ld.%03d s; "
-						"distance=%d kB, estimate=%d kB",
-						CheckpointStats.ckpt_bufs_written,
-						(double) CheckpointStats.ckpt_bufs_written * 100 / NBuffers,
-						CheckpointStats.ckpt_segs_added,
-						CheckpointStats.ckpt_segs_removed,
-						CheckpointStats.ckpt_segs_recycled,
-						write_msecs / 1000, (int) (write_msecs % 1000),
-						sync_msecs / 1000, (int) (sync_msecs % 1000),
-						total_msecs / 1000, (int) (total_msecs % 1000),
-						CheckpointStats.ckpt_sync_rels,
-						longest_msecs / 1000, (int) (longest_msecs % 1000),
-						average_msecs / 1000, (int) (average_msecs % 1000),
-						(int) (PrevCheckPointDistance / 1024.0),
-						(int) (CheckPointDistanceEstimate / 1024.0))));
-	else
-		ereport(LOG,
-				(errmsg("checkpoint complete: wrote %d buffers (%.1f%%); "
-						"%d WAL file(s) added, %d removed, %d recycled; "
-						"write=%ld.%03d s, sync=%ld.%03d s, total=%ld.%03d s; "
-						"sync files=%d, longest=%ld.%03d s, average=%ld.%03d s; "
-						"distance=%d kB, estimate=%d kB",
-						CheckpointStats.ckpt_bufs_written,
-						(double) CheckpointStats.ckpt_bufs_written * 100 / NBuffers,
-						CheckpointStats.ckpt_segs_added,
-						CheckpointStats.ckpt_segs_removed,
-						CheckpointStats.ckpt_segs_recycled,
-						write_msecs / 1000, (int) (write_msecs % 1000),
-						sync_msecs / 1000, (int) (sync_msecs % 1000),
-						total_msecs / 1000, (int) (total_msecs % 1000),
-						CheckpointStats.ckpt_sync_rels,
-						longest_msecs / 1000, (int) (longest_msecs % 1000),
-						average_msecs / 1000, (int) (average_msecs % 1000),
-						(int) (PrevCheckPointDistance / 1024.0),
-						(int) (CheckPointDistanceEstimate / 1024.0))));
+	ereport(LOG,
+	/* translator: the placeholders after first %s show restartpoint/checkpoint stats */
+			(errmsg("%s complete: wrote %d buffers (%.1f%%); "
+					"%d WAL file(s) added, %d removed, %d recycled; "
+					"write=%ld.%03d s, sync=%ld.%03d s, total=%ld.%03d s; "
+					"sync files=%d, longest=%ld.%03d s, average=%ld.%03d s; "
+					"distance=%d kB, estimate=%d kB",
+					restartpoint ? _("restartpoint") : _("checkpoint"),
+					CheckpointStats.ckpt_bufs_written,
+					(double) CheckpointStats.ckpt_bufs_written * 100 / NBuffers,
+					CheckpointStats.ckpt_segs_added,
+					CheckpointStats.ckpt_segs_removed,
+					CheckpointStats.ckpt_segs_recycled,
+					write_msecs / 1000, (int) (write_msecs % 1000),
+					sync_msecs / 1000, (int) (sync_msecs % 1000),
+					total_msecs / 1000, (int) (total_msecs % 1000),
+					CheckpointStats.ckpt_sync_rels,
+					longest_msecs / 1000, (int) (longest_msecs % 1000),
+					average_msecs / 1000, (int) (average_msecs % 1000),
+					(int) (PrevCheckPointDistance / 1024.0),
+					(int) (CheckPointDistanceEstimate / 1024.0))));
 }
 
 /*
-- 
2.25.1

From 28a323466b2af9f75d9280f2dea399580e25759c Mon Sep 17 00:00:00 2001
From: Bharath Rupireddy <bharath.rupireddyforpostgres@gmail.com>
Date: Wed, 23 Mar 2022 04:18:56 +0000
Subject: [PATCH v7] Add checkpoint stats of snapshot and mapping files of
 pg_logical dir

At times, there can be many snapshot and mapping files under
pg_logical dir that the checkpoint might have to delete/fsync
based on the cutoff LSN which can increase the checkpoint time.
Add stats related to these files to better understand the delays
or time spent by the checkpointer processing them.

Add these new log message only when necessary i.e. at least one
snapshot or mapping files is processed during the checkpoint.
---
 src/backend/access/heap/rewriteheap.c       |  4 +
 src/backend/access/transam/xlog.c           | 86 ++++++++++++++++-----
 src/backend/replication/logical/snapbuild.c |  2 +
 src/include/access/xlog.h                   | 11 +++
 4 files changed, 82 insertions(+), 21 deletions(-)

diff --git a/src/backend/access/heap/rewriteheap.c b/src/backend/access/heap/rewriteheap.c
index 2a53826736..696d04b5f0 100644
--- a/src/backend/access/heap/rewriteheap.c
+++ b/src/backend/access/heap/rewriteheap.c
@@ -1247,6 +1247,8 @@ CheckPointLogicalRewriteHeap(void)
 				ereport(ERROR,
 						(errcode_for_file_access(),
 						 errmsg("could not remove file \"%s\": %m", path)));
+
+			CheckpointStats.repl_map_files_rmvd_cnt++;
 		}
 		else
 		{
@@ -1280,6 +1282,8 @@ CheckPointLogicalRewriteHeap(void)
 						(errcode_for_file_access(),
 						 errmsg("could not close file \"%s\": %m", path)));
 		}
+
+		CheckpointStats.repl_map_files_syncd_cnt++;
 	}
 	FreeDir(mappings_dir);
 
diff --git a/src/backend/access/transam/xlog.c b/src/backend/access/transam/xlog.c
index 364f07bee9..7e8991e27a 100644
--- a/src/backend/access/transam/xlog.c
+++ b/src/backend/access/transam/xlog.c
@@ -6082,6 +6082,7 @@ LogCheckpointEnd(bool restartpoint)
 				longest_msecs,
 				average_msecs;
 	uint64		average_sync_time;
+	StringInfoData logmsg;
 
 	CheckpointStats.ckpt_end_t = GetCurrentTimestamp();
 
@@ -6117,27 +6118,63 @@ LogCheckpointEnd(bool restartpoint)
 			CheckpointStats.ckpt_sync_rels;
 	average_msecs = (long) ((average_sync_time + 999) / 1000);
 
-	ereport(LOG,
-	/* translator: the placeholders after first %s show restartpoint/checkpoint stats */
-			(errmsg("%s complete: wrote %d buffers (%.1f%%); "
-					"%d WAL file(s) added, %d removed, %d recycled; "
-					"write=%ld.%03d s, sync=%ld.%03d s, total=%ld.%03d s; "
-					"sync files=%d, longest=%ld.%03d s, average=%ld.%03d s; "
-					"distance=%d kB, estimate=%d kB",
-					restartpoint ? _("restartpoint") : _("checkpoint"),
-					CheckpointStats.ckpt_bufs_written,
-					(double) CheckpointStats.ckpt_bufs_written * 100 / NBuffers,
-					CheckpointStats.ckpt_segs_added,
-					CheckpointStats.ckpt_segs_removed,
-					CheckpointStats.ckpt_segs_recycled,
-					write_msecs / 1000, (int) (write_msecs % 1000),
-					sync_msecs / 1000, (int) (sync_msecs % 1000),
-					total_msecs / 1000, (int) (total_msecs % 1000),
-					CheckpointStats.ckpt_sync_rels,
-					longest_msecs / 1000, (int) (longest_msecs % 1000),
-					average_msecs / 1000, (int) (average_msecs % 1000),
-					(int) (PrevCheckPointDistance / 1024.0),
-					(int) (CheckPointDistanceEstimate / 1024.0))));
+	initStringInfo(&logmsg);
+
+	if (restartpoint)
+		appendStringInfo(&logmsg, _("restartpoint complete: "));
+	else
+		appendStringInfo(&logmsg, _("checkpoint complete: "));
+
+	appendStringInfo(&logmsg,
+					_("wrote %d buffers (%.1f%%); "
+					  "%d WAL file(s) added, %d removed, %d recycled; "
+					  "write=%ld.%03d s, sync=%ld.%03d s, total=%ld.%03d s; "
+					  "sync files=%d, longest=%ld.%03d s, average=%ld.%03d s; "
+					  "distance=%d kB, estimate=%d kB"),
+					  CheckpointStats.ckpt_bufs_written,
+					  (double) CheckpointStats.ckpt_bufs_written * 100 / NBuffers,
+					  CheckpointStats.ckpt_segs_added,
+					  CheckpointStats.ckpt_segs_removed,
+					  CheckpointStats.ckpt_segs_recycled,
+					  write_msecs / 1000, (int) (write_msecs % 1000),
+					  sync_msecs / 1000, (int) (sync_msecs % 1000),
+					  total_msecs / 1000, (int) (total_msecs % 1000),
+					  CheckpointStats.ckpt_sync_rels,
+					  longest_msecs / 1000, (int) (longest_msecs % 1000),
+					  average_msecs / 1000, (int) (average_msecs % 1000),
+					  (int) (PrevCheckPointDistance / 1024.0),
+					  (int) (CheckPointDistanceEstimate / 1024.0));
+
+	if (CheckpointStats.repl_snap_files_rmvd_cnt > 0)
+	{
+		long t_msecs;
+
+		t_msecs = TimestampDifferenceMilliseconds(CheckpointStats.repl_snap_start_t,
+												  CheckpointStats.repl_snap_end_t);
+
+		appendStringInfo(&logmsg,
+						_("; logical snapshot file(s) removed=%lu, time=%ld.%03d s"),
+						  CheckpointStats.repl_snap_files_rmvd_cnt,
+						  t_msecs / 1000, (int) (t_msecs % 1000));
+	}
+
+	if (CheckpointStats.repl_map_files_rmvd_cnt ||
+		CheckpointStats.repl_map_files_syncd_cnt > 0)
+	{
+		long t_msecs;
+
+		t_msecs = TimestampDifferenceMilliseconds(CheckpointStats.repl_snap_start_t,
+												  CheckpointStats.repl_snap_end_t);
+
+		appendStringInfo(&logmsg,
+						_("; logical rewrite mapping file(s) removed=%lu, synced=%lu, time=%ld.%03d s"),
+						  CheckpointStats.repl_map_files_rmvd_cnt,
+						  CheckpointStats.repl_map_files_syncd_cnt,
+						  t_msecs / 1000, (int) (t_msecs % 1000));
+	}
+
+	ereport(LOG, errmsg_internal("%s", logmsg.data));
+	pfree(logmsg.data);
 }
 
 /*
@@ -6794,8 +6831,15 @@ CheckPointGuts(XLogRecPtr checkPointRedo, int flags)
 {
 	CheckPointRelationMap();
 	CheckPointReplicationSlots();
+
+	CheckpointStats.repl_snap_start_t = GetCurrentTimestamp();
 	CheckPointSnapBuild();
+	CheckpointStats.repl_snap_end_t = GetCurrentTimestamp();
+
+	CheckpointStats.repl_map_start_t = GetCurrentTimestamp();
 	CheckPointLogicalRewriteHeap();
+	CheckpointStats.repl_map_end_t = GetCurrentTimestamp();
+
 	CheckPointReplicationOrigin();
 
 	/* Write out all dirty data in SLRUs and the main buffer pool */
diff --git a/src/backend/replication/logical/snapbuild.c b/src/backend/replication/logical/snapbuild.c
index 83fca8a77d..2bfb367dc1 100644
--- a/src/backend/replication/logical/snapbuild.c
+++ b/src/backend/replication/logical/snapbuild.c
@@ -1997,6 +1997,8 @@ CheckPointSnapBuild(void)
 								path)));
 				continue;
 			}
+
+			CheckpointStats.repl_snap_files_rmvd_cnt++;
 		}
 	}
 	FreeDir(snap_dir);
diff --git a/src/include/access/xlog.h b/src/include/access/xlog.h
index 09f6464331..a615724b4e 100644
--- a/src/include/access/xlog.h
+++ b/src/include/access/xlog.h
@@ -172,6 +172,17 @@ typedef struct CheckpointStatsData
 									 * times, which is not necessarily the
 									 * same as the total elapsed time for the
 									 * entire sync phase. */
+
+	/* Statistics of snapshot files under "pg_logical/snapshots" */
+	uint64 repl_snap_files_rmvd_cnt;
+	TimestampTz	repl_snap_start_t;
+	TimestampTz	repl_snap_end_t;
+
+	/* Statistics of map files under "pg_logical/mappings" */
+	uint64 repl_map_files_syncd_cnt;
+	uint64 repl_map_files_rmvd_cnt;
+	TimestampTz	repl_map_start_t;
+	TimestampTz	repl_map_end_t;
 } CheckpointStatsData;
 
 extern CheckpointStatsData CheckpointStats;
-- 
2.25.1

From c9f92f39da7f79d4f4296af4e44957066eb61992 Mon Sep 17 00:00:00 2001
From: Bharath Rupireddy <bharath.rupireddyforpostgres@gmail.com>
Date: Wed, 23 Mar 2022 03:29:03 +0000
Subject: [PATCH v8] Deduplicate checkpoint/restartpoint starting/complete
 message

---
 src/backend/access/transam/xlog.c | 97 +++++++++++--------------------
 1 file changed, 33 insertions(+), 64 deletions(-)

diff --git a/src/backend/access/transam/xlog.c b/src/backend/access/transam/xlog.c
index 4ac3871c74..364f07bee9 100644
--- a/src/backend/access/transam/xlog.c
+++ b/src/backend/access/transam/xlog.c
@@ -6056,30 +6056,18 @@ ShutdownXLOG(int code, Datum arg)
 static void
 LogCheckpointStart(int flags, bool restartpoint)
 {
-	if (restartpoint)
-		ereport(LOG,
-		/* translator: the placeholders show checkpoint options */
-				(errmsg("restartpoint starting:%s%s%s%s%s%s%s%s",
-						(flags & CHECKPOINT_IS_SHUTDOWN) ? " shutdown" : "",
-						(flags & CHECKPOINT_END_OF_RECOVERY) ? " end-of-recovery" : "",
-						(flags & CHECKPOINT_IMMEDIATE) ? " immediate" : "",
-						(flags & CHECKPOINT_FORCE) ? " force" : "",
-						(flags & CHECKPOINT_WAIT) ? " wait" : "",
-						(flags & CHECKPOINT_CAUSE_XLOG) ? " wal" : "",
-						(flags & CHECKPOINT_CAUSE_TIME) ? " time" : "",
-						(flags & CHECKPOINT_FLUSH_ALL) ? " flush-all" : "")));
-	else
-		ereport(LOG,
-		/* translator: the placeholders show checkpoint options */
-				(errmsg("checkpoint starting:%s%s%s%s%s%s%s%s",
-						(flags & CHECKPOINT_IS_SHUTDOWN) ? " shutdown" : "",
-						(flags & CHECKPOINT_END_OF_RECOVERY) ? " end-of-recovery" : "",
-						(flags & CHECKPOINT_IMMEDIATE) ? " immediate" : "",
-						(flags & CHECKPOINT_FORCE) ? " force" : "",
-						(flags & CHECKPOINT_WAIT) ? " wait" : "",
-						(flags & CHECKPOINT_CAUSE_XLOG) ? " wal" : "",
-						(flags & CHECKPOINT_CAUSE_TIME) ? " time" : "",
-						(flags & CHECKPOINT_FLUSH_ALL) ? " flush-all" : "")));
+	ereport(LOG,
+	/* translator: the placeholders after first %s show restartpoint/checkpoint options */
+			(errmsg("%s starting:%s%s%s%s%s%s%s%s",
+					restartpoint ? _("restartpoint") : _("checkpoint"),
+					(flags & CHECKPOINT_IS_SHUTDOWN) ? " shutdown" : "",
+					(flags & CHECKPOINT_END_OF_RECOVERY) ? " end-of-recovery" : "",
+					(flags & CHECKPOINT_IMMEDIATE) ? " immediate" : "",
+					(flags & CHECKPOINT_FORCE) ? " force" : "",
+					(flags & CHECKPOINT_WAIT) ? " wait" : "",
+					(flags & CHECKPOINT_CAUSE_XLOG) ? " wal" : "",
+					(flags & CHECKPOINT_CAUSE_TIME) ? " time" : "",
+					(flags & CHECKPOINT_FLUSH_ALL) ? " flush-all" : "")));
 }
 
 /*
@@ -6129,46 +6117,27 @@ LogCheckpointEnd(bool restartpoint)
 			CheckpointStats.ckpt_sync_rels;
 	average_msecs = (long) ((average_sync_time + 999) / 1000);
 
-	if (restartpoint)
-		ereport(LOG,
-				(errmsg("restartpoint complete: wrote %d buffers (%.1f%%); "
-						"%d WAL file(s) added, %d removed, %d recycled; "
-						"write=%ld.%03d s, sync=%ld.%03d s, total=%ld.%03d s; "
-						"sync files=%d, longest=%ld.%03d s, average=%ld.%03d s; "
-						"distance=%d kB, estimate=%d kB",
-						CheckpointStats.ckpt_bufs_written,
-						(double) CheckpointStats.ckpt_bufs_written * 100 / NBuffers,
-						CheckpointStats.ckpt_segs_added,
-						CheckpointStats.ckpt_segs_removed,
-						CheckpointStats.ckpt_segs_recycled,
-						write_msecs / 1000, (int) (write_msecs % 1000),
-						sync_msecs / 1000, (int) (sync_msecs % 1000),
-						total_msecs / 1000, (int) (total_msecs % 1000),
-						CheckpointStats.ckpt_sync_rels,
-						longest_msecs / 1000, (int) (longest_msecs % 1000),
-						average_msecs / 1000, (int) (average_msecs % 1000),
-						(int) (PrevCheckPointDistance / 1024.0),
-						(int) (CheckPointDistanceEstimate / 1024.0))));
-	else
-		ereport(LOG,
-				(errmsg("checkpoint complete: wrote %d buffers (%.1f%%); "
-						"%d WAL file(s) added, %d removed, %d recycled; "
-						"write=%ld.%03d s, sync=%ld.%03d s, total=%ld.%03d s; "
-						"sync files=%d, longest=%ld.%03d s, average=%ld.%03d s; "
-						"distance=%d kB, estimate=%d kB",
-						CheckpointStats.ckpt_bufs_written,
-						(double) CheckpointStats.ckpt_bufs_written * 100 / NBuffers,
-						CheckpointStats.ckpt_segs_added,
-						CheckpointStats.ckpt_segs_removed,
-						CheckpointStats.ckpt_segs_recycled,
-						write_msecs / 1000, (int) (write_msecs % 1000),
-						sync_msecs / 1000, (int) (sync_msecs % 1000),
-						total_msecs / 1000, (int) (total_msecs % 1000),
-						CheckpointStats.ckpt_sync_rels,
-						longest_msecs / 1000, (int) (longest_msecs % 1000),
-						average_msecs / 1000, (int) (average_msecs % 1000),
-						(int) (PrevCheckPointDistance / 1024.0),
-						(int) (CheckPointDistanceEstimate / 1024.0))));
+	ereport(LOG,
+	/* translator: the placeholders after first %s show restartpoint/checkpoint stats */
+			(errmsg("%s complete: wrote %d buffers (%.1f%%); "
+					"%d WAL file(s) added, %d removed, %d recycled; "
+					"write=%ld.%03d s, sync=%ld.%03d s, total=%ld.%03d s; "
+					"sync files=%d, longest=%ld.%03d s, average=%ld.%03d s; "
+					"distance=%d kB, estimate=%d kB",
+					restartpoint ? _("restartpoint") : _("checkpoint"),
+					CheckpointStats.ckpt_bufs_written,
+					(double) CheckpointStats.ckpt_bufs_written * 100 / NBuffers,
+					CheckpointStats.ckpt_segs_added,
+					CheckpointStats.ckpt_segs_removed,
+					CheckpointStats.ckpt_segs_recycled,
+					write_msecs / 1000, (int) (write_msecs % 1000),
+					sync_msecs / 1000, (int) (sync_msecs % 1000),
+					total_msecs / 1000, (int) (total_msecs % 1000),
+					CheckpointStats.ckpt_sync_rels,
+					longest_msecs / 1000, (int) (longest_msecs % 1000),
+					average_msecs / 1000, (int) (average_msecs % 1000),
+					(int) (PrevCheckPointDistance / 1024.0),
+					(int) (CheckPointDistanceEstimate / 1024.0))));
 }
 
 /*
-- 
2.25.1

From 28a323466b2af9f75d9280f2dea399580e25759c Mon Sep 17 00:00:00 2001
From: Bharath Rupireddy <bharath.rupireddyforpostgres@gmail.com>
Date: Wed, 23 Mar 2022 04:18:56 +0000
Subject: [PATCH v8] Add checkpoint stats of snapshot and mapping files of
 pg_logical dir

At times, there can be many snapshot and mapping files under
pg_logical dir that the checkpoint might have to delete/fsync
based on the cutoff LSN which can increase the checkpoint time.
Add stats related to these files to better understand the delays
or time spent by the checkpointer processing them.

Add these new log message only when necessary i.e. at least one
snapshot or mapping files is processed during the checkpoint.
---
 src/backend/access/heap/rewriteheap.c       |  4 +
 src/backend/access/transam/xlog.c           | 86 ++++++++++++++++-----
 src/backend/replication/logical/snapbuild.c |  2 +
 src/include/access/xlog.h                   | 11 +++
 4 files changed, 82 insertions(+), 21 deletions(-)

diff --git a/src/backend/access/heap/rewriteheap.c b/src/backend/access/heap/rewriteheap.c
index 2a53826736..696d04b5f0 100644
--- a/src/backend/access/heap/rewriteheap.c
+++ b/src/backend/access/heap/rewriteheap.c
@@ -1247,6 +1247,8 @@ CheckPointLogicalRewriteHeap(void)
 				ereport(ERROR,
 						(errcode_for_file_access(),
 						 errmsg("could not remove file \"%s\": %m", path)));
+
+			CheckpointStats.repl_map_files_rmvd_cnt++;
 		}
 		else
 		{
@@ -1280,6 +1282,8 @@ CheckPointLogicalRewriteHeap(void)
 						(errcode_for_file_access(),
 						 errmsg("could not close file \"%s\": %m", path)));
 		}
+
+		CheckpointStats.repl_map_files_syncd_cnt++;
 	}
 	FreeDir(mappings_dir);
 
diff --git a/src/backend/access/transam/xlog.c b/src/backend/access/transam/xlog.c
index 364f07bee9..7e8991e27a 100644
--- a/src/backend/access/transam/xlog.c
+++ b/src/backend/access/transam/xlog.c
@@ -6082,6 +6082,7 @@ LogCheckpointEnd(bool restartpoint)
 				longest_msecs,
 				average_msecs;
 	uint64		average_sync_time;
+	StringInfoData logmsg;
 
 	CheckpointStats.ckpt_end_t = GetCurrentTimestamp();
 
@@ -6117,27 +6118,63 @@ LogCheckpointEnd(bool restartpoint)
 			CheckpointStats.ckpt_sync_rels;
 	average_msecs = (long) ((average_sync_time + 999) / 1000);
 
-	ereport(LOG,
-	/* translator: the placeholders after first %s show restartpoint/checkpoint stats */
-			(errmsg("%s complete: wrote %d buffers (%.1f%%); "
-					"%d WAL file(s) added, %d removed, %d recycled; "
-					"write=%ld.%03d s, sync=%ld.%03d s, total=%ld.%03d s; "
-					"sync files=%d, longest=%ld.%03d s, average=%ld.%03d s; "
-					"distance=%d kB, estimate=%d kB",
-					restartpoint ? _("restartpoint") : _("checkpoint"),
-					CheckpointStats.ckpt_bufs_written,
-					(double) CheckpointStats.ckpt_bufs_written * 100 / NBuffers,
-					CheckpointStats.ckpt_segs_added,
-					CheckpointStats.ckpt_segs_removed,
-					CheckpointStats.ckpt_segs_recycled,
-					write_msecs / 1000, (int) (write_msecs % 1000),
-					sync_msecs / 1000, (int) (sync_msecs % 1000),
-					total_msecs / 1000, (int) (total_msecs % 1000),
-					CheckpointStats.ckpt_sync_rels,
-					longest_msecs / 1000, (int) (longest_msecs % 1000),
-					average_msecs / 1000, (int) (average_msecs % 1000),
-					(int) (PrevCheckPointDistance / 1024.0),
-					(int) (CheckPointDistanceEstimate / 1024.0))));
+	initStringInfo(&logmsg);
+
+	if (restartpoint)
+		appendStringInfo(&logmsg, _("restartpoint complete: "));
+	else
+		appendStringInfo(&logmsg, _("checkpoint complete: "));
+
+	appendStringInfo(&logmsg,
+					_("wrote %d buffers (%.1f%%); "
+					  "%d WAL file(s) added, %d removed, %d recycled; "
+					  "write=%ld.%03d s, sync=%ld.%03d s, total=%ld.%03d s; "
+					  "sync files=%d, longest=%ld.%03d s, average=%ld.%03d s; "
+					  "distance=%d kB, estimate=%d kB"),
+					  CheckpointStats.ckpt_bufs_written,
+					  (double) CheckpointStats.ckpt_bufs_written * 100 / NBuffers,
+					  CheckpointStats.ckpt_segs_added,
+					  CheckpointStats.ckpt_segs_removed,
+					  CheckpointStats.ckpt_segs_recycled,
+					  write_msecs / 1000, (int) (write_msecs % 1000),
+					  sync_msecs / 1000, (int) (sync_msecs % 1000),
+					  total_msecs / 1000, (int) (total_msecs % 1000),
+					  CheckpointStats.ckpt_sync_rels,
+					  longest_msecs / 1000, (int) (longest_msecs % 1000),
+					  average_msecs / 1000, (int) (average_msecs % 1000),
+					  (int) (PrevCheckPointDistance / 1024.0),
+					  (int) (CheckPointDistanceEstimate / 1024.0));
+
+	if (CheckpointStats.repl_snap_files_rmvd_cnt > 0)
+	{
+		long t_msecs;
+
+		t_msecs = TimestampDifferenceMilliseconds(CheckpointStats.repl_snap_start_t,
+												  CheckpointStats.repl_snap_end_t);
+
+		appendStringInfo(&logmsg,
+						_("; logical snapshot file(s) removed=%lu, time=%ld.%03d s"),
+						  CheckpointStats.repl_snap_files_rmvd_cnt,
+						  t_msecs / 1000, (int) (t_msecs % 1000));
+	}
+
+	if (CheckpointStats.repl_map_files_rmvd_cnt ||
+		CheckpointStats.repl_map_files_syncd_cnt > 0)
+	{
+		long t_msecs;
+
+		t_msecs = TimestampDifferenceMilliseconds(CheckpointStats.repl_snap_start_t,
+												  CheckpointStats.repl_snap_end_t);
+
+		appendStringInfo(&logmsg,
+						_("; logical rewrite mapping file(s) removed=%lu, synced=%lu, time=%ld.%03d s"),
+						  CheckpointStats.repl_map_files_rmvd_cnt,
+						  CheckpointStats.repl_map_files_syncd_cnt,
+						  t_msecs / 1000, (int) (t_msecs % 1000));
+	}
+
+	ereport(LOG, errmsg_internal("%s", logmsg.data));
+	pfree(logmsg.data);
 }
 
 /*
@@ -6794,8 +6831,15 @@ CheckPointGuts(XLogRecPtr checkPointRedo, int flags)
 {
 	CheckPointRelationMap();
 	CheckPointReplicationSlots();
+
+	CheckpointStats.repl_snap_start_t = GetCurrentTimestamp();
 	CheckPointSnapBuild();
+	CheckpointStats.repl_snap_end_t = GetCurrentTimestamp();
+
+	CheckpointStats.repl_map_start_t = GetCurrentTimestamp();
 	CheckPointLogicalRewriteHeap();
+	CheckpointStats.repl_map_end_t = GetCurrentTimestamp();
+
 	CheckPointReplicationOrigin();
 
 	/* Write out all dirty data in SLRUs and the main buffer pool */
diff --git a/src/backend/replication/logical/snapbuild.c b/src/backend/replication/logical/snapbuild.c
index 83fca8a77d..2bfb367dc1 100644
--- a/src/backend/replication/logical/snapbuild.c
+++ b/src/backend/replication/logical/snapbuild.c
@@ -1997,6 +1997,8 @@ CheckPointSnapBuild(void)
 								path)));
 				continue;
 			}
+
+			CheckpointStats.repl_snap_files_rmvd_cnt++;
 		}
 	}
 	FreeDir(snap_dir);
diff --git a/src/include/access/xlog.h b/src/include/access/xlog.h
index 09f6464331..a615724b4e 100644
--- a/src/include/access/xlog.h
+++ b/src/include/access/xlog.h
@@ -172,6 +172,17 @@ typedef struct CheckpointStatsData
 									 * times, which is not necessarily the
 									 * same as the total elapsed time for the
 									 * entire sync phase. */
+
+	/* Statistics of snapshot files under "pg_logical/snapshots" */
+	uint64 repl_snap_files_rmvd_cnt;
+	TimestampTz	repl_snap_start_t;
+	TimestampTz	repl_snap_end_t;
+
+	/* Statistics of map files under "pg_logical/mappings" */
+	uint64 repl_map_files_syncd_cnt;
+	uint64 repl_map_files_rmvd_cnt;
+	TimestampTz	repl_map_start_t;
+	TimestampTz	repl_map_end_t;
 } CheckpointStatsData;
 
 extern CheckpointStatsData CheckpointStats;
-- 
2.25.1

From e30020e4157b9a15ed47862fdc0ca09acd4725c4 Mon Sep 17 00:00:00 2001
From: Bharath Rupireddy <bharath.rupireddyforpostgres@gmail.com>
Date: Thu, 24 Mar 2022 09:39:02 +0000
Subject: [PATCH v9] Deduplicate checkpoint/restartpoint starting/complete
 message

---
 src/backend/access/transam/xlog.c | 97 +++++++++++--------------------
 1 file changed, 33 insertions(+), 64 deletions(-)

diff --git a/src/backend/access/transam/xlog.c b/src/backend/access/transam/xlog.c
index 4ac3871c74..364f07bee9 100644
--- a/src/backend/access/transam/xlog.c
+++ b/src/backend/access/transam/xlog.c
@@ -6056,30 +6056,18 @@ ShutdownXLOG(int code, Datum arg)
 static void
 LogCheckpointStart(int flags, bool restartpoint)
 {
-	if (restartpoint)
-		ereport(LOG,
-		/* translator: the placeholders show checkpoint options */
-				(errmsg("restartpoint starting:%s%s%s%s%s%s%s%s",
-						(flags & CHECKPOINT_IS_SHUTDOWN) ? " shutdown" : "",
-						(flags & CHECKPOINT_END_OF_RECOVERY) ? " end-of-recovery" : "",
-						(flags & CHECKPOINT_IMMEDIATE) ? " immediate" : "",
-						(flags & CHECKPOINT_FORCE) ? " force" : "",
-						(flags & CHECKPOINT_WAIT) ? " wait" : "",
-						(flags & CHECKPOINT_CAUSE_XLOG) ? " wal" : "",
-						(flags & CHECKPOINT_CAUSE_TIME) ? " time" : "",
-						(flags & CHECKPOINT_FLUSH_ALL) ? " flush-all" : "")));
-	else
-		ereport(LOG,
-		/* translator: the placeholders show checkpoint options */
-				(errmsg("checkpoint starting:%s%s%s%s%s%s%s%s",
-						(flags & CHECKPOINT_IS_SHUTDOWN) ? " shutdown" : "",
-						(flags & CHECKPOINT_END_OF_RECOVERY) ? " end-of-recovery" : "",
-						(flags & CHECKPOINT_IMMEDIATE) ? " immediate" : "",
-						(flags & CHECKPOINT_FORCE) ? " force" : "",
-						(flags & CHECKPOINT_WAIT) ? " wait" : "",
-						(flags & CHECKPOINT_CAUSE_XLOG) ? " wal" : "",
-						(flags & CHECKPOINT_CAUSE_TIME) ? " time" : "",
-						(flags & CHECKPOINT_FLUSH_ALL) ? " flush-all" : "")));
+	ereport(LOG,
+	/* translator: the placeholders after first %s show restartpoint/checkpoint options */
+			(errmsg("%s starting:%s%s%s%s%s%s%s%s",
+					restartpoint ? _("restartpoint") : _("checkpoint"),
+					(flags & CHECKPOINT_IS_SHUTDOWN) ? " shutdown" : "",
+					(flags & CHECKPOINT_END_OF_RECOVERY) ? " end-of-recovery" : "",
+					(flags & CHECKPOINT_IMMEDIATE) ? " immediate" : "",
+					(flags & CHECKPOINT_FORCE) ? " force" : "",
+					(flags & CHECKPOINT_WAIT) ? " wait" : "",
+					(flags & CHECKPOINT_CAUSE_XLOG) ? " wal" : "",
+					(flags & CHECKPOINT_CAUSE_TIME) ? " time" : "",
+					(flags & CHECKPOINT_FLUSH_ALL) ? " flush-all" : "")));
 }
 
 /*
@@ -6129,46 +6117,27 @@ LogCheckpointEnd(bool restartpoint)
 			CheckpointStats.ckpt_sync_rels;
 	average_msecs = (long) ((average_sync_time + 999) / 1000);
 
-	if (restartpoint)
-		ereport(LOG,
-				(errmsg("restartpoint complete: wrote %d buffers (%.1f%%); "
-						"%d WAL file(s) added, %d removed, %d recycled; "
-						"write=%ld.%03d s, sync=%ld.%03d s, total=%ld.%03d s; "
-						"sync files=%d, longest=%ld.%03d s, average=%ld.%03d s; "
-						"distance=%d kB, estimate=%d kB",
-						CheckpointStats.ckpt_bufs_written,
-						(double) CheckpointStats.ckpt_bufs_written * 100 / NBuffers,
-						CheckpointStats.ckpt_segs_added,
-						CheckpointStats.ckpt_segs_removed,
-						CheckpointStats.ckpt_segs_recycled,
-						write_msecs / 1000, (int) (write_msecs % 1000),
-						sync_msecs / 1000, (int) (sync_msecs % 1000),
-						total_msecs / 1000, (int) (total_msecs % 1000),
-						CheckpointStats.ckpt_sync_rels,
-						longest_msecs / 1000, (int) (longest_msecs % 1000),
-						average_msecs / 1000, (int) (average_msecs % 1000),
-						(int) (PrevCheckPointDistance / 1024.0),
-						(int) (CheckPointDistanceEstimate / 1024.0))));
-	else
-		ereport(LOG,
-				(errmsg("checkpoint complete: wrote %d buffers (%.1f%%); "
-						"%d WAL file(s) added, %d removed, %d recycled; "
-						"write=%ld.%03d s, sync=%ld.%03d s, total=%ld.%03d s; "
-						"sync files=%d, longest=%ld.%03d s, average=%ld.%03d s; "
-						"distance=%d kB, estimate=%d kB",
-						CheckpointStats.ckpt_bufs_written,
-						(double) CheckpointStats.ckpt_bufs_written * 100 / NBuffers,
-						CheckpointStats.ckpt_segs_added,
-						CheckpointStats.ckpt_segs_removed,
-						CheckpointStats.ckpt_segs_recycled,
-						write_msecs / 1000, (int) (write_msecs % 1000),
-						sync_msecs / 1000, (int) (sync_msecs % 1000),
-						total_msecs / 1000, (int) (total_msecs % 1000),
-						CheckpointStats.ckpt_sync_rels,
-						longest_msecs / 1000, (int) (longest_msecs % 1000),
-						average_msecs / 1000, (int) (average_msecs % 1000),
-						(int) (PrevCheckPointDistance / 1024.0),
-						(int) (CheckPointDistanceEstimate / 1024.0))));
+	ereport(LOG,
+	/* translator: the placeholders after first %s show restartpoint/checkpoint stats */
+			(errmsg("%s complete: wrote %d buffers (%.1f%%); "
+					"%d WAL file(s) added, %d removed, %d recycled; "
+					"write=%ld.%03d s, sync=%ld.%03d s, total=%ld.%03d s; "
+					"sync files=%d, longest=%ld.%03d s, average=%ld.%03d s; "
+					"distance=%d kB, estimate=%d kB",
+					restartpoint ? _("restartpoint") : _("checkpoint"),
+					CheckpointStats.ckpt_bufs_written,
+					(double) CheckpointStats.ckpt_bufs_written * 100 / NBuffers,
+					CheckpointStats.ckpt_segs_added,
+					CheckpointStats.ckpt_segs_removed,
+					CheckpointStats.ckpt_segs_recycled,
+					write_msecs / 1000, (int) (write_msecs % 1000),
+					sync_msecs / 1000, (int) (sync_msecs % 1000),
+					total_msecs / 1000, (int) (total_msecs % 1000),
+					CheckpointStats.ckpt_sync_rels,
+					longest_msecs / 1000, (int) (longest_msecs % 1000),
+					average_msecs / 1000, (int) (average_msecs % 1000),
+					(int) (PrevCheckPointDistance / 1024.0),
+					(int) (CheckPointDistanceEstimate / 1024.0))));
 }
 
 /*
-- 
2.25.1

From 73dc4e9dded4f7b691bcb1e8171438ba5d7bb81a Mon Sep 17 00:00:00 2001
From: Bharath Rupireddy <bharath.rupireddyforpostgres@gmail.com>
Date: Thu, 24 Mar 2022 09:49:34 +0000
Subject: [PATCH v9] Add checkpoint stats of snapshot and mapping files of
 pg_logical dir

At times, there can be many snapshot and mapping files under
pg_logical dir that the checkpoint might have to delete/fsync
based on the cutoff LSN which can increase the checkpoint time.
Add stats related to these files to better understand the delays
or time spent by the checkpointer processing them.

Add these new log message only when necessary i.e. at least one
snapshot or mapping files is processed during the checkpoint.
---
 src/backend/access/heap/rewriteheap.c       |  4 +
 src/backend/access/transam/xlog.c           | 86 ++++++++++++++++-----
 src/backend/replication/logical/snapbuild.c |  2 +
 src/include/access/xlog.h                   | 11 +++
 4 files changed, 82 insertions(+), 21 deletions(-)

diff --git a/src/backend/access/heap/rewriteheap.c b/src/backend/access/heap/rewriteheap.c
index 2a53826736..696d04b5f0 100644
--- a/src/backend/access/heap/rewriteheap.c
+++ b/src/backend/access/heap/rewriteheap.c
@@ -1247,6 +1247,8 @@ CheckPointLogicalRewriteHeap(void)
 				ereport(ERROR,
 						(errcode_for_file_access(),
 						 errmsg("could not remove file \"%s\": %m", path)));
+
+			CheckpointStats.repl_map_files_rmvd_cnt++;
 		}
 		else
 		{
@@ -1280,6 +1282,8 @@ CheckPointLogicalRewriteHeap(void)
 						(errcode_for_file_access(),
 						 errmsg("could not close file \"%s\": %m", path)));
 		}
+
+		CheckpointStats.repl_map_files_syncd_cnt++;
 	}
 	FreeDir(mappings_dir);
 
diff --git a/src/backend/access/transam/xlog.c b/src/backend/access/transam/xlog.c
index 364f07bee9..a147f2d6fa 100644
--- a/src/backend/access/transam/xlog.c
+++ b/src/backend/access/transam/xlog.c
@@ -6082,6 +6082,7 @@ LogCheckpointEnd(bool restartpoint)
 				longest_msecs,
 				average_msecs;
 	uint64		average_sync_time;
+	StringInfoData logmsg;
 
 	CheckpointStats.ckpt_end_t = GetCurrentTimestamp();
 
@@ -6117,27 +6118,63 @@ LogCheckpointEnd(bool restartpoint)
 			CheckpointStats.ckpt_sync_rels;
 	average_msecs = (long) ((average_sync_time + 999) / 1000);
 
-	ereport(LOG,
-	/* translator: the placeholders after first %s show restartpoint/checkpoint stats */
-			(errmsg("%s complete: wrote %d buffers (%.1f%%); "
-					"%d WAL file(s) added, %d removed, %d recycled; "
-					"write=%ld.%03d s, sync=%ld.%03d s, total=%ld.%03d s; "
-					"sync files=%d, longest=%ld.%03d s, average=%ld.%03d s; "
-					"distance=%d kB, estimate=%d kB",
-					restartpoint ? _("restartpoint") : _("checkpoint"),
-					CheckpointStats.ckpt_bufs_written,
-					(double) CheckpointStats.ckpt_bufs_written * 100 / NBuffers,
-					CheckpointStats.ckpt_segs_added,
-					CheckpointStats.ckpt_segs_removed,
-					CheckpointStats.ckpt_segs_recycled,
-					write_msecs / 1000, (int) (write_msecs % 1000),
-					sync_msecs / 1000, (int) (sync_msecs % 1000),
-					total_msecs / 1000, (int) (total_msecs % 1000),
-					CheckpointStats.ckpt_sync_rels,
-					longest_msecs / 1000, (int) (longest_msecs % 1000),
-					average_msecs / 1000, (int) (average_msecs % 1000),
-					(int) (PrevCheckPointDistance / 1024.0),
-					(int) (CheckPointDistanceEstimate / 1024.0))));
+	initStringInfo(&logmsg);
+
+	if (restartpoint)
+		appendStringInfo(&logmsg, _("restartpoint complete: "));
+	else
+		appendStringInfo(&logmsg, _("checkpoint complete: "));
+
+	appendStringInfo(&logmsg,
+					_("wrote %d buffers (%.1f%%); "
+					  "%d WAL file(s) added, %d removed, %d recycled; "
+					  "write=%ld.%03d s, sync=%ld.%03d s, total=%ld.%03d s; "
+					  "sync files=%d, longest=%ld.%03d s, average=%ld.%03d s; "
+					  "distance=%d kB, estimate=%d kB"),
+					  CheckpointStats.ckpt_bufs_written,
+					  (double) CheckpointStats.ckpt_bufs_written * 100 / NBuffers,
+					  CheckpointStats.ckpt_segs_added,
+					  CheckpointStats.ckpt_segs_removed,
+					  CheckpointStats.ckpt_segs_recycled,
+					  write_msecs / 1000, (int) (write_msecs % 1000),
+					  sync_msecs / 1000, (int) (sync_msecs % 1000),
+					  total_msecs / 1000, (int) (total_msecs % 1000),
+					  CheckpointStats.ckpt_sync_rels,
+					  longest_msecs / 1000, (int) (longest_msecs % 1000),
+					  average_msecs / 1000, (int) (average_msecs % 1000),
+					  (int) (PrevCheckPointDistance / 1024.0),
+					  (int) (CheckPointDistanceEstimate / 1024.0));
+
+	if (CheckpointStats.repl_snap_files_rmvd_cnt > 0)
+	{
+		long t_msecs;
+
+		t_msecs = TimestampDifferenceMilliseconds(CheckpointStats.repl_snap_start_t,
+												  CheckpointStats.repl_snap_end_t);
+
+		appendStringInfo(&logmsg,
+						_("; logical snapshot file(s) removed=%llu, time=%ld.%03d s"),
+						  (unsigned long long) CheckpointStats.repl_snap_files_rmvd_cnt,
+						  t_msecs / 1000, (int) (t_msecs % 1000));
+	}
+
+	if (CheckpointStats.repl_map_files_rmvd_cnt ||
+		CheckpointStats.repl_map_files_syncd_cnt > 0)
+	{
+		long t_msecs;
+
+		t_msecs = TimestampDifferenceMilliseconds(CheckpointStats.repl_snap_start_t,
+												  CheckpointStats.repl_snap_end_t);
+
+		appendStringInfo(&logmsg,
+						_("; logical rewrite mapping file(s) removed=%llu, synced=%llu, time=%ld.%03d s"),
+						  (unsigned long long) CheckpointStats.repl_map_files_rmvd_cnt,
+						  (unsigned long long) CheckpointStats.repl_map_files_syncd_cnt,
+						  t_msecs / 1000, (int) (t_msecs % 1000));
+	}
+
+	ereport(LOG, errmsg_internal("%s", logmsg.data));
+	pfree(logmsg.data);
 }
 
 /*
@@ -6794,8 +6831,15 @@ CheckPointGuts(XLogRecPtr checkPointRedo, int flags)
 {
 	CheckPointRelationMap();
 	CheckPointReplicationSlots();
+
+	CheckpointStats.repl_snap_start_t = GetCurrentTimestamp();
 	CheckPointSnapBuild();
+	CheckpointStats.repl_snap_end_t = GetCurrentTimestamp();
+
+	CheckpointStats.repl_map_start_t = GetCurrentTimestamp();
 	CheckPointLogicalRewriteHeap();
+	CheckpointStats.repl_map_end_t = GetCurrentTimestamp();
+
 	CheckPointReplicationOrigin();
 
 	/* Write out all dirty data in SLRUs and the main buffer pool */
diff --git a/src/backend/replication/logical/snapbuild.c b/src/backend/replication/logical/snapbuild.c
index 83fca8a77d..2bfb367dc1 100644
--- a/src/backend/replication/logical/snapbuild.c
+++ b/src/backend/replication/logical/snapbuild.c
@@ -1997,6 +1997,8 @@ CheckPointSnapBuild(void)
 								path)));
 				continue;
 			}
+
+			CheckpointStats.repl_snap_files_rmvd_cnt++;
 		}
 	}
 	FreeDir(snap_dir);
diff --git a/src/include/access/xlog.h b/src/include/access/xlog.h
index 09f6464331..a615724b4e 100644
--- a/src/include/access/xlog.h
+++ b/src/include/access/xlog.h
@@ -172,6 +172,17 @@ typedef struct CheckpointStatsData
 									 * times, which is not necessarily the
 									 * same as the total elapsed time for the
 									 * entire sync phase. */
+
+	/* Statistics of snapshot files under "pg_logical/snapshots" */
+	uint64 repl_snap_files_rmvd_cnt;
+	TimestampTz	repl_snap_start_t;
+	TimestampTz	repl_snap_end_t;
+
+	/* Statistics of map files under "pg_logical/mappings" */
+	uint64 repl_map_files_syncd_cnt;
+	uint64 repl_map_files_rmvd_cnt;
+	TimestampTz	repl_map_start_t;
+	TimestampTz	repl_map_end_t;
 } CheckpointStatsData;
 
 extern CheckpointStatsData CheckpointStats;
-- 
2.25.1

From b113dfb9e876a84c2121b64ab94a9d10c3c670b4 Mon Sep 17 00:00:00 2001
From: Bharath Rupireddy <bharath.rupireddyforpostgres@gmail.com>
Date: Tue, 19 Jul 2022 10:35:29 +0000
Subject: [PATCH v10] Add time taken for processing logical decoding files to
 checkpoint log

At times, there can be many snapshot and mapping files under
pg_logical dir that the checkpoint might have to delete/fsync
based on the cutoff LSN which can increase the checkpoint time.
Add stats related to these files to better understand the delays
or time spent by the checkpointer processing them.

Also, add total number of WAL files processed during checkpoint to
the log message. This will be useful for debugging issues like
total time taken by checkpoint (if there are many WAL files) and
estimate the disk space occupied by pg_wal at the time of checkpoint.
---
 src/backend/access/transam/xlog.c | 30 +++++++++++++++++++++++-------
 src/include/access/xlog.h         |  5 +++++
 2 files changed, 28 insertions(+), 7 deletions(-)

diff --git a/src/backend/access/transam/xlog.c b/src/backend/access/transam/xlog.c
index b809a2152c..20c1689ed2 100644
--- a/src/backend/access/transam/xlog.c
+++ b/src/backend/access/transam/xlog.c
@@ -3603,6 +3603,8 @@ RemoveOldXlogFiles(XLogSegNo segno, XLogRecPtr lastredoptr, XLogRecPtr endptr,
 							   insertTLI);
 			}
 		}
+
+		CheckpointStats.ckpt_segs_processed++;
 	}
 
 	FreeDir(xldir);
@@ -6092,7 +6094,8 @@ LogCheckpointEnd(bool restartpoint)
 				sync_msecs,
 				total_msecs,
 				longest_msecs,
-				average_msecs;
+				average_msecs,
+				l_dec_ops_msecs;
 	uint64		average_sync_time;
 
 	CheckpointStats.ckpt_end_t = GetCurrentTimestamp();
@@ -6129,6 +6132,9 @@ LogCheckpointEnd(bool restartpoint)
 			CheckpointStats.ckpt_sync_rels;
 	average_msecs = (long) ((average_sync_time + 999) / 1000);
 
+	l_dec_ops_msecs = TimestampDifferenceMilliseconds(CheckpointStats.l_dec_ops_start_t,
+													  CheckpointStats.l_dec_ops_end_t);
+
 	/*
 	 * ControlFileLock is not required to see ControlFile->checkPoint and
 	 * ->checkPointCopy here as we are the only updator of those variables at
@@ -6137,16 +6143,18 @@ LogCheckpointEnd(bool restartpoint)
 	if (restartpoint)
 		ereport(LOG,
 				(errmsg("restartpoint complete: wrote %d buffers (%.1f%%); "
-						"%d WAL file(s) added, %d removed, %d recycled; "
+						"%d WAL file(s) added, %d removed, %d recycled, %d processed; "
 						"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/%X, redo lsn=%X/%X",
+						"lsn=%X/%X, redo lsn=%X/%X; "
+						"logical decoding file(s) processing=%ld.%03d s",
 						CheckpointStats.ckpt_bufs_written,
 						(double) CheckpointStats.ckpt_bufs_written * 100 / NBuffers,
 						CheckpointStats.ckpt_segs_added,
 						CheckpointStats.ckpt_segs_removed,
 						CheckpointStats.ckpt_segs_recycled,
+						CheckpointStats.ckpt_segs_processed,
 						write_msecs / 1000, (int) (write_msecs % 1000),
 						sync_msecs / 1000, (int) (sync_msecs % 1000),
 						total_msecs / 1000, (int) (total_msecs % 1000),
@@ -6156,20 +6164,23 @@ LogCheckpointEnd(bool restartpoint)
 						(int) (PrevCheckPointDistance / 1024.0),
 						(int) (CheckPointDistanceEstimate / 1024.0),
 						LSN_FORMAT_ARGS(ControlFile->checkPoint),
-						LSN_FORMAT_ARGS(ControlFile->checkPointCopy.redo))));
+						LSN_FORMAT_ARGS(ControlFile->checkPointCopy.redo),
+						l_dec_ops_msecs / 1000, (int) (l_dec_ops_msecs % 1000))));
 	else
 		ereport(LOG,
 				(errmsg("checkpoint complete: wrote %d buffers (%.1f%%); "
-						"%d WAL file(s) added, %d removed, %d recycled; "
+						"%d WAL file(s) added, %d removed, %d recycled, %d processed; "
 						"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/%X, redo lsn=%X/%X",
+						"lsn=%X/%X, redo lsn=%X/%X; "
+						"logical decoding file(s) processing=%ld.%03d s",
 						CheckpointStats.ckpt_bufs_written,
 						(double) CheckpointStats.ckpt_bufs_written * 100 / NBuffers,
 						CheckpointStats.ckpt_segs_added,
 						CheckpointStats.ckpt_segs_removed,
 						CheckpointStats.ckpt_segs_recycled,
+						CheckpointStats.ckpt_segs_processed,
 						write_msecs / 1000, (int) (write_msecs % 1000),
 						sync_msecs / 1000, (int) (sync_msecs % 1000),
 						total_msecs / 1000, (int) (total_msecs % 1000),
@@ -6179,7 +6190,8 @@ LogCheckpointEnd(bool restartpoint)
 						(int) (PrevCheckPointDistance / 1024.0),
 						(int) (CheckPointDistanceEstimate / 1024.0),
 						LSN_FORMAT_ARGS(ControlFile->checkPoint),
-						LSN_FORMAT_ARGS(ControlFile->checkPointCopy.redo))));
+						LSN_FORMAT_ARGS(ControlFile->checkPointCopy.redo),
+						l_dec_ops_msecs / 1000, (int) (l_dec_ops_msecs % 1000))));
 }
 
 /*
@@ -6848,8 +6860,12 @@ CheckPointGuts(XLogRecPtr checkPointRedo, int flags)
 {
 	CheckPointRelationMap();
 	CheckPointReplicationSlots();
+
+	CheckpointStats.l_dec_ops_start_t = GetCurrentTimestamp();
 	CheckPointSnapBuild();
 	CheckPointLogicalRewriteHeap();
+	CheckpointStats.l_dec_ops_end_t = GetCurrentTimestamp();
+
 	CheckPointReplicationOrigin();
 
 	/* Write out all dirty data in SLRUs and the main buffer pool */
diff --git a/src/include/access/xlog.h b/src/include/access/xlog.h
index cd674c3c23..75730254ed 100644
--- a/src/include/access/xlog.h
+++ b/src/include/access/xlog.h
@@ -166,6 +166,7 @@ typedef struct CheckpointStatsData
 	int			ckpt_segs_added;	/* # of new xlog segments created */
 	int			ckpt_segs_removed;	/* # of xlog segments deleted */
 	int			ckpt_segs_recycled; /* # of xlog segments recycled */
+	int			ckpt_segs_processed; /* # of xlog segments processed */
 
 	int			ckpt_sync_rels; /* # of relations synced */
 	uint64		ckpt_longest_sync;	/* Longest sync for one relation */
@@ -173,6 +174,10 @@ typedef struct CheckpointStatsData
 									 * times, which is not necessarily the
 									 * same as the total elapsed time for the
 									 * entire sync phase. */
+
+	/* start and end timestamps of logical decoding file processing */
+	TimestampTz	l_dec_ops_start_t;
+	TimestampTz	l_dec_ops_end_t;
 } CheckpointStatsData;
 
 extern PGDLLIMPORT CheckpointStatsData CheckpointStats;
-- 
2.25.1

From f5e0761835e863dd5b308756b262f897c99938b2 Mon Sep 17 00:00:00 2001
From: Bharath Rupireddy <bharath.rupireddyforpostgres@gmail.com>
Date: Wed, 17 Aug 2022 05:45:00 +0000
Subject: [PATCH v11] Add time taken for processing logical decoding files to
 checkpoint log

At times, there can be many snapshot and mapping files under
pg_logical dir that the checkpoint might have to delete/fsync
based on the cutoff LSN which can increase the checkpoint time.
Add stats related to these files to better understand the delays
or time spent by the checkpointer processing them.
---
 src/backend/access/transam/xlog.c | 22 +++++++++++++++++-----
 src/include/access/xlog.h         |  4 ++++
 2 files changed, 21 insertions(+), 5 deletions(-)

diff --git a/src/backend/access/transam/xlog.c b/src/backend/access/transam/xlog.c
index 9cedd6876f..251b73a4f0 100644
--- a/src/backend/access/transam/xlog.c
+++ b/src/backend/access/transam/xlog.c
@@ -6090,7 +6090,8 @@ LogCheckpointEnd(bool restartpoint)
 				sync_msecs,
 				total_msecs,
 				longest_msecs,
-				average_msecs;
+				average_msecs,
+				l_dec_ops_msecs;
 	uint64		average_sync_time;
 
 	CheckpointStats.ckpt_end_t = GetCurrentTimestamp();
@@ -6127,6 +6128,9 @@ LogCheckpointEnd(bool restartpoint)
 			CheckpointStats.ckpt_sync_rels;
 	average_msecs = (long) ((average_sync_time + 999) / 1000);
 
+	l_dec_ops_msecs = TimestampDifferenceMilliseconds(CheckpointStats.l_dec_ops_start_t,
+													  CheckpointStats.l_dec_ops_end_t);
+
 	/*
 	 * ControlFileLock is not required to see ControlFile->checkPoint and
 	 * ->checkPointCopy here as we are the only updator of those variables at
@@ -6139,7 +6143,8 @@ LogCheckpointEnd(bool restartpoint)
 						"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/%X, redo lsn=%X/%X",
+						"lsn=%X/%X, redo lsn=%X/%X; "
+						"logical decoding file(s) processing time=%ld.%03d s",
 						CheckpointStats.ckpt_bufs_written,
 						(double) CheckpointStats.ckpt_bufs_written * 100 / NBuffers,
 						CheckpointStats.ckpt_segs_added,
@@ -6154,7 +6159,8 @@ LogCheckpointEnd(bool restartpoint)
 						(int) (PrevCheckPointDistance / 1024.0),
 						(int) (CheckPointDistanceEstimate / 1024.0),
 						LSN_FORMAT_ARGS(ControlFile->checkPoint),
-						LSN_FORMAT_ARGS(ControlFile->checkPointCopy.redo))));
+						LSN_FORMAT_ARGS(ControlFile->checkPointCopy.redo),
+						l_dec_ops_msecs / 1000, (int) (l_dec_ops_msecs % 1000))));
 	else
 		ereport(LOG,
 				(errmsg("checkpoint complete: wrote %d buffers (%.1f%%); "
@@ -6162,7 +6168,8 @@ LogCheckpointEnd(bool restartpoint)
 						"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/%X, redo lsn=%X/%X",
+						"lsn=%X/%X, redo lsn=%X/%X; "
+						"logical decoding file(s) processing time=%ld.%03d s",
 						CheckpointStats.ckpt_bufs_written,
 						(double) CheckpointStats.ckpt_bufs_written * 100 / NBuffers,
 						CheckpointStats.ckpt_segs_added,
@@ -6177,7 +6184,8 @@ LogCheckpointEnd(bool restartpoint)
 						(int) (PrevCheckPointDistance / 1024.0),
 						(int) (CheckPointDistanceEstimate / 1024.0),
 						LSN_FORMAT_ARGS(ControlFile->checkPoint),
-						LSN_FORMAT_ARGS(ControlFile->checkPointCopy.redo))));
+						LSN_FORMAT_ARGS(ControlFile->checkPointCopy.redo),
+						l_dec_ops_msecs / 1000, (int) (l_dec_ops_msecs % 1000))));
 }
 
 /*
@@ -6846,8 +6854,12 @@ CheckPointGuts(XLogRecPtr checkPointRedo, int flags)
 {
 	CheckPointRelationMap();
 	CheckPointReplicationSlots();
+
+	CheckpointStats.l_dec_ops_start_t = GetCurrentTimestamp();
 	CheckPointSnapBuild();
 	CheckPointLogicalRewriteHeap();
+	CheckpointStats.l_dec_ops_end_t = GetCurrentTimestamp();
+
 	CheckPointReplicationOrigin();
 
 	/* Write out all dirty data in SLRUs and the main buffer pool */
diff --git a/src/include/access/xlog.h b/src/include/access/xlog.h
index cd674c3c23..c71aca8534 100644
--- a/src/include/access/xlog.h
+++ b/src/include/access/xlog.h
@@ -173,6 +173,10 @@ typedef struct CheckpointStatsData
 									 * times, which is not necessarily the
 									 * same as the total elapsed time for the
 									 * entire sync phase. */
+
+	/* start and end timestamps of logical decoding file processing */
+	TimestampTz	l_dec_ops_start_t;
+	TimestampTz	l_dec_ops_end_t;
 } CheckpointStatsData;
 
 extern PGDLLIMPORT CheckpointStatsData CheckpointStats;
-- 
2.34.1

From 917911eeaadb7e42548bf7f263ca1755791989d4 Mon Sep 17 00:00:00 2001
From: Bharath Rupireddy <bharath.rupireddyforpostgres@gmail.com>
Date: Thu, 25 Aug 2022 04:36:21 +0000
Subject: [PATCH v12] Add logical decoding processing time to checkpoint log

At times, logical decoding processing during checkpoint can
take a while, for instance, when there are many snapshot
and/or mapping files under pg_logical dir that the checkpoint
has to either delete or fsync based on the cutoff LSN. This
increases the total checkpoint duration and measuring the time
taken for these logical decoding processing alone will help in
understanding the delays.

Author: Bharath Rupireddy <bharath.rupireddyforpostgres@gmail.com>
Reviewed-by: Nathan Bossart <nathandbossart@gmail.com>, Cary Huang <cary.huang@highgo.ca>
Reviewed-by: Andres Freund <andres@anarazel.de>, Michael Paquier <michael@paquier.xyz>
Reviewed-by: Kyotaro Horiguchi <horikyota.ntt@gmail.com>
Discussion: https://www.postgresql.org/message-id/CALj2ACXwALpiPyqj8n-LLB8J_R_s9pE3xvuGJWjVEBngG6873Q%40mail.gmail.com
---
 src/backend/access/transam/xlog.c | 22 +++++++++++++++++-----
 src/include/access/xlog.h         |  4 ++++
 2 files changed, 21 insertions(+), 5 deletions(-)

diff --git a/src/backend/access/transam/xlog.c b/src/backend/access/transam/xlog.c
index 87b243e0d4..ebe21e67c2 100644
--- a/src/backend/access/transam/xlog.c
+++ b/src/backend/access/transam/xlog.c
@@ -6086,7 +6086,8 @@ LogCheckpointEnd(bool restartpoint)
 				sync_msecs,
 				total_msecs,
 				longest_msecs,
-				average_msecs;
+				average_msecs,
+				l_dec_ops_msecs;
 	uint64		average_sync_time;
 
 	CheckpointStats.ckpt_end_t = GetCurrentTimestamp();
@@ -6123,6 +6124,9 @@ LogCheckpointEnd(bool restartpoint)
 			CheckpointStats.ckpt_sync_rels;
 	average_msecs = (long) ((average_sync_time + 999) / 1000);
 
+	l_dec_ops_msecs = TimestampDifferenceMilliseconds(CheckpointStats.l_dec_ops_start_t,
+													  CheckpointStats.l_dec_ops_end_t);
+
 	/*
 	 * ControlFileLock is not required to see ControlFile->checkPoint and
 	 * ->checkPointCopy here as we are the only updator of those variables at
@@ -6135,7 +6139,8 @@ LogCheckpointEnd(bool restartpoint)
 						"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/%X, redo lsn=%X/%X",
+						"lsn=%X/%X, redo lsn=%X/%X; "
+						"logical decoding processing=%ld.%03d s",
 						CheckpointStats.ckpt_bufs_written,
 						(double) CheckpointStats.ckpt_bufs_written * 100 / NBuffers,
 						CheckpointStats.ckpt_segs_added,
@@ -6150,7 +6155,8 @@ LogCheckpointEnd(bool restartpoint)
 						(int) (PrevCheckPointDistance / 1024.0),
 						(int) (CheckPointDistanceEstimate / 1024.0),
 						LSN_FORMAT_ARGS(ControlFile->checkPoint),
-						LSN_FORMAT_ARGS(ControlFile->checkPointCopy.redo))));
+						LSN_FORMAT_ARGS(ControlFile->checkPointCopy.redo),
+						l_dec_ops_msecs / 1000, (int) (l_dec_ops_msecs % 1000))));
 	else
 		ereport(LOG,
 				(errmsg("checkpoint complete: wrote %d buffers (%.1f%%); "
@@ -6158,7 +6164,8 @@ LogCheckpointEnd(bool restartpoint)
 						"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/%X, redo lsn=%X/%X",
+						"lsn=%X/%X, redo lsn=%X/%X; "
+						"logical decoding processing=%ld.%03d s",
 						CheckpointStats.ckpt_bufs_written,
 						(double) CheckpointStats.ckpt_bufs_written * 100 / NBuffers,
 						CheckpointStats.ckpt_segs_added,
@@ -6173,7 +6180,8 @@ LogCheckpointEnd(bool restartpoint)
 						(int) (PrevCheckPointDistance / 1024.0),
 						(int) (CheckPointDistanceEstimate / 1024.0),
 						LSN_FORMAT_ARGS(ControlFile->checkPoint),
-						LSN_FORMAT_ARGS(ControlFile->checkPointCopy.redo))));
+						LSN_FORMAT_ARGS(ControlFile->checkPointCopy.redo),
+						l_dec_ops_msecs / 1000, (int) (l_dec_ops_msecs % 1000))));
 }
 
 /*
@@ -6842,9 +6850,13 @@ CheckPointGuts(XLogRecPtr checkPointRedo, int flags)
 {
 	CheckPointRelationMap();
 	CheckPointReplicationSlots();
+
+	/* Capture logical decoding processing time */
+	CheckpointStats.l_dec_ops_start_t = GetCurrentTimestamp();
 	CheckPointSnapBuild();
 	CheckPointLogicalRewriteHeap();
 	CheckPointReplicationOrigin();
+	CheckpointStats.l_dec_ops_end_t = GetCurrentTimestamp();
 
 	/* Write out all dirty data in SLRUs and the main buffer pool */
 	TRACE_POSTGRESQL_BUFFER_CHECKPOINT_START(flags);
diff --git a/src/include/access/xlog.h b/src/include/access/xlog.h
index cd674c3c23..c71aca8534 100644
--- a/src/include/access/xlog.h
+++ b/src/include/access/xlog.h
@@ -173,6 +173,10 @@ typedef struct CheckpointStatsData
 									 * times, which is not necessarily the
 									 * same as the total elapsed time for the
 									 * entire sync phase. */
+
+	/* start and end timestamps of logical decoding file processing */
+	TimestampTz	l_dec_ops_start_t;
+	TimestampTz	l_dec_ops_end_t;
 } CheckpointStatsData;
 
 extern PGDLLIMPORT CheckpointStatsData CheckpointStats;
-- 
2.34.1