From dbe57b35278772dc1faf10fa7a5cac66c3085807 Mon Sep 17 00:00:00 2001
From: Peter Smith <peter.b.smith@fujitsu.com>
Date: Thu, 26 Aug 2021 19:25:06 +1000
Subject: [PATCH v25] ExprState cache temp extra logging.

This patch just injects some extra logging into the code which is helpful
to see what is going on when debugging the row filter caching.

Temporary. Not to be committed.
---
 src/backend/replication/pgoutput/pgoutput.c | 22 ++++++++++++++++++++++
 1 file changed, 22 insertions(+)

diff --git a/src/backend/replication/pgoutput/pgoutput.c b/src/backend/replication/pgoutput/pgoutput.c
index bb6f608..de6d1e9 100644
--- a/src/backend/replication/pgoutput/pgoutput.c
+++ b/src/backend/replication/pgoutput/pgoutput.c
@@ -766,11 +766,15 @@ pgoutput_row_filter(Relation relation, HeapTuple oldtuple, HeapTuple newtuple, R
 	{
 		MemoryContext oldctx;
 
+		elog(LOG, "!!> pgoutput_row_filter: (re)build the ExprState cache for relid=%d", relid);
+
 		foreach(lc, entry->rfnode_list)
 		{
 			Node		*rfnode = (Node *) lfirst(lc);
 			ExprState	*exprstate;
 
+			elog(LOG, "!!> pgoutput_row_filter: build the ExprState on-the-fly");
+
 			oldctx = MemoryContextSwitchTo(CacheMemoryContext);
 			exprstate = pgoutput_row_filter_init_expr(rfnode);
 			entry->exprstate = lappend(entry->exprstate, exprstate);
@@ -789,6 +793,8 @@ pgoutput_row_filter(Relation relation, HeapTuple oldtuple, HeapTuple newtuple, R
 	{
 		ExprState  *exprstate = (ExprState *) lfirst(lc);
 
+		elog(LOG, "!!> pgoutput_row_filter: using cached ExprState for relid=%d", relid);
+
 		/* Evaluates row filter */
 		result = pgoutput_row_filter_exec_expr(exprstate, ecxt);
 
@@ -1255,6 +1261,8 @@ init_rel_sync_cache(MemoryContext cachectx)
 {
 	HASHCTL		ctl;
 
+	elog(LOG, "!!> HELLO init_rel_sync_cache");
+
 	if (RelationSyncCache != NULL)
 		return;
 
@@ -1329,6 +1337,8 @@ get_rel_sync_entry(PGOutputData *data, Relation relation)
 
 	Assert(RelationSyncCache != NULL);
 
+	elog(LOG, "!!> HELLO get_rel_sync_entry for relid=%d", relid);
+
 	/* Find cached relation info, creating if not found */
 	entry = (RelationSyncEntry *) hash_search(RelationSyncCache,
 											  (void *) &relid,
@@ -1482,6 +1492,7 @@ get_rel_sync_entry(PGOutputData *data, Relation relation)
 						rfnode = stringToNode(TextDatumGetCString(rfdatum));
 						entry->rfnode_list = lappend(entry->rfnode_list, rfnode);
 						MemoryContextSwitchTo(oldctx);
+						elog(LOG, "!!> get_rel_sync_entry: caching the rfnode_list for relid=%d", relid);
 					}
 
 					ReleaseSysCache(rftuple);
@@ -1516,6 +1527,8 @@ cleanup_rel_sync_cache(TransactionId xid, bool is_commit)
 	RelationSyncEntry *entry;
 	ListCell   *lc;
 
+	elog(LOG, "!!> HELLO cleanup_rel_sync_cache");
+
 	Assert(RelationSyncCache != NULL);
 
 	hash_seq_init(&hash_seq, RelationSyncCache);
@@ -1550,6 +1563,8 @@ rel_sync_cache_relation_cb(Datum arg, Oid relid)
 {
 	RelationSyncEntry *entry;
 
+	elog(LOG, "!!> HELLO rel_sync_cache_relation_cb relid=%d", relid);
+
 	/*
 	 * We can get here if the plugin was used in SQL interface as the
 	 * RelSchemaSyncCache is destroyed when the decoding finishes, but there
@@ -1579,6 +1594,9 @@ rel_sync_cache_relation_cb(Datum arg, Oid relid)
 	 */
 	if (entry != NULL)
 	{
+		elog(LOG, "!!> rel_sync_cache_relation_cb: rfnode_list %s", entry->rfnode_list == NIL ? "NIL" : "not NIL");
+		elog(LOG, "!!> rel_sync_cache_relation_cb: exprstate %s", entry->exprstate == NIL ? "NIL" : "not NIL");
+
 		entry->schema_sent = false;
 		list_free(entry->streamed_txns);
 		entry->streamed_txns = NIL;
@@ -1599,12 +1617,14 @@ rel_sync_cache_relation_cb(Datum arg, Oid relid)
 		 */
 		if (entry->rfnode_list != NIL)
 		{
+			elog(LOG, "!!> rel_sync_cache_relation_cb: cleanup rfnode_list cache for relid=%d", relid);
 			list_free_deep(entry->rfnode_list);
 			entry->rfnode_list = NIL;
 			entry->replicate_valid = false; /* Clear flag so get_rel_syn_entry with rebuild cache. */
 		}
 		if (entry->exprstate != NIL)
 		{
+			elog(LOG, "!!> rel_sync_cache_relation_cb: cleanup ExprState cache for relid=%d", relid);
 			list_free_deep(entry->exprstate);
 			entry->exprstate = NIL;
 		}
@@ -1621,6 +1641,8 @@ rel_sync_cache_publication_cb(Datum arg, int cacheid, uint32 hashvalue)
 	RelationSyncEntry *entry;
 	MemoryContext oldctx;
 
+	elog(LOG, "!!> HELLO rel_sync_cache_publication_cb");
+
 	/*
 	 * We can get here if the plugin was used in SQL interface as the
 	 * RelSchemaSyncCache is destroyed when the decoding finishes, but there
-- 
1.8.3.1