MIME-Version: 1.0
From: Fujii Masao <masao.fujii@gmail.com>
Date: Sat, 28 Feb 2026 00:03:45 +0900
Message-ID: <CAHGQGwF6zG9Z8ws1yb3hY1VqV-WT7hR0qyXCn2HdbjvZQKufDw@mail.gmail.com>
Subject: Fix slotsync worker busy loop causing repeated log messages
To: PostgreSQL Hackers <pgsql-hackers@lists.postgresql.org>
Content-Type: multipart/mixed; boundary="0000000000004541b2064bcf8c4e"
Archived-At: <https://www.postgresql.org/message-id/CAHGQGwF6zG9Z8ws1yb3hY1VqV-WT7hR0qyXCn2HdbjvZQKufDw%40mail.gmail.com>
Precedence: bulk

--0000000000004541b2064bcf8c4e
Content-Type: text/plain; charset="UTF-8"

Hi,

While testing the replication slot sync feature, I observed that the slotsync
worker can suddenly start emitting four log messages every 200 ms, even when
both primary and standby are idle. For example:

--------------------------
2026-02-27 23:06:46.123 JST [80789] LOG:  starting logical decoding
for slot "logical_slot"
2026-02-27 23:06:46.123 JST [80789] DETAIL:  Streaming transactions
committing after 0/03000140, reading WAL from 0/03000098.
2026-02-27 23:06:46.123 JST [80789] LOG:  logical decoding found
consistent point at 0/03000098
2026-02-27 23:06:46.123 JST [80789] DETAIL:  There are no running transactions.
2026-02-27 23:06:46.330 JST [80789] LOG:  starting logical decoding
for slot "logical_slot"
2026-02-27 23:06:46.330 JST [80789] DETAIL:  Streaming transactions
committing after 0/03000140, reading WAL from 0/03000098.
2026-02-27 23:06:46.330 JST [80789] LOG:  logical decoding found
consistent point at 0/03000098
2026-02-27 23:06:46.330 JST [80789] DETAIL:  There are no running transactions.
2026-02-27 23:06:46.536 JST [80789] LOG:  starting logical decoding
for slot "logical_slot"
2026-02-27 23:06:46.536 JST [80789] DETAIL:  Streaming transactions
committing after 0/03000140, reading WAL from 0/03000098.
2026-02-27 23:06:46.536 JST [80789] LOG:  logical decoding found
consistent point at 0/03000098
2026-02-27 23:06:46.536 JST [80789] DETAIL:  There are no running transactions.
--------------------------

These messages repeat roughly every 200 ms.


I created the replication slot sync environment as follows:

--------------------------
initdb -D data --encoding=UTF8 --locale=C
cat <<EOF >> data/postgresql.conf
wal_level = logical
synchronized_standby_slots = 'physical_slot'
EOF
pg_ctl -D data start
pg_receivewal --create-slot -S physical_slot
pg_recvlogical --create-slot -S logical_slot -P pgoutput
--enable-failover -d postgres
psql -c "CREATE PUBLICATION mypub"

pg_basebackup -D sby1 -c fast -R -S physical_slot -d "dbname=postgres"
cat <<EOF >> sby1/postgresql.conf
port = 5433
sync_replication_slots = on
hot_standby_feedback = on
EOF
pg_ctl -D sby1 start
--------------------------


After that, I executed the following, and then the issue occurred:

--------------------------
SELECT pg_logical_emit_message(true, 'abc', 'xyz');

SELECT pg_replication_slot_advance('logical_slot', max(lsn)) FROM
pg_logical_slot_peek_binary_changes('logical_slot', NULL, NULL,
'proto_version', '3', 'publication_names', 'mypub', 'messages',
'true', 'binary', 'false', 'streaming', 'false');

-- Wait for the log message "newly created replication slot
"logical_slot" is sync-ready now" to output

SELECT pg_replication_slot_advance('logical_slot', max(lsn)) FROM
pg_logical_slot_peek_binary_changes('logical_slot', NULL, NULL,
'proto_version', '3', 'publication_names', 'mypub', 'messages',
'true', 'binary', 'false', 'streaming', 'false');
--------------------------


