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

From 415ad469b751f64a42c214ee497d10a196bc5440 Mon Sep 17 00:00:00 2001
From: Ajin Cherian <ajinc@fast.au.fujitsu.com>
Date: Mon, 15 Mar 2021 08:32:45 -0400
Subject: [PATCH v60] 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 | 27 +++++++++++++++++++++++++++
 src/backend/replication/logical/worker.c    |  1 +
 2 files changed, 28 insertions(+)

diff --git a/src/backend/replication/logical/tablesync.c b/src/backend/replication/logical/tablesync.c
index d946b59..35d2637 100644
--- a/src/backend/replication/logical/tablesync.c
+++ b/src/backend/replication/logical/tablesync.c
@@ -409,6 +409,7 @@ process_syncing_tables_for_apply(XLogRecPtr current_lsn)
 	 */
 	if (MySubscription->twophase == LOGICALREP_TWOPHASE_STATE_PENDING)
 	{
+		elog(LOG, "!!> two_phase enable is still pending");
 		if (AllTablesyncsREADY())
 		{
 			ereport(LOG,
@@ -1150,6 +1151,7 @@ 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_all);
@@ -1173,6 +1175,7 @@ FetchTableStates(bool *started_tx)
 			rstate = palloc(sizeof(SubscriptionRelState));
 			memcpy(rstate, cur_rstate, sizeof(SubscriptionRelState));
 			table_states_all = lappend(table_states_all, rstate);
+			elog(LOG, "!!> FetchTableStates: table_states_all - added Table relid %u with state '%c'", rstate->relid, rstate->state);
 
 			/* List of only not-ready states */
 			if (cur_rstate->state != SUBREL_STATE_READY)
@@ -1180,12 +1183,17 @@ FetchTableStates(bool *started_tx)
 				rstate = palloc(sizeof(SubscriptionRelState));
 				memcpy(rstate, cur_rstate, 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");
+	}
 }
 
 /*
@@ -1208,6 +1216,8 @@ AnyTablesyncsNotREADY(void)
 	int			count = 0;
 	ListCell   *lc;
 
+	elog(LOG, "!!> AnyTablesyncsNotREADY");
+
 	/* We need up-to-date sync state info for subscription tables here. */
 	FetchTableStates(&started_tx);
 
@@ -1219,6 +1229,12 @@ AnyTablesyncsNotREADY(void)
 		SubscriptionRelState *rstate = (SubscriptionRelState *) lfirst(lc);
 
 		count++;
+		elog(LOG,
+			 "!!> AnyTablesyncsNotREADY: #%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
@@ -1230,6 +1246,7 @@ AnyTablesyncsNotREADY(void)
 		 */
 		if (rstate->state != SUBREL_STATE_READY)
 		{
+			elog(LOG, "!!> AnyTablesyncsNotREADY: Table relid %u is busy!", rstate->relid);
 			found_busy = true;
 			break;
 		}
@@ -1241,6 +1258,11 @@ AnyTablesyncsNotREADY(void)
 		pgstat_report_stat(false);
 	}
 
+	elog(LOG,
+		 "!!> AnyTablesyncsNotREADY: Scanned %d tables, and found busy = %s",
+		 count,
+		 found_busy ? "true" : "false");
+
 	return found_busy;
 }
 
@@ -1292,6 +1314,11 @@ UpdateTwoPhaseTriState(char new_tristate)
 
 		StartTransactionCommand();
 		new_s = GetSubscription(MySubscription->oid, false);
+		elog(LOG,
+			 "!!> 2PC Tri-state for \"%s\": '%c' ==> '%c'",
+			 MySubscription->name,
+			 MySubscription->twophase,
+			 new_s->twophase);
 		CommitTransactionCommand();
 	}
 #endif
diff --git a/src/backend/replication/logical/worker.c b/src/backend/replication/logical/worker.c
index f0e0b11..98ad27e 100644
--- a/src/backend/replication/logical/worker.c
+++ b/src/backend/replication/logical/worker.c
@@ -3203,6 +3203,7 @@ ApplyWorkerMain(Datum main_arg)
 						MyLogicalRepWorker->subid)));
 		proc_exit(0);
 	}
+	elog(LOG, "!!> MAIN: MySubscription twophase = '%c'", MySubscription->twophase);
 
 	MySubscriptionValid = true;
 	MemoryContextSwitchTo(oldctx);
-- 
1.8.3.1