From 7ce24a04e4b3df8ac3921bf41a45e97edeb3039b Mon Sep 17 00:00:00 2001 From: Peter Smith Date: Thu, 28 Jan 2021 17:08:04 +1100 Subject: [PATCH v21] Tablesync extra logging. This patch only adds some extra logging which may be helpful for testing, but is not for committing. --- src/backend/replication/logical/tablesync.c | 56 +++++++++++++++++++++++++++-- 1 file changed, 54 insertions(+), 2 deletions(-) diff --git a/src/backend/replication/logical/tablesync.c b/src/backend/replication/logical/tablesync.c index f8cf93e..26eae37 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_replorign_drop: droppping origin OID %d, named \"%s\"", + originid, originname); replorigin_drop(originid, nowait); + elog(LOG, + "!!>> tablesync_replorign_drop: dropped origin OID %d, named \"%s\"", + originid, originname); } PG_CATCH(); { @@ -317,6 +323,10 @@ tablesync_cleanup_at_shutdown(void) Oid subid = MySubscription->oid; Oid relid = MyLogicalRepWorker->relid; + elog(LOG, + "!!>> tablesync_cleanup_at_shutdown for relid = %d", + MyLogicalRepWorker->relid); + /* * Cleanup the tablesync slot, if needed. * @@ -349,7 +359,13 @@ tablesync_cleanup_at_shutdown(void) ReplicationSlotNameForTablesync(MySubscription->slotname, subid, relid, syncslotname); + elog(LOG, + "!!>> tablesync_cleanup_at_shutdown: dropping the tablesync slot \"%s\".", + syncslotname); ReplicationSlotDropAtPubNode(wrconn, syncslotname, true /* missing_ok */ ); + elog(LOG, + "!!>> tablesync_cleanup_at_shutdown: dropped the tablesync slot \"%s\".", + syncslotname); } /* @@ -363,6 +379,8 @@ tablesync_cleanup_at_shutdown(void) StartTransactionCommand(); } + elog(LOG, + "!!>> tablesync_cleanup_at_shutdown: call tablesync_replorigin_drop"); tablesync_replorigin_drop(subid, relid, false /* nowait */ ); /* @@ -409,7 +427,13 @@ process_syncing_tables_for_sync(XLogRecPtr current_lsn) */ ReplicationSlotNameForTablesync(MySubscription->slotname, 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. @@ -563,6 +587,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 */ ); @@ -1073,6 +1099,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(); /* @@ -1080,8 +1108,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(); @@ -1137,6 +1171,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); @@ -1168,13 +1205,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; } @@ -1203,7 +1249,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; @@ -1214,8 +1266,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