v62-0003-Fix-apply-worker-dev-logs.patch

From b13d2aed04ddf6d71b57ce87ecd3c98a9b0f66e8 Mon Sep 17 00:00:00 2001
From: Ajin Cherian <ajinc@fast.au.fujitsu.com>
Date: Thu, 18 Mar 2021 07:23:48 -0400
Subject: [PATCH v62] Fix apply worker (dev logs)

NOT TO BE COMMITTED.

This patch is only for adding some developer logging which may help for
debugging/testing the patch.
---
 src/backend/replication/logical/tablesync.c | 38 +++++++++++++++++++++++++++++
 1 file changed, 38 insertions(+)

diff --git a/src/backend/replication/logical/tablesync.c b/src/backend/replication/logical/tablesync.c
index f64a2fb..7505a90 100644
--- a/src/backend/replication/logical/tablesync.c
+++ b/src/backend/replication/logical/tablesync.c
@@ -407,6 +407,7 @@ process_syncing_tables_for_apply(XLogRecPtr current_lsn)
 	 */
 	if (MySubscription->twophasestate == LOGICALREP_TWOPHASE_STATE_PENDING)
 	{
+		elog(LOG, "!!> two_phase enable is still pending");
 		if (AllTablesyncsREADY())
 		{
 			ereport(LOG,
@@ -1155,6 +1156,8 @@ FetchTableStates(bool *started_tx)
 		ListCell   *lc;
 		SubscriptionRelState *rstate;
 
+		elog(LOG, "!!> FetchTableStates: Re-fetching the state list caches");
+
 		/* Clean the old lists. */
 		list_free_deep(table_states_not_ready);
 		table_states_not_ready = NIL;
@@ -1172,11 +1175,16 @@ FetchTableStates(bool *started_tx)
 			rstate = palloc(sizeof(SubscriptionRelState));
 			memcpy(rstate, lfirst(lc), sizeof(SubscriptionRelState));
 			table_states_not_ready = lappend(table_states_not_ready, rstate);
+			elog(LOG, "!!> FetchTableStates: table_states_not_ready - added Table relid %u with state '%c'", rstate->relid, rstate->state);
 		}
 		MemoryContextSwitchTo(oldctx);
 
 		table_states_valid = true;
 	}
+	else
+	{
+		elog(LOG, "!!> FetchTableStates: Already up-to-date");
+	}
 }
 
 /*
@@ -1190,6 +1198,8 @@ AllTablesyncsREADY(void)
 	int			count = 0;
 	ListCell   *lc;
 
+	elog(LOG, "!!> AllTablesyncsREADY");
+
 	/* We need up-to-date sync state info for subscription tables here. */
 	FetchTableStates(&started_tx);
 
@@ -1201,6 +1211,12 @@ AllTablesyncsREADY(void)
 		SubscriptionRelState *rstate = (SubscriptionRelState *) lfirst(lc);
 
 		count++;
+		elog(LOG,
+			 "!!> AllTablesyncsREADY: #%d. Table relid %u has state '%c'",
+			 count,
+			 rstate->relid,
+			 rstate->state);
+
 		/*
 		 * When the process_syncing_tables_for_apply changes the state from
 		 * SYNCDONE to READY, that change is actually written directly into
@@ -1212,6 +1228,7 @@ AllTablesyncsREADY(void)
 		 */
 		if (rstate->state != SUBREL_STATE_READY)
 		{
+			elog(LOG, "!!> AllTablesyncsREADY: Table relid %u is busy!", rstate->relid);
 			found_busy = true;
 			break;
 		}
@@ -1223,6 +1240,11 @@ AllTablesyncsREADY(void)
 		pgstat_report_stat(false);
 	}
 
+	elog(LOG,
+		 "!!> AllTablesyncsREADY: Scanned %d tables, and found busy = %s",
+		 count,
+		 found_busy ? "true" : "false");
+
 	/* When no tablesyncs are busy, then all are READY */
 	return !found_busy;
 }
@@ -1270,4 +1292,20 @@ UpdateTwoPhaseState(char new_state)
 	table_close(rel, RowExclusiveLock);
 
 	CommitTransactionCommand();
+
+#if 1
+	/* This is just debugging, for confirmation the update worked. */
+	{
+		Subscription *new_s;
+
+		StartTransactionCommand();
+		new_s = GetSubscription(MySubscription->oid, false);
+		elog(LOG,
+			 "!!> 2PC Tri-state for \"%s\": '%c' ==> '%c'",
+			 MySubscription->name,
+			 MySubscription->twophasestate,
+			 new_s->twophasestate);
+		CommitTransactionCommand();
+	}
+#endif
 }
-- 
1.8.3.1