On Wed, Dec 15, 2021 at 8:32 AM Kyotaro Horiguchi
<horikyota....@gmail.com> wrote:
> > Here's the patch that adds a LOG message whenever a replication slot
> > becomes active and inactive. These logs will be extremely useful on
> > production servers to debug and analyze inactive replication slot
> > issues.
> >
> > Thoughts?
>
> If I create a replication slot, I saw the following lines in server log.
>
> [22054:client backend] LOG: replication slot "s1" becomes active
> [22054:client backend] DETAIL: The process with PID 22054 acquired it.
> [22054:client backend] STATEMENT: select pg_drop_replication_slot('s1');
> [22054:client backend] LOG: replication slot "s1" becomes inactive
> [22054:client backend] DETAIL: The process with PID 22054 released it.
> [22054:client backend] STATEMENT: select pg_drop_replication_slot('s1');
>
> They are apparently too much as if they were DEBUG3 lines. The
> process PID shown is of the process the slot operations took place so
> I think it conveys no information. The STATEMENT lines are also noisy
> for non-ERROR emssages. Couldn't we hide that line?
>
> That is, how about making the log lines as simple as the follows?
>
> [17156:walsender] LOG: acquired replication slot "s1"
> [17156:walsender] LOG: released replication slot "s1"Thanks for taking a look at the patch. Here's what I've come up with: for drops: 2021-12-28 06:39:34.963 UTC [2541600] LOG: acquired persistent physical replication slot "myslot1" 2021-12-28 06:39:34.980 UTC [2541600] LOG: dropped persistent physical replication slot "myslot1" 2021-12-28 06:47:39.994 UTC [2544153] LOG: acquired persistent logical replication slot "myslot2" 2021-12-28 06:47:40.003 UTC [2544153] LOG: dropped persistent logical replication slot "myslot2" for creates: 2021-12-28 06:39:46.859 UTC [2541600] LOG: created persistent physical replication slot "myslot1" 2021-12-28 06:39:46.859 UTC [2541600] LOG: released persistent physical replication slot "myslot1" 2021-12-28 06:45:20.037 UTC [2544153] LOG: created persistent logical replication slot "myslot2" 2021-12-28 06:45:20.058 UTC [2544153] LOG: released persistent logical replication slot "myslot2" for pg_basebackup: 2021-12-28 06:41:04.601 UTC [2542686] LOG: created temporary physical replication slot "pg_basebackup_2542686" 2021-12-28 06:41:04.602 UTC [2542686] LOG: released temporary physical replication slot "pg_basebackup_2542686" 2021-12-28 06:41:04.602 UTC [2542686] LOG: acquired temporary physical replication slot "pg_basebackup_2542686" 2021-12-28 06:41:04.867 UTC [2542686] LOG: released temporary physical replication slot "pg_basebackup_2542686" 2021-12-28 06:41:04.954 UTC [2542686] LOG: dropped temporary physical replication slot "pg_basebackup_2542686" The amount of logs may seem noisy, but they do help a lot given the fact that the server generates much more noise, for instance, the server logs the syntax error statements. And, the replication slots don't get created/dropped every now and then (at max, the pg_basebackup if at all used and configured to take the backups, say, every 24hrs or so). With the above set of logs debugging for inactive replication slots becomes easier. One can find the root cause and answer questions like "why there was a huge WAL file growth at some point or when did a replication slot become inactive or how much time a replication slot was inactive or when did a standby disconnected and connected again or when did a pg_receivewal or pg_recvlogical connected and disconnected so on.". Here's the v2 patch. Please provide your thoughts. Regards, Bharath Rupireddy.
v2-0001-Add-LOG-messages-when-replication-slots-become-ac.patch
Description: Binary data
