From 22f471614e150c0a07833592ae39f3ed73429b03 Mon Sep 17 00:00:00 2001 From: Peter Smith Date: Sat, 23 Jan 2021 10:13:54 +1100 Subject: [PATCH v18] 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 | 10 ++++++---- src/backend/replication/logical/tablesync.c | 31 +++++++++++++++++++++++++++-- 2 files changed, 35 insertions(+), 6 deletions(-) diff --git a/src/backend/commands/subscriptioncmds.c b/src/backend/commands/subscriptioncmds.c index 58f8a86..352c3bf 100644 --- a/src/backend/commands/subscriptioncmds.c +++ b/src/backend/commands/subscriptioncmds.c @@ -661,12 +661,13 @@ AlterSubscription_refresh(Subscription *sub, bool copy_data) originid = replorigin_by_name(originname, true); if (originid != InvalidRepOriginId) { - elog(DEBUG1, "AlterSubscription_refresh: dropping origin tracking for \"%s\"", originname); + elog(LOG, "!!>> AlterSubscription_refresh: dropping origin tracking for \"%s\"", originname); replorigin_drop(originid, false /* nowait */ ); + elog(LOG, "!!>> AlterSubscription_refresh: dropped origin tracking for \"%s\"", originname); } - ereport(DEBUG1, - (errmsg("table \"%s.%s\" removed from subscription \"%s\"", + ereport(LOG, + (errmsg("!!>> table \"%s.%s\" removed from subscription \"%s\"", get_namespace_name(get_rel_namespace(relid)), get_rel_name(relid), sub->name))); @@ -1075,8 +1076,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 /* nowait */ ); + elog(LOG, "!!>> DropSubscription: droppped origin tracking for \"%s\"", originname); } } list_free(rstates); diff --git a/src/backend/replication/logical/tablesync.c b/src/backend/replication/logical/tablesync.c index 1f828fc..b531516 100644 --- a/src/backend/replication/logical/tablesync.c +++ b/src/backend/replication/logical/tablesync.c @@ -449,10 +449,13 @@ process_syncing_tables_for_apply(XLogRecPtr current_lsn) originid = replorigin_by_name(originname, true); if (OidIsValid(originid)) { - elog(DEBUG1, - "process_syncing_tables_for_apply: dropping tablesync origin tracking for \"%s\".", + elog(LOG, + "!!>> process_syncing_tables_for_apply: dropping tablesync origin tracking for \"%s\".", originname); replorigin_drop(originid, false /* nowait */ ); + elog(LOG, + "!!>> process_syncing_tables_for_apply: dropped tablesync origin tracking for \"%s\".", + originname); } /* @@ -941,12 +944,17 @@ 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(); /* * Slot creation passes NULL lsn because the origin startpos is got * from origin tracking this time, not from the slot. */ + elog(LOG, + "!!>> LogicalRepSyncTableStart: 2 walrcv_create_slot for \"%s\".", + slotname); walrcv_create_slot(wrconn, slotname, true /* temporary */ , CRS_NOEXPORT_SNAPSHOT, NULL /* lsn */ ); @@ -955,8 +963,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); goto copy_table_done; @@ -1005,6 +1019,9 @@ 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: 1 walrcv_create_slot for \"%s\".", + slotname); walrcv_create_slot(wrconn, slotname, true, CRS_USE_SNAPSHOT, origin_startpos); @@ -1036,13 +1053,23 @@ LogicalRepSyncTableStart(XLogRecPtr *origin_startpos) * logged for for the purpose of recovery. Locks are to prevent the * replication origin from vanishing while advancing. */ + LockRelationOid(ReplicationOriginRelationId, RowExclusiveLock); + 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; } -- 1.8.3.1