On Thu, Mar 17, 2022 at 12:12 AM Nathan Bossart <nathandboss...@gmail.com> wrote: > > On Wed, Mar 16, 2022 at 03:02:41PM +0530, Bharath Rupireddy wrote: > > On Mon, Mar 14, 2022 at 10:34 PM Nathan Bossart > > <nathandboss...@gmail.com> wrote: > >> I'm -1 on splitting these new statistics to separate LOGs. In addition to > >> making it more difficult to discover statistics for a given checkpoint, I > >> think it actually adds even more bloat to the server log. If we are > >> concerned about the amount of information in these LOGs, perhaps we should > >> adjust the format to make it more human-readable. > > > > Below are the ways that I can think of. Thoughts? > > I think I prefer the first option. If these tasks don't do anything, we > leave the stats out of the message. If they do some work, we add them.
Thanks Nathan.
> Below are the ways that I can think of. Thoughts?
>
> 1)
> if (restartpoint)
> {
> if (snap_files_rmvd > 0 && map_files_rmvd > 0)
> existing "restartpoint complete" message + "snapshot files
> removed cnt, time, cutoff lsn" + "mapping files removed cnt, time,
> cutoff lsn"
> else if (snap_files_rmvd > 0)
> existing "restartpoint complete" message + "snapshot files
> removed cnt, time, cutoff lsn"
> else if (map_files_rmvd > 0)
> existing "restartpoint complete" message + "mapping files removed
> cnt, time, cutoff lsn"
> else
> existing "restartpoint complete" message
> }
> else
> {
> same as above but with "checkpoint complete" instead of "restart complete"
> }
>
> 2) Use StringInfoData to prepare the message dynamically but this will
> create message translation problems.
>
> 3) Emit the "snapshot files removed cnt, time, cutoff lsn" and
> "mapping files removed cnt, time, cutoff lsn" at LOG level if
> (log_checkpoints) in CheckPointSnapBuild and
> CheckPointLogicalRewriteHeap respectively.
>
> 4) Have separate log messages in LogCheckpointEnd:
> if (snap_files_rmvd > 0)
> "snapshot files removed cnt, time, cutoff lsn"
> if (map_files_rmvd > 0)
> "mapping files removed cnt, time, cutoff lsn"
>
> if (restartpoint)
> existing "restartpoint complete" message
> else
> existing "checkpoint complete" message
FWIW, I'm attaching patches as follows:
v4-0001...patch implements option (4)
v4-0002...txt implements option (3)
v4-0003...txt implements option (1)
Personally, I tend to agree with v4-0001 (option (4)) or v4-0002
(option (3)) than v4-0003 (option (1)) as it adds more unreadability
with most of the code duplicated creating more diff with previous
versions and maintainability problems. Having said that, I will leave
it to the committer to decide on that.
Regards,
Bharath Rupireddy.
From caa4ab307a2daaf6cc495aaea78d34dbd66faa2f Mon Sep 17 00:00:00 2001
From: Bharath Rupireddy <bharath.rupireddyforpostg...@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
v4-0001-Add-checkpoint-stats-of-snapshot-and-mapping-fil.patch
Description: Binary data
From f4170e961cb9dbb2fe135f71645d163a3d2a9ef1 Mon Sep 17 00:00:00 2001
From: Bharath Rupireddy <bharath.rupireddyforpostg...@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
