From 1a1d1a18b999c45fd546332acec83690f1d39b6e Mon Sep 17 00:00:00 2001 From: Peter Smith Date: Fri, 29 Jan 2021 21:29:31 +1100 Subject: [PATCH v22] 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 | 16 +++++++++++ src/backend/replication/logical/tablesync.c | 44 +++++++++++++++++++++++++++-- 2 files changed, 58 insertions(+), 2 deletions(-) diff --git a/src/backend/commands/subscriptioncmds.c b/src/backend/commands/subscriptioncmds.c index b9ecf04..ed55934 100644 --- a/src/backend/commands/subscriptioncmds.c +++ b/src/backend/commands/subscriptioncmds.c @@ -684,12 +684,20 @@ AlterSubscription_refresh(Subscription *sub, bool copy_data) char syncslotname[NAMEDATALEN] = {0}; ReplicationSlotNameForTablesync(sub->oid, relid, syncslotname); + elog(LOG, + "!!>> AlterSubscription_refresh: dropping sync slot \"%s\"", + syncslotname); ReplicationSlotDropAtPubNode(wrconn, syncslotname, true /* missing_ok */ ); + elog(LOG, + "!!>> AlterSubscription_refresh: dropped sync slot \"%s\"", + syncslotname); } /* * Drop the tablesync's origin tracking if exists. */ + elog(LOG, + "!!>> AlterSubscription_refresh: call tablesync_replorigin_drop"); tablesync_replorigin_drop(sub->oid, relid, false /* nowait */ ); ereport(DEBUG1, @@ -1150,7 +1158,13 @@ DropSubscription(DropSubscriptionStmt *stmt, bool isTopLevel) ReplicationSlotNameForTablesync(subid, relid, syncslotname); if (wrconn) { + elog(LOG, + "!!>> DropSubscription: dropping sync slot \"%s\"", + syncslotname); ReplicationSlotDropAtPubNode(wrconn, syncslotname, true /* missing_ok */ ); + elog(LOG, + "!!>> DropSubscription: dropped sync slot \"%s\"", + syncslotname); } else { @@ -1181,6 +1195,8 @@ DropSubscription(DropSubscriptionStmt *stmt, bool isTopLevel) /* * Drop the tablesync's origin tracking if exists. */ + elog(LOG, + "!!>> DropSubscription: call tablesync_replorigin_drop"); tablesync_replorigin_drop(subid, relid, false /* nowait */ ); } list_free(rstates); diff --git a/src/backend/replication/logical/tablesync.c b/src/backend/replication/logical/tablesync.c index 165086a..9cc3cdf 100644 --- a/src/backend/replication/logical/tablesync.c +++ b/src/backend/replication/logical/tablesync.c @@ -145,7 +145,13 @@ tablesync_replorigin_drop(Oid subid, Oid relid, bool nowait) { PG_TRY(); { + elog(LOG, + "!!>> tablesync_replorigin_drop: droppping origin OID %d, named \"%s\"", + originid, originname); replorigin_drop(originid, nowait); + elog(LOG, + "!!>> tablesync_replorigin_drop: dropped origin OID %d, named \"%s\"", + originid, originname); } PG_CATCH(); { @@ -338,7 +344,13 @@ process_syncing_tables_for_sync(XLogRecPtr current_lsn) */ ReplicationSlotNameForTablesync(subid, relid, syncslotname); + elog(LOG, + "!!>> process_syncing_tables_for_sync: dropping the tablesync slot \"%s\".", + syncslotname); ReplicationSlotDropAtPubNode(wrconn, syncslotname, false /* missing_ok */ ); + elog(LOG, + "!!>> process_syncing_tables_for_sync: dropped the tablesync slot \"%s\".", + syncslotname); /* * Change state to SYNCDONE. @@ -492,6 +504,8 @@ process_syncing_tables_for_apply(XLogRecPtr current_lsn) * orign then would prevent the origin from advancing properly * on commit TX. */ + elog(LOG, + "!!>> process_syncing_tables_for_apply: call tablesync_replorigin_drop"); tablesync_replorigin_drop(MyLogicalRepWorker->subid, rstate->relid, false /* nowait */ ); @@ -999,6 +1013,8 @@ LogicalRepSyncTableStart(XLogRecPtr *origin_startpos) * The COPY phase was previously done, but tablesync then crashed * before it was able to finish normally. */ + elog(LOG, + "!!>> LogicalRepSyncTableStart: tablesync relstate was SUBREL_STATE_FINISHEDCOPY."); StartTransactionCommand(); /* @@ -1006,8 +1022,14 @@ LogicalRepSyncTableStart(XLogRecPtr *origin_startpos) * time this tablesync was launched. */ originid = replorigin_by_name(originname, false /* missing_ok */ ); + 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); CommitTransactionCommand(); @@ -1063,6 +1085,9 @@ LogicalRepSyncTableStart(XLogRecPtr *origin_startpos) * used 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 /* permanent */ , CRS_USE_SNAPSHOT, origin_startpos); @@ -1094,13 +1119,22 @@ LogicalRepSyncTableStart(XLogRecPtr *origin_startpos) * WAL logged for the purpose of recovery. Locks are to prevent * the replication origin from vanishing while advancing. */ + elog(LOG, + "!!>> LogicalRepSyncTableStart: 1 replorigin_create \"%s\".", + originname); originid = replorigin_create(originname); LockRelationOid(ReplicationOriginRelationId, RowExclusiveLock); + elog(LOG, + "!!>> LogicalRepSyncTableStart: 1 replorigin_advance \"%s\".", + originname); replorigin_advance(originid, *origin_startpos, InvalidXLogRecPtr, true /* go backward */ , true /* WAL log */ ); UnlockRelationOid(ReplicationOriginRelationId, RowExclusiveLock); + elog(LOG, + "!!>> LogicalRepSyncTableStart: 1 replorigin_session_setup \"%s\".", + originname); replorigin_session_setup(originid); replorigin_session_origin = originid; } @@ -1129,7 +1163,13 @@ LogicalRepSyncTableStart(XLogRecPtr *origin_startpos) * If something failed during copy table then cleanup the created * slot. */ + elog(LOG, + "!!>> LogicalRepSyncTableStart: tablesync copy failed. Dropping the tablesync slot \"%s\".", + slotname); ReplicationSlotDropAtPubNode(wrconn, slotname, false /* missing_ok */ ); + elog(LOG, + "!!>> LogicalRepSyncTableStart: tablesync copy failed. Dropped the tablesync slot \"%s\".", + slotname); pfree(slotname); slotname = NULL; @@ -1140,8 +1180,8 @@ LogicalRepSyncTableStart(XLogRecPtr *origin_startpos) copy_table_done: - 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