server log inflates due to pg_logical_slot_peek_changes/pg_logical_slot_get_changes calls

On Sun, Mar 19, 2023 at 4:59 PM Jeevan Ladhe <jeevanladhe.os@gmail.com> wrote:

Hi,

I observed absurd behaviour while using pg_logical_slot_peek_changes()
and pg_logical_slot_get_changes(). Whenever any of these two functions
are called to read the changes using a decoder plugin, the following
messages are printed in the log for every single such call.

2023-03-19 16:36:06.040 IST [30099] LOG: starting logical decoding for slot "test_slot1"
2023-03-19 16:36:06.040 IST [30099] DETAIL: Streaming transactions committing after 0/851DFD8, reading WAL from 0/851DFA0.
2023-03-19 16:36:06.040 IST [30099] STATEMENT: SELECT data FROM pg_logical_slot_get_changes('test_slot1', NULL, NULL, 'format-version', '2');
2023-03-19 16:36:06.040 IST [30099] LOG: logical decoding found consistent point at 0/851DFA0
2023-03-19 16:36:06.040 IST [30099] DETAIL: There are no running transactions.
2023-03-19 16:36:06.040 IST [30099] STATEMENT: SELECT data FROM pg_logical_slot_get_changes('test_slot1', NULL, NULL, 'format-version', '2');

This log is printed on every single call to peek/get functions and bloats
the server log file by a huge amount when called in the loop for reading
the changes.

IMHO, printing the message every time we create the context for
decoding a slot using pg_logical_slot_get_changes() seems over-burn.
Wondering if instead of LOG messages, should we mark these as
DEBUG1 in SnapBuildFindSnapshot() and CreateDecodingContext()
respectively? I can produce a patch for the same if we agree.

I think those messages are useful when debugging logical replication
problems (imagine missing transaction or inconsistent data between
publisher and subscriber). I don't think pg_logical_slot_get_changes()
or pg_logical_slot_peek_changes() are expected to be called frequently
in a loop. Instead you should open a replication connection to
continue to receive logical changes ... forever.

Why do you need to call pg_logical_slot_peek_changes() and
pg_logical_slot_get_changes() frequently?

--
Best Wishes,
Ashutosh Bapat

Thanks, Ashutosh for the reply.

I think those messages are useful when debugging logical replication

problems (imagine missing transaction or inconsistent data between
publisher and subscriber). I don't think pg_logical_slot_get_changes()
or pg_logical_slot_peek_changes() are expected to be called frequently
in a loop.

Yeah right. But can you please shed some light on when these functions
should be called, or are they used only for testing purposes?

Instead you should open a replication connection to

continue to receive logical changes ... forever.

Yes, this is what I have decided to resort to now.

Why do you need to call pg_logical_slot_peek_changes() and

pg_logical_slot_get_changes() frequently?

I was just playing around to do something for logical replication and
thought
of doing this quick test where every time interval I read using
pg_logical_slot_peek_changes(), make sure to consume them to a consistent
state, and only then use pg_logical_slot_get_changes() to advance the slot.

Regards,
Jeevan Ladhe