From eb6c97f2120ba3ede48ff525e8e7239134814e11 Mon Sep 17 00:00:00 2001 From: Peter Smith Date: Tue, 24 Aug 2021 15:51:11 +1000 Subject: [PATCH v24] TEMP - extra logging for cache debugging. This patch just injects some extra logging into the code which is helpful to see what is going on for debugging the row filter caching. None of this patch is destined to be committed. --- src/backend/replication/pgoutput/pgoutput.c | 20 ++++++++++++++++++++ 1 file changed, 20 insertions(+) diff --git a/src/backend/replication/pgoutput/pgoutput.c b/src/backend/replication/pgoutput/pgoutput.c index 8d3a6b5..f2beaf0 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,11 +1617,13 @@ 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; } 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; } -- 1.8.3.1