While the issue is happening, the failover logical slot shows:

[PRIMARY]
=# SELECT slot_name, restart_lsn, confirmed_flush_lsn from
pg_replication_slots where slot_name = 'logical_slot';
  slot_name   | restart_lsn | confirmed_flush_lsn
--------------+-------------+---------------------
 logical_slot | 0/03000140  | 0/03000140

[STANDBY]
=# SELECT slot_name, restart_lsn, confirmed_flush_lsn from
pg_replication_slots where slot_name = 'logical_slot';
  slot_name   | restart_lsn | confirmed_flush_lsn
--------------+-------------+---------------------
 logical_slot | 0/03000098  | 0/03000140

confirmed_flush_lsn matches on both servers, but restart_lsn differs.


Normally, the slotsync worker updates the standby slot using the primary's slot
state. However, when confirmed_flush_lsn matches but restart_lsn does not,
the worker does not actually update the standby slot. Despite that, the current
code of update_local_synced_slot() appears to treat this situation as if
an update occurred. As a result, the worker sleeps only for the minimum
interval (200 ms) before retrying. In the next cycle, it again assumes
an update happened, and continues looping with the short sleep interval,
causing the repeated logical decoding log messages. Based on a quick analysis,
this seems to be the root cause.

I think update_local_synced_slot() should return false (i.e., no update
happened) when confirmed_flush_lsn is equal but restart_lsn differs between
primary and standby. That would allow the worker to use the normal sleep
interval instead of the minimum one.

I've attached a PoC patch implementing this change.

Thoughts?

Regards,

-- 
Fujii Masao

--0000000000004541b2064bcf8c4e
Content-Type: application/octet-stream; 
	name="v1-0001-Fix-slotsync-worker-busy-loop-causing-repeated-lo.patch"
Content-Disposition: attachment; 
	filename="v1-0001-Fix-slotsync-worker-busy-loop-causing-repeated-lo.patch"
Content-Transfer-Encoding: base64
Content-ID: <f_mm50tk080>
X-Attachment-Id: f_mm50tk080

RnJvbSA4Y2Q3MzE4NTc1YTY1MTcyZDQwZjFjZDY2YTZjNWZjODA3ZDMzNjZhIE1vbiBTZXAgMTcg
MDA6MDA6MDAgMjAwMQpGcm9tOiBGdWppaSBNYXNhbyA8ZnVqaWlAcG9zdGdyZXNxbC5vcmc+CkRh
dGU6IEZyaSwgMjcgRmViIDIwMjYgMjM6MDI6MjMgKzA5MDAKU3ViamVjdDogW1BBVENIIHYxXSBG
aXggc2xvdHN5bmMgd29ya2VyIGJ1c3kgbG9vcCBjYXVzaW5nIHJlcGVhdGVkIGxvZ2ljYWwKIGRl
Y29kaW5nIGxvZ3MuCgpQcmV2aW91c2x5LCB0aGUgc2xvdHN5bmMgd29ya2VyIGNvdWxkIGVudGVy
IGEgYnVzeSBsb29wIGFuZCBlbWl0IGZvdXIgbG9naWNhbApsb2cgbWVzc2FnZXMgZXZlcnkgMjAw
IG1zLCBldmVuIHdoZW4gYm90aCB0aGUgcHJpbWFyeSBhbmQgc3RhbmRieSB3ZXJlIGlkbGUuCgpU
aGlzIGhhcHBlbmVkIGJlY2F1c2UgdGhlIHdvcmtlciBpbmNvcnJlY3RseSB0cmVhdGVkIGNlcnRh
aW4gY2FzZXMgYXMKc3VjY2Vzc2Z1bCBzbG90IHVwZGF0ZXMsIGNhdXNpbmcgaXQgdG8gdXNlIHRo
ZSBtaW5pbXVtIHNsZWVwIGludGVydmFsIGFuZApyZXBlYXRlZGx5IHJlc3RhcnQgc2xvdCBzeW5j
aW5nLgoKVGhpcyBjb21taXQgZml4ZXMgdGhpcyBieSBlbnN1cmluZyB0aGUgd29ya2VyIGRvZXMg
bm90IHRyZWF0IHN1Y2ggY2FzZXMgYXMKdXBkYXRlcywgYWxsb3dpbmcgaXQgdG8gc2xlZXAgbm9y
bWFsbHkgYW5kIGF2b2lkIGV4Y2Vzc2l2ZSBsb2cgb3V0cHV0LgotLS0KIHNyYy9iYWNrZW5kL3Jl
cGxpY2F0aW9uL2xvZ2ljYWwvc2xvdHN5bmMuYyB8IDggKysrKystLS0KIDEgZmlsZSBjaGFuZ2Vk
LCA1IGluc2VydGlvbnMoKyksIDMgZGVsZXRpb25zKC0pCgpkaWZmIC0tZ2l0IGEvc3JjL2JhY2tl
bmQvcmVwbGljYXRpb24vbG9naWNhbC9zbG90c3luYy5jIGIvc3JjL2JhY2tlbmQvcmVwbGljYXRp
b24vbG9naWNhbC9zbG90c3luYy5jCmluZGV4IDA2MmEwOGNjYjg4Li5mYzIxNTNlMjQzYiAxMDA2
NDQKLS0tIGEvc3JjL2JhY2tlbmQvcmVwbGljYXRpb24vbG9naWNhbC9zbG90c3luYy5jCisrKyBi
L3NyYy9iYWNrZW5kL3JlcGxpY2F0aW9uL2xvZ2ljYWwvc2xvdHN5bmMuYwpAQCAtMzEwLDggKzMx
MCwxMCBAQCB1cGRhdGVfbG9jYWxfc3luY2VkX3Nsb3QoUmVtb3RlU2xvdCAqcmVtb3RlX3Nsb3Qs
IE9pZCByZW1vdGVfZGJpZCkKIAkJCXNsb3QtPmRhdGEuY29uZmlybWVkX2ZsdXNoID0gcmVtb3Rl
X3Nsb3QtPmNvbmZpcm1lZF9sc247CiAJCQlzbG90LT5kYXRhLmNhdGFsb2dfeG1pbiA9IHJlbW90
ZV9zbG90LT5jYXRhbG9nX3htaW47CiAJCQlTcGluTG9ja1JlbGVhc2UoJnNsb3QtPm11dGV4KTsK
KworCQkJdXBkYXRlZF94bWluX29yX2xzbiA9IHRydWU7CiAJCX0KLQkJZWxzZQorCQllbHNlIGlm
IChyZW1vdGVfc2xvdC0+Y29uZmlybWVkX2xzbiA+IHNsb3QtPmRhdGEuY29uZmlybWVkX2ZsdXNo
KQogCQl7CiAJCQlib29sCQlmb3VuZF9jb25zaXN0ZW50X3NuYXBzaG90OwogCkBAIC0zNDMsOSAr
MzQ1LDkgQEAgdXBkYXRlX2xvY2FsX3N5bmNlZF9zbG90KFJlbW90ZVNsb3QgKnJlbW90ZV9zbG90
LCBPaWQgcmVtb3RlX2RiaWQpCiAKIAkJCQlza2lwX3JlYXNvbiA9IFNTX1NLSVBfTk9fQ09OU0lT
VEVOVF9TTkFQU0hPVDsKIAkJCX0KLQkJfQogCi0JCXVwZGF0ZWRfeG1pbl9vcl9sc24gPSB0cnVl
OworCQkJdXBkYXRlZF94bWluX29yX2xzbiA9IHRydWU7CisJCX0KIAl9CiAKIAkvKiBVcGRhdGUg
c2xvdCBzeW5jIHNraXAgc3RhdHMgKi8KLS0gCjIuNTEuMgoK
--0000000000004541b2064bcf8c4e--