Excessive LOG messages from replication slot sync worker - Mailing list pgsql-hackers

From Fujii Masao
Subject Excessive LOG messages from replication slot sync worker
Date
Msg-id CAHGQGwHuHPB-ucAk_Tq3uSs4Fdziu1Jp_AA_RD3m5Ycky7m48w@mail.gmail.com
Whole thread Raw
Responses Re: Excessive LOG messages from replication slot sync worker
List pgsql-hackers
Hi,

While testing the replication slot synchronization feature, I set up
three instances on the same machine:

- Physical replication primary (also Logical replication publisher)
- Physical replication standby
- Logical replication subscriber

----------------------------------------
initdb -D pri --encoding=UTF8 --locale=C
cat <<EOF >> pri/postgresql.conf
wal_level = logical
log_line_prefix = '%m [pri][%b] '
logging_collector = on
EOF
pg_ctl -D pri start
pgbench -i
cat <<EOF | psql
CREATE PUBLICATION mypub FOR ALL TABLES;
SELECT pg_create_physical_replication_slot('pslot');
EOF
cat <<EOF >> pri/postgresql.conf
synchronized_standby_slots = 'pslot'
EOF
pg_ctl -D pri reload

pg_basebackup -D sby -c fast
touch sby/standby.signal
cat <<EOF >> sby/postgresql.conf
port = 5433
primary_conninfo = 'host=localhost port=5432 dbname=postgres'
primary_slot_name = 'pslot'
sync_replication_slots = on
hot_standby_feedback = on
log_line_prefix = '%m [sby][%b] '
EOF
pg_ctl -D sby start

initdb -D sub --encoding=UTF8 --locale=C
cat <<EOF >> sub/postgresql.conf
port = 5434
wal_level = logical
log_line_prefix = '%m [sub][%b] '
logging_collector = on
EOF
pg_ctl -D sub start
pgbench -i -Itp -p 5434
cat <<EOF | psql -p 5434
CREATE SUBSCRIPTION mysub CONNECTION 'host=localhost port=5432
dbname=postgres' PUBLICATION mypub WITH (failover);
EOF
----------------------------------------


I noticed that the replication slot sync worker on the standby generates
a large number of LOG messages, about two per 200–300 ms, during
pgbench runs (pgbench -c 10 -j 10 -T 60). For example,

----------------------------------------
2025-08-12 11:48:21.067 JST [sby][slotsync worker] LOG:  starting
logical decoding for slot "mysub"
2025-08-12 11:48:21.067 JST [sby][slotsync worker] DETAIL:  Streaming
transactions committing after 0/04F317B8, reading WAL from 0/04006FC0.
2025-08-12 11:48:21.067 JST [sby][slotsync worker] LOG:  logical
decoding found consistent point at 0/04006FC0
2025-08-12 11:48:21.067 JST [sby][slotsync worker] DETAIL:  There are
no running transactions.
2025-08-12 11:48:21.296 JST [sby][slotsync worker] LOG:  starting
logical decoding for slot "mysub"
2025-08-12 11:48:21.296 JST [sby][slotsync worker] DETAIL:  Streaming
transactions committing after 0/04F9DC90, reading WAL from 0/04006FC0.
2025-08-12 11:48:21.297 JST [sby][slotsync worker] LOG:  logical
decoding found consistent point at 0/04006FC0
2025-08-12 11:48:21.297 JST [sby][slotsync worker] DETAIL:  There are
no running transactions.
2025-08-12 11:48:21.526 JST [sby][slotsync worker] LOG:  starting
logical decoding for slot "mysub"
2025-08-12 11:48:21.526 JST [sby][slotsync worker] DETAIL:  Streaming
transactions committing after 0/0506A5C0, reading WAL from 0/04006FC0.
2025-08-12 11:48:21.527 JST [sby][slotsync worker] LOG:  logical
decoding found consistent point at 0/04006FC0
2025-08-12 11:48:21.527 JST [sby][slotsync worker] DETAIL:  There are
no running transactions.
2025-08-12 11:48:21.762 JST [sby][slotsync worker] LOG:  starting
logical decoding for slot "mysub"
2025-08-12 11:48:21.762 JST [sby][slotsync worker] DETAIL:  Streaming
transactions committing after 0/050C7F70, reading WAL from 0/04006FC0.
2025-08-12 11:48:21.763 JST [sby][slotsync worker] LOG:  logical
decoding found consistent point at 0/04006FC0
2025-08-12 11:48:21.763 JST [sby][slotsync worker] DETAIL:  There are
no running transactions.
2025-08-12 11:48:21.999 JST [sby][slotsync worker] LOG:  starting
logical decoding for slot "mysub"
2025-08-12 11:48:21.999 JST [sby][slotsync worker] DETAIL:  Streaming
transactions committing after 0/05111420, reading WAL from 0/04006FC0.
2025-08-12 11:48:21.999 JST [sby][slotsync worker] LOG:  logical
decoding found consistent point at 0/04006FC0
2025-08-12 11:48:21.999 JST [sby][slotsync worker] DETAIL:  There are
no running transactions.
----------------------------------------


 Is this expected behavior, a configuration mistake on my side, or perhaps
 an oversight in the commit of the replication slot synchronization feature?

This seems more like debug output left over from development rather than
something useful for users. If this is true, would it make sense to change
these messages from LOG to DEBUG?

Regards,


--
Fujii Masao



pgsql-hackers by date:

Previous
From: Michael Paquier
Date:
Subject: Re: Annoying warning in SerializeClientConnectionInfo
Next
From: Sami Imseih
Date:
Subject: Re: Improve LWLock tranche name visibility across backends