From 917911eeaadb7e42548bf7f263ca1755791989d4 Mon Sep 17 00:00:00 2001 From: Bharath Rupireddy 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 Reviewed-by: Nathan Bossart , Cary Huang Reviewed-by: Andres Freund , Michael Paquier Reviewed-by: Kyotaro Horiguchi 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