From b755cab38ff76e9f63304b2d8f344cb098ca6a33 Mon Sep 17 00:00:00 2001 From: Hou Zhijie Date: Fri, 4 Aug 2023 17:57:29 +0800 Subject: [PATCH v1 1/2] count state change time --- src/backend/replication/logical/tablesync.c | 28 +++++++++++++++++++++ 1 file changed, 28 insertions(+) diff --git a/src/backend/replication/logical/tablesync.c b/src/backend/replication/logical/tablesync.c index 651a775065..0d9298f7b3 100644 --- a/src/backend/replication/logical/tablesync.c +++ b/src/backend/replication/logical/tablesync.c @@ -123,6 +123,10 @@ #include "utils/syscache.h" #include "utils/usercontext.h" +static TimestampTz start = 0; +static long secs = 0; +static int microsecs = 0; + static bool table_states_valid = false; static List *table_states_not_ready = NIL; static bool FetchTableStates(bool *started_tx); @@ -338,6 +342,11 @@ process_syncing_tables_for_sync(XLogRecPtr current_lsn) ReplicationSlotDropAtPubNode(LogRepWorkerWalRcvConn, syncslotname, false); CommitTransactionCommand(); + + TimestampDifference(start, GetCurrentTimestamp(), &secs, µsecs); + elog(LOG, "SUBREL_STATE_SYNCDONE %d", ((int) secs * 1000000 + microsecs)); + start = GetCurrentTimestamp(); + pgstat_report_stat(false); /* @@ -1258,6 +1267,8 @@ LogicalRepSyncTableStart(XLogRecPtr *origin_startpos) bool must_use_password; bool run_as_owner; + start = GetCurrentTimestamp(); + /* Check the state of the table synchronization. */ StartTransactionCommand(); relstate = GetSubscriptionRelState(MyLogicalRepWorker->subid, @@ -1361,6 +1372,10 @@ LogicalRepSyncTableStart(XLogRecPtr *origin_startpos) MyLogicalRepWorker->relstate_lsn = InvalidXLogRecPtr; SpinLockRelease(&MyLogicalRepWorker->relmutex); + TimestampDifference(start, GetCurrentTimestamp(), &secs, µsecs); + elog(LOG, "SUBREL_STATE_DATASYNC %d", ((int) secs * 1000000 + microsecs)); + start = GetCurrentTimestamp(); + /* Update the state and make it visible to others. */ StartTransactionCommand(); UpdateSubscriptionRelState(MyLogicalRepWorker->subid, @@ -1404,6 +1419,10 @@ LogicalRepSyncTableStart(XLogRecPtr *origin_startpos) slotname, false /* permanent */ , false /* two_phase */ , CRS_USE_SNAPSHOT, origin_startpos); + TimestampDifference(start, GetCurrentTimestamp(), &secs, µsecs); + elog(LOG, "WALRCV_CREATE_SLOT %d", ((int) secs * 1000000 + microsecs)); + start = GetCurrentTimestamp(); + /* * Setup replication origin tracking. The purpose of doing this before the * copy is to avoid doing the copy again due to any error in setting up @@ -1502,6 +1521,10 @@ LogicalRepSyncTableStart(XLogRecPtr *origin_startpos) CommitTransactionCommand(); + TimestampDifference(start, GetCurrentTimestamp(), &secs, µsecs); + elog(LOG, "SUBREL_STATE_FINISHEDCOPY %d", ((int) secs * 1000000 + microsecs)); + start = GetCurrentTimestamp(); + copy_table_done: elog(DEBUG1, @@ -1521,6 +1544,11 @@ copy_table_done: * then return to let LogicalRepApplyLoop do it. */ wait_for_worker_state_change(SUBREL_STATE_CATCHUP); + + TimestampDifference(start, GetCurrentTimestamp(), &secs, µsecs); + elog(LOG, "SUBREL_STATE_CATCHUP %d", ((int) secs * 1000000 + microsecs)); + start = GetCurrentTimestamp(); + return slotname; } -- 2.34.1