From 66711b4fe91fd96e413ed6650c819fdd12aceca4 Mon Sep 17 00:00:00 2001 From: Bharath Rupireddy Date: Fri, 29 Oct 2021 18:52:09 +0000 Subject: [PATCH v1] add checkpoint stats of snapshot and mapping files of pg_logical dir --- src/backend/access/heap/rewriteheap.c | 5 +++ src/backend/access/transam/xlog.c | 45 ++++++++++++++++++--- src/backend/replication/logical/snapbuild.c | 5 +++ src/include/access/xlog.h | 14 +++++++ 4 files changed, 64 insertions(+), 5 deletions(-) diff --git a/src/backend/access/heap/rewriteheap.c b/src/backend/access/heap/rewriteheap.c index 986a776bbd..863e9e3deb 100644 --- a/src/backend/access/heap/rewriteheap.c +++ b/src/backend/access/heap/rewriteheap.c @@ -1280,6 +1280,11 @@ CheckPointLogicalRewriteHeap(void) (errcode_for_file_access(), errmsg("could not close file \"%s\": %m", path))); } + + CheckpointStats.repl_map_files_cnt++; + CheckpointStats.repl_map_files_sz += statbuf.st_size; } + + CheckpointStats.repl_map_cutoff_lsn = cutoff; FreeDir(mappings_dir); } diff --git a/src/backend/access/transam/xlog.c b/src/backend/access/transam/xlog.c index f547efd294..da96097464 100644 --- a/src/backend/access/transam/xlog.c +++ b/src/backend/access/transam/xlog.c @@ -8844,7 +8844,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(); @@ -8881,13 +8883,21 @@ LogCheckpointEnd(bool restartpoint) CheckpointStats.ckpt_sync_rels; average_msecs = (long) ((average_sync_time + 999) / 1000); + 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%%); " "%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/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, @@ -8900,14 +8910,24 @@ 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_cnt, + CheckpointStats.repl_snap_files_sz, + repl_snap_msecs / 1000, (int) (repl_snap_msecs % 1000), + LSN_FORMAT_ARGS(CheckpointStats.repl_snap_cutoff_lsn), + CheckpointStats.repl_map_files_cnt, + CheckpointStats.repl_map_files_sz, + repl_map_msecs / 1000, (int) (repl_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", + "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/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, @@ -8920,7 +8940,15 @@ 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_cnt, + CheckpointStats.repl_snap_files_sz, + repl_snap_msecs / 1000, (int) (repl_snap_msecs % 1000), + LSN_FORMAT_ARGS(CheckpointStats.repl_snap_cutoff_lsn), + CheckpointStats.repl_map_files_cnt, + CheckpointStats.repl_map_files_sz, + repl_map_msecs / 1000, (int) (repl_map_msecs % 1000), + LSN_FORMAT_ARGS(CheckpointStats.repl_map_cutoff_lsn)))); } /* @@ -9546,8 +9574,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 dbdc172a2b..ecdef8f712 100644 --- a/src/backend/replication/logical/snapbuild.c +++ b/src/backend/replication/logical/snapbuild.c @@ -1997,7 +1997,12 @@ CheckPointSnapBuild(void) path))); continue; } + + CheckpointStats.repl_snap_files_cnt++; + CheckpointStats.repl_snap_files_sz += statbuf.st_size; } } + + CheckpointStats.repl_snap_cutoff_lsn = cutoff; FreeDir(snap_dir); } diff --git a/src/include/access/xlog.h b/src/include/access/xlog.h index 5e2c94a05f..29aeb88cf3 100644 --- a/src/include/access/xlog.h +++ b/src/include/access/xlog.h @@ -236,6 +236,20 @@ 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_sz; + uint64 repl_snap_files_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_sz; + uint64 repl_map_files_cnt; + XLogRecPtr repl_map_cutoff_lsn; + TimestampTz repl_map_start_t; + TimestampTz repl_map_end_t; } CheckpointStatsData; extern CheckpointStatsData CheckpointStats; -- 2.25.1