From 568246ff3d2e77b9010a6bd48188bbf4ccdf8cff Mon Sep 17 00:00:00 2001 From: Peter Smith Date: Mon, 4 Jan 2021 19:30:35 +1100 Subject: [PATCH v10] Tablesync extra logging. This patch only adds some extra logging which may be helpful for testing, but is not for committing. --- src/backend/commands/subscriptioncmds.c | 6 ++++-- src/backend/replication/logical/tablesync.c | 20 +++++++++++++++----- 2 files changed, 19 insertions(+), 7 deletions(-) diff --git a/src/backend/commands/subscriptioncmds.c b/src/backend/commands/subscriptioncmds.c index f829e5e..6e05407 100644 --- a/src/backend/commands/subscriptioncmds.c +++ b/src/backend/commands/subscriptioncmds.c @@ -1105,8 +1105,9 @@ DropSubscription(DropSubscriptionStmt *stmt, bool isTopLevel) { PG_TRY(); { - elog(DEBUG1, "DropSubscription: dropping the tablesync slot \"%s\".", syncslotname); + elog(LOG, "!!>> DropSubscription: dropping the tablesync slot \"%s\".", syncslotname); ReplicationSlotDropAtPubNode(wrconn, syncslotname); + elog(LOG, "!!>> DropSubscription: dropped the tablesync slot \"%s\".", syncslotname); } PG_CATCH(); { @@ -1137,8 +1138,9 @@ DropSubscription(DropSubscriptionStmt *stmt, bool isTopLevel) originid = replorigin_by_name(originname, true); if (originid != InvalidRepOriginId) { - elog(DEBUG1, "DropSubscription: dropping origin tracking for \"%s\"", originname); + elog(LOG, "!!>> DropSubscription: dropping origin tracking for \"%s\"", originname); replorigin_drop(originid, false); + elog(LOG, "!!>> DropSubscription: dropped origin tracking for \"%s\"", originname); } } diff --git a/src/backend/replication/logical/tablesync.c b/src/backend/replication/logical/tablesync.c index 206b2de..7eec7d2 100644 --- a/src/backend/replication/logical/tablesync.c +++ b/src/backend/replication/logical/tablesync.c @@ -158,8 +158,9 @@ finish_sync_worker(void) PG_TRY(); { - elog(DEBUG1, "finish_sync_worker: dropping the tablesync slot \"%s\".", syncslotname); + elog(LOG, "!!>> finish_sync_worker: dropping the tablesync slot \"%s\".", syncslotname); ReplicationSlotDropAtPubNode(wrconn, syncslotname); + elog(LOG, "!!>> finish_sync_worker: dropped the tablesync slot \"%s\".", syncslotname); } PG_CATCH(); { @@ -469,10 +470,12 @@ process_syncing_tables_for_apply(XLogRecPtr current_lsn) snprintf(originname, sizeof(originname), "pg_%u_%u", MyLogicalRepWorker->subid, rstate->relid); originid = replorigin_by_name(originname, true); + elog(LOG, "!!>> apply worker: find tablesync origin tracking for \"%s\".", originname); if (OidIsValid(originid)) { - elog(DEBUG1, "process_syncing_tables_for_apply: dropping tablesync origin tracking for \"%s\".", originname); + elog(LOG, "!!>> apply worker: dropping tablesync origin tracking for \"%s\".", originname); replorigin_drop(originid, false); + elog(LOG, "!!>> apply worker: dropped tablesync origin tracking for \"%s\".", originname); } } @@ -966,7 +969,7 @@ LogicalRepSyncTableStart(XLogRecPtr *origin_startpos) * The COPY phase was previously done, but tablesync then crashed/etc * before it was able to finish normally. */ - elog(DEBUG1, "LogicalRepSyncTableStart: tablesync relstate was SUBREL_STATE_COPYDONE."); + elog(LOG, "!!>> LogicalRepSyncTableStart: tablesync relstate was SUBREL_STATE_COPYDONE."); StartTransactionCommand(); goto copy_table_done; } @@ -1014,6 +1017,7 @@ LogicalRepSyncTableStart(XLogRecPtr *origin_startpos) * for the catchup phase after COPY is done, so tell it to use the * snapshot to make the final data consistent. */ + elog(LOG, "!!>> LogicalRepSyncTableStart: walrcv_create_slot for \"%s\".", slotname); walrcv_create_slot(wrconn, slotname, false, CRS_USE_SNAPSHOT, origin_startpos); @@ -1042,8 +1046,9 @@ LogicalRepSyncTableStart(XLogRecPtr *origin_startpos) PG_CATCH(); { /* If something failed during copy table then cleanup the created slot. */ - elog(DEBUG1, "LogicalRepSyncTableStart: tablesync copy failed. Dropping the tablesync slot \"%s\".", slotname); + elog(LOG, "!!>> LogicalRepSyncTableStart: tablesync copy failed. Dropping the tablesync slot \"%s\".", slotname); ReplicationSlotDropAtPubNode(wrconn, slotname); + elog(LOG, "!!>> LogicalRepSyncTableStart: tablesync copy failed. Dropped the tablesync slot \"%s\".", slotname); pfree(slotname); slotname = NULL; @@ -1072,9 +1077,12 @@ copy_table_done: /* * Origin tracking does not exist. Create it now, and advance to LSN got from walrcv_create_slot. */ + elog(LOG, "!!>> LogicalRepSyncTableStart: 1 replorigin_create \"%s\".", originname); originid = replorigin_create(originname); + elog(LOG, "!!>> LogicalRepSyncTableStart: 1 replorigin_session_setup \"%s\".", originname); replorigin_session_setup(originid); replorigin_session_origin = originid; + elog(LOG, "!!>> LogicalRepSyncTableStart: 1 replorigin_advance \"%s\".", originname); replorigin_advance(originid, *origin_startpos, InvalidXLogRecPtr, true /* go backward */ , true /* WAL log */ ); } @@ -1083,12 +1091,14 @@ copy_table_done: /* * Origin tracking already exists. */ + elog(LOG, "!!>> LogicalRepSyncTableStart: 2 replorigin_session_setup \"%s\".", originname); replorigin_session_setup(originid); replorigin_session_origin = originid; + elog(LOG, "!!>> LogicalRepSyncTableStart: 2 replorigin_session_get_progress \"%s\".", originname); *origin_startpos = replorigin_session_get_progress(false); } - elog(DEBUG1, "LogicalRepSyncTableStart: '%s' origin_startpos lsn %X/%X", + elog(LOG, "!!>> LogicalRepSyncTableStart: '%s' origin_startpos lsn %X/%X", originname, (uint32) (*origin_startpos >> 32), (uint32) *origin_startpos); -- 1.8.3.1