From cf26b61bb26e994cac16f9b2e033d9a2a12cae53 Mon Sep 17 00:00:00 2001 From: Peter Smith Date: Mon, 30 Aug 2021 11:59:00 +1000 Subject: [PATCH v26] 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 | 19 +++++++++++++++++++ 1 file changed, 19 insertions(+) diff --git a/src/backend/replication/pgoutput/pgoutput.c b/src/backend/replication/pgoutput/pgoutput.c index ce5e1c5..d89dcb0 100644 --- a/src/backend/replication/pgoutput/pgoutput.c +++ b/src/backend/replication/pgoutput/pgoutput.c @@ -759,6 +759,8 @@ pgoutput_row_filter(PGOutputData *data, Relation relation, HeapTuple oldtuple, H MemoryContext oldctx; TupleDesc tupdesc = RelationGetDescr(relation); + elog(LOG, "!!> pgoutput_row_filter: Look for row filters of relid=%d", relid); + /* * Create a tuple table slot for row filter. TupleDesc must live as * long as the cache remains. Release the tuple table slot if it @@ -832,11 +834,13 @@ pgoutput_row_filter(PGOutputData *data, Relation relation, HeapTuple oldtuple, H Node *rfnode; ExprState *exprstate; + elog(LOG, "!!> pgoutput_row_filter: (re)build the ExprState cache for relid=%d", pub_relid); oldctx = MemoryContextSwitchTo(CacheMemoryContext); rfnode = stringToNode(TextDatumGetCString(rfdatum)); exprstate = pgoutput_row_filter_init_expr(rfnode); entry->exprstate_list = lappend(entry->exprstate_list, exprstate); MemoryContextSwitchTo(oldctx); + elog(LOG, "!!> pgoutput_row_filter: build the ExprState on-the-fly"); } ReleaseSysCache(rftuple); @@ -874,6 +878,8 @@ pgoutput_row_filter(PGOutputData *data, Relation relation, HeapTuple oldtuple, H { 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); @@ -1340,6 +1346,8 @@ init_rel_sync_cache(MemoryContext cachectx) { HASHCTL ctl; + elog(LOG, "!!> HELLO init_rel_sync_cache"); + if (RelationSyncCache != NULL) return; @@ -1414,6 +1422,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, @@ -1553,6 +1563,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); @@ -1587,6 +1599,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 @@ -1616,6 +1630,8 @@ rel_sync_cache_relation_cb(Datum arg, Oid relid) */ if (entry != NULL) { + elog(LOG, "!!> rel_sync_cache_relation_cb: exprstate_list %s", entry->exprstate_list == NIL ? "NIL" : "not NIL"); + entry->schema_sent = false; list_free(entry->streamed_txns); entry->streamed_txns = NIL; @@ -1642,6 +1658,7 @@ rel_sync_cache_relation_cb(Datum arg, Oid relid) } if (entry->exprstate_list != NIL) { + elog(LOG, "!!> rel_sync_cache_relation_cb: cleanup ExprState cache for relid=%d", relid); list_free_deep(entry->exprstate_list); entry->exprstate_list = NIL; } @@ -1658,6 +1675,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