Logical replication CPU-bound with TRUNCATE/DROP/CREATE many tables

Hi hackers,

I found a problem in logical replication.
It seems to have the same cause as the following problem.

Creating many tables gets logical replication stuck
https://www.postgresql.org/message-id/flat/20f3de7675f83176253f607b5e199b228406c21c.camel%40cybertec.at

Logical decoding CPU-bound w/ large number of tables
https://www.postgresql.org/message-id/flat/CAHoiPjzea6N0zuCi%3D%2Bf9v_j94nfsy6y8SU7-%3Dbp4%3D7qw6_i%3DRg%40mail.gmail.com

# problem

* logical replication enabled
* walsender process has RelfilenodeMap cache(2000 relations in this case)
* TRUNCATE or DROP or CREATE many tables in same transaction

At this time, walsender process continues to use 100% of the CPU 1core.

# environment

PostgreSQL 12.4(rpm)
CentOS 7.6.1810

# test case

sh logical_replication_truncate.sh

# perf report walsender process

Samples: 25K of event 'cpu-clock:uhH', Event count (approx.): 6315250000
Overhead Command Shared Object Symbol
87.34% postgres postgres [.] hash_seq_search
2.80% postgres postgres [.] hash_search_with_hash_value
1.57% postgres postgres [.] LocalExecuteInvalidationMessage
1.50% postgres postgres [.] hash_search
1.31% postgres postgres [.] RelfilenodeMapInvalidateCallback
0.83% postgres postgres [.] uint32_hash
0.79% postgres pgoutput.so [.] rel_sync_cache_relation_cb
0.63% postgres postgres [.] hash_uint32
0.59% postgres postgres [.] PlanCacheRelCallback
0.48% postgres postgres [.] CatCacheInvalidate
0.43% postgres postgres [.] ReorderBufferCommit
0.36% postgres libc-2.17.so [.] __memcmp_sse4_1
0.34% postgres postgres [.] deregister_seq_scan
0.27% postgres postgres [.] hash_seq_init
0.27% postgres postgres [.] CallSyscacheCallbacks
0.23% postgres postgres [.] SysCacheInvalidate
0.10% postgres postgres [.] memcmp(at)plt
0.08% postgres postgres [.] RelationCacheInvalidateEntry
0.05% postgres postgres [.] InvalidateCatalogSnapshot
0.03% postgres postgres [.] GetCurrentTransactionNestLevel
0.01% postgres pgoutput.so [.] hash_search(at)plt
0.00% postgres libpthread-2.17.so [.] __pread_nocancel

# backtrace walsender process

0x0000000000889cb4 in hash_seq_search
(status=status(at)entry=0x7ffd5ae38310) at dynahash.c:1442
#0 0x0000000000889cb4 in hash_seq_search
(status=status(at)entry=0x7ffd5ae38310) at dynahash.c:1442
#1 0x0000000000877df8 in RelfilenodeMapInvalidateCallback
(arg=<optimized out>, relid=17284) at relfilenodemap.c:64
#2 0x000000000086999a in LocalExecuteInvalidationMessage
(msg=0x2f2ef18) at inval.c:595
#3 0x000000000070b81e in ReorderBufferExecuteInvalidations
(rb=<optimized out>, txn=<optimized out>, txn=<optimized out>) at
reorderbuffer.c:2149
#4 ReorderBufferCommit (rb=0x2cbda90, xid=xid(at)entry=490,
commit_lsn=94490944, end_lsn=<optimized out>,
commit_time=commit_time(at)entry=653705313747147,
origin_id=origin_id(at)entry=0, origin_lsn=origin_lsn(at)entry=0) at
reorderbuffer.c:1770
#5 0x0000000000701248 in DecodeCommit (xid=490,
parsed=0x7ffd5ae38600, buf=0x7ffd5ae387c0, ctx=0x2c2f1e0) at
decode.c:640
#6 DecodeXactOp (ctx=0x2c2f1e0, buf=buf(at)entry=0x7ffd5ae387c0) at decode.c:248
#7 0x00000000007015fa in LogicalDecodingProcessRecord (ctx=0x2c2f1e0,
record=0x2c2f458) at decode.c:117
#8 0x0000000000712cd1 in XLogSendLogical () at walsender.c:2848
#9 0x0000000000714e92 in WalSndLoop
(send_data=send_data(at)entry=0x712c70 <XLogSendLogical>) at
walsender.c:2199
#10 0x0000000000715b51 in StartLogicalReplication (cmd=0x2c8c5c0) at
walsender.c:1129
#11 exec_replication_command (
cmd_string=cmd_string(at)entry=0x2c0af60 "START_REPLICATION SLOT
\"subdb_test\" LOGICAL 0/0 (proto_version '1', publication_names
'\"pubdb_test\"')") at walsender.c:1545
#12 0x0000000000760ff1 in PostgresMain (argc=<optimized out>,
argv=argv(at)entry=0x2c353d0, dbname=0x2c35288 "postgres",
username=<optimized out>)
at postgres.c:4243
#13 0x0000000000484172 in BackendRun (port=<optimized out>,
port=<optimized out>) at postmaster.c:4448
#14 BackendStartup (port=0x2c2d200) at postmaster.c:4139
#15 ServerLoop () at postmaster.c:1704
#16 0x00000000006f10b3 in PostmasterMain (argc=argc(at)entry=3,
argv=argv(at)entry=0x2c05b20) at postmaster.c:1377
#17 0x0000000000485073 in main (argc=3, argv=0x2c05b20) at main.c:228

# probable cause

RelfilenodeMapInvalidateCallback is called many times.

Every time the CommandId is incremented, execute all invalidations.
ReorderBufferExecuteInvalidations repeats the invalidation
of all TRUNCATE objects in same transaction by the number of objects.

hash_seq_search in RelfilenodeMapInvalidateCallback is heavy,
but I have no idea to solve this problem...

./src/backend/replication/logical/reorderbuffer.c
1746 case REORDER_BUFFER_CHANGE_INTERNAL_COMMAND_ID:
1747 Assert(change->data.command_id != InvalidCommandId);
1748
1749 if (command_id < change->data.command_id)
1750 {
1751 command_id = change->data.command_id;
1752
1753 if (!snapshot_now->copied)
1754 {
1755 /* we don't use the global one anymore */
1756 snapshot_now = ReorderBufferCopySnap(rb, snapshot_now,
1757 txn, command_id);
1758 }
1759
1760 snapshot_now->curcid = command_id;
1761
1762 TeardownHistoricSnapshot(false);
1763 SetupHistoricSnapshot(snapshot_now, txn->tuplecid_hash);
1764
1765 /*
1766 * Every time the CommandId is incremented, we could
1767 * see new catalog contents, so execute all
1768 * invalidations.
1769 */
1770 ReorderBufferExecuteInvalidations(rb, txn);
1771 }
1772
1773 break;

Do you have any solutions?

--
Keisuke Kuroda
NTT Software Innovation Center
keisuke(dot)kuroda(dot)3862(at)gmail(dot)com