From f4170e961cb9dbb2fe135f71645d163a3d2a9ef1 Mon Sep 17 00:00:00 2001 From: Bharath Rupireddy 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