walsender performance regression due to logical decoding on standby changes

On Tue, 2023-05-09 at 12:02 -0700, Andres Freund wrote:

I don't think the approach of not having any sort of "registry" of
whether
anybody is waiting for the replay position to be updated is
feasible. Iterating over all walsenders slots is just too expensive -

Would it work to use a shared counter for the waiters (or, two
counters, one for physical and one for logical), and just early exit if
the count is zero?

Regards,
Jeff Davis

Hi,

On 2023-05-09 13:38:24 -0700, Jeff Davis wrote:

On Tue, 2023-05-09 at 12:02 -0700, Andres Freund wrote:

I don't think the approach of not having any sort of "registry" of
whether
anybody is waiting for the replay position to be updated is
feasible. Iterating over all walsenders slots is just too expensive -

Would it work to use a shared counter for the waiters (or, two
counters, one for physical and one for logical), and just early exit if
the count is zero?

That doesn't really fix the problem - once you have a single walsender
connected, performance is bad again.

Greetings,

Andres Freund

On Wed, May 10, 2023 at 12:33 AM Andres Freund <andres@anarazel.de> wrote:

Unfortunately I have found the following commit to have caused a performance
regression:

commit e101dfac3a53c20bfbf1ca85d30a368c2954facf

The problem is that, on a standby, after the change - as needed to for the
approach to work - the call to WalSndWakeup() in ApplyWalRecord() happens for
every record, instead of only happening when the timeline is changed (or WAL
is flushed or ...).

WalSndWakeup() iterates over all walsender slots, regardless of whether in
use. For each of the walsender slots it acquires a spinlock.

When replaying a lot of small-ish WAL records I found the startup process to
spend the majority of the time in WalSndWakeup(). I've not measured it very
precisely yet, but the overhead is significant (~35% slowdown), even with the
default max_wal_senders. If that's increased substantially, it obviously gets
worse.

I played it with a simple primary -> standby1 -> standby2 setup. I ran
a pgbench script [1]./pg_ctl -D data -l logfile stop ./pg_ctl -D sbdata1 -l logfile1 stop ./pg_ctl -D sbdata2 -l logfile2 stop on primary and counted the number of times
WalSndWakeup() gets called from ApplyWalRecord() and the number of
times spinlock is acquired/released in WalSndWakeup(). It's a whopping
21 million times spinlock is acquired/released on the standby 1 and
standby 2 for just a < 5min of pgbench run on the primary:

standby 1:
2023-05-10 05:32:43.249 UTC [1595600] LOG: FOO WalSndWakeup() in
ApplyWalRecord() was called 2176352 times
2023-05-10 05:32:43.249 UTC [1595600] LOG: FOO spinlock
acquisition/release count in WalSndWakeup() is 21763530

standby 2:
2023-05-10 05:32:43.249 UTC [1595625] LOG: FOO WalSndWakeup() in
ApplyWalRecord() was called 2176352 times
2023-05-10 05:32:43.249 UTC [1595625] LOG: FOO spinlock
acquisition/release count in WalSndWakeup() is 21763530

In this case, there is no timeline switch or no logical decoding on
the standby or such, but WalSndWakeup() gets called because the
standby can't make out if the slot is for logical or physical
replication unless spinlock is acquired. Before e101dfac3a,
WalSndWakeup() was getting called only when there was a timeline
switch.

The only saving grace is that this is not an issue on the primary.

Yeah.

I don't think the approach of not having any sort of "registry" of whether
anybody is waiting for the replay position to be updated is
feasible. Iterating over all walsenders slots is just too expensive -
WalSndWakeup() shows up even if I remove the spinlock (which we likely could,
especially when just checking if the the walsender is connected).

Right.

My current guess is that mis-using a condition variable is the best bet. I
think it should work to use ConditionVariablePrepareToSleep() before a
WalSndWait(), and then ConditionVariableCancelSleep(). I.e. to never use
ConditionVariableSleep(). The latch set from ConditionVariableBroadcast()
would still cause the necessary wakeup.

How about something like the attached? Recovery and subscription tests
don't complain with the patch.

[1]: ./pg_ctl -D data -l logfile stop ./pg_ctl -D sbdata1 -l logfile1 stop ./pg_ctl -D sbdata2 -l logfile2 stop
./pg_ctl -D data -l logfile stop
./pg_ctl -D sbdata1 -l logfile1 stop
./pg_ctl -D sbdata2 -l logfile2 stop

cd /home/ubuntu/postgres
rm -rf inst
make distclean
./configure --prefix=$PWD/inst/ CFLAGS="-O3" > install.log && make -j
8 install > install.log 2>&1 &

primary -> standby1 -> standby2

free -m
sudo su -c 'sync; echo 3 > /proc/sys/vm/drop_caches'
free -m

cd inst/bin
./initdb -D data
mkdir archived_wal

cat << EOF >> data/postgresql.conf
shared_buffers = '8GB'
wal_buffers = '1GB'
max_wal_size = '16GB'
max_connections = '5000'
archive_mode = 'on'
archive_command='cp %p /home/ubuntu/postgres/inst/bin/archived_wal/%f'
EOF

./pg_ctl -D data -l logfile start
./pg_basebackup -D sbdata1
./psql -c "select pg_create_physical_replication_slot('sb1_slot',
true, false)" postgres

cat << EOF >> sbdata1/postgresql.conf
port=5433
primary_conninfo='host=localhost port=5432 dbname=postgres user=ubuntu
application_name=sb1'
primary_slot_name='sb1_slot'
restore_command='cp /home/ubuntu/postgres/inst/bin/archived_wal/%f %p'
EOF

touch sbdata1/standby.signal

./pg_ctl -D sbdata1 -l logfile1 start
./pg_basebackup -D sbdata2 -p 5433
./psql -p 5433 -c "select
pg_create_physical_replication_slot('sb2_slot', true, false)" postgres

cat << EOF >> sbdata2/postgresql.conf
port=5434
primary_conninfo='host=localhost port=5433 dbname=postgres user=ubuntu
application_name=sb2'
primary_slot_name='sb2_slot'
restore_command='cp /home/ubuntu/postgres/inst/bin/archived_wal/%f %p'
EOF

touch sbdata2/standby.signal

./pg_ctl -D sbdata2 -l logfile2 start
./psql -c "select pid, backend_type from pg_stat_activity where
backend_type in ('walreceiver', 'walsender');" postgres
./psql -p 5433 -c "select pid, backend_type from pg_stat_activity
where backend_type in ('walreceiver', 'walsender');" postgres
./psql -p 5434 -c "select pid, backend_type from pg_stat_activity
where backend_type in ('walreceiver', 'walsender');" postgres

ulimit -S -n 5000
./pgbench --initialize --scale=300 postgres
for c in 1 2 4 8 16 32 64 128 256 512 768 1024 2048 4096; do echo -n
"$c ";./pgbench -n -M prepared -U ubuntu postgres -b tpcb-like -c$c
-j$c -T5 2>&1|grep '^tps'|awk '{print $3}';done

--
Bharath Rupireddy
PostgreSQL Contributors Team
RDS Open Source Databases
Amazon Web Services: https://aws.amazon.com

Hi,

On 5/9/23 11:00 PM, Andres Freund wrote:

Hi,

On 2023-05-09 13:38:24 -0700, Jeff Davis wrote:

On Tue, 2023-05-09 at 12:02 -0700, Andres Freund wrote:

I don't think the approach of not having any sort of "registry" of
whether
anybody is waiting for the replay position to be updated is
feasible. Iterating over all walsenders slots is just too expensive -

Would it work to use a shared counter for the waiters (or, two
counters, one for physical and one for logical), and just early exit if
the count is zero?

That doesn't really fix the problem - once you have a single walsender
connected, performance is bad again.

Just to clarify, do you mean that if there is only one remaining active walsender that, say,
has been located at slot n, then we’d still have to loop from 0 to n in WalSndWakeup()?

Regards,

--
Bertrand Drouvot
PostgreSQL Contributors Team
RDS Open Source Databases
Amazon Web Services: https://aws.amazon.com

Hi,

On 5/10/23 8:36 AM, Bharath Rupireddy wrote:

On Wed, May 10, 2023 at 12:33 AM Andres Freund <andres@anarazel.de> wrote:

Unfortunately I have found the following commit to have caused a performance
regression:

commit e101dfac3a53c20bfbf1ca85d30a368c2954facf

The problem is that, on a standby, after the change - as needed to for the
approach to work - the call to WalSndWakeup() in ApplyWalRecord() happens for
every record, instead of only happening when the timeline is changed (or WAL
is flushed or ...).

WalSndWakeup() iterates over all walsender slots, regardless of whether in
use. For each of the walsender slots it acquires a spinlock.

When replaying a lot of small-ish WAL records I found the startup process to
spend the majority of the time in WalSndWakeup(). I've not measured it very
precisely yet, but the overhead is significant (~35% slowdown), even with the
default max_wal_senders. If that's increased substantially, it obviously gets
worse.

Thanks Andres for the call out! I do agree that this is a concern.

The only saving grace is that this is not an issue on the primary.

Yeah.

+1

My current guess is that mis-using a condition variable is the best bet. I
think it should work to use ConditionVariablePrepareToSleep() before a
WalSndWait(), and then ConditionVariableCancelSleep(). I.e. to never use
ConditionVariableSleep(). The latch set from ConditionVariableBroadcast()
would still cause the necessary wakeup.

Yeah, I think that "mis-using" a condition variable is a valid option. Unless I'm missing
something, I don't think there is anything wrong with using a CV that way (aka not using
ConditionVariableTimedSleep() or ConditionVariableSleep() in this particular case).

How about something like the attached? Recovery and subscription tests
don't complain with the patch.

Thanks Bharath for looking at it!

I launched a full Cirrus CI test with it but it failed on one environment (did not look in details,
just sharing this here): https://cirrus-ci.com/task/6570140767092736

Also I have a few comments:

@@ -1958,7 +1959,7 @@ ApplyWalRecord(XLogReaderState *xlogreader, XLogRecord *record, TimeLineID *repl
          * ------
          */
         if (AllowCascadeReplication())
-               WalSndWakeup(switchedTLI, true);
+               ConditionVariableBroadcast(&WalSndCtl->cv);

I think the comment above this change needs to be updated.

@@ -3368,9 +3370,13 @@ WalSndWait(uint32 socket_events, long timeout, uint32 wait_event)
WaitEvent event;

         ModifyWaitEvent(FeBeWaitSet, FeBeWaitSetSocketPos, socket_events, NULL);
+
+       ConditionVariablePrepareToSleep(&WalSndCtl->cv);
         if (WaitEventSetWait(FeBeWaitSet, timeout, &event, 1, wait_event) == 1 &&
                 (event.events & WL_POSTMASTER_DEATH))
                 proc_exit(1);
+
+       ConditionVariableCancelSleep();

May be worth to update the comment above WalSndWait() too? (to explain why a CV handling is part of it).

@@ -108,6 +109,8 @@ typedef struct
*/
bool sync_standbys_defined;

+ ConditionVariable cv;

Worth to give it a more meaning full name? (to give a clue as when it is used)

I think we also need to update the comment above WalSndWakeup():

"
* For cascading replication we need to wake up physical walsenders separately
* from logical walsenders (see the comment before calling WalSndWakeup() in
* ApplyWalRecord() for more details).
"

Regards,

--
Bertrand Drouvot
PostgreSQL Contributors Team
RDS Open Source Databases
Amazon Web Services: https://aws.amazon.com

On Wednesday, May 10, 2023 2:36 PM Bharath Rupireddy <bharath.rupireddyforpostgres@gmail.com> wrote:

On Wed, May 10, 2023 at 12:33 AM Andres Freund <andres@anarazel.de>
wrote:

Unfortunately I have found the following commit to have caused a

performance

regression:

commit e101dfac3a53c20bfbf1ca85d30a368c2954facf

The problem is that, on a standby, after the change - as needed to for the
approach to work - the call to WalSndWakeup() in ApplyWalRecord()

happens for

every record, instead of only happening when the timeline is changed (or

WAL

is flushed or ...).

WalSndWakeup() iterates over all walsender slots, regardless of whether in
use. For each of the walsender slots it acquires a spinlock.

When replaying a lot of small-ish WAL records I found the startup process to
spend the majority of the time in WalSndWakeup(). I've not measured it very
precisely yet, but the overhead is significant (~35% slowdown), even with the
default max_wal_senders. If that's increased substantially, it obviously gets
worse.

I played it with a simple primary -> standby1 -> standby2 setup. I ran
a pgbench script [1] on primary and counted the number of times
WalSndWakeup() gets called from ApplyWalRecord() and the number of
times spinlock is acquired/released in WalSndWakeup(). It's a whopping
21 million times spinlock is acquired/released on the standby 1 and
standby 2 for just a < 5min of pgbench run on the primary:

standby 1:
2023-05-10 05:32:43.249 UTC [1595600] LOG: FOO WalSndWakeup() in
ApplyWalRecord() was called 2176352 times
2023-05-10 05:32:43.249 UTC [1595600] LOG: FOO spinlock
acquisition/release count in WalSndWakeup() is 21763530

standby 2:
2023-05-10 05:32:43.249 UTC [1595625] LOG: FOO WalSndWakeup() in
ApplyWalRecord() was called 2176352 times
2023-05-10 05:32:43.249 UTC [1595625] LOG: FOO spinlock
acquisition/release count in WalSndWakeup() is 21763530

In this case, there is no timeline switch or no logical decoding on
the standby or such, but WalSndWakeup() gets called because the
standby can't make out if the slot is for logical or physical
replication unless spinlock is acquired. Before e101dfac3a,
WalSndWakeup() was getting called only when there was a timeline
switch.

The only saving grace is that this is not an issue on the primary.

Yeah.

I don't think the approach of not having any sort of "registry" of whether
anybody is waiting for the replay position to be updated is
feasible. Iterating over all walsenders slots is just too expensive -
WalSndWakeup() shows up even if I remove the spinlock (which we likely

could,

especially when just checking if the the walsender is connected).

Right.

My current guess is that mis-using a condition variable is the best bet. I
think it should work to use ConditionVariablePrepareToSleep() before a
WalSndWait(), and then ConditionVariableCancelSleep(). I.e. to never use
ConditionVariableSleep(). The latch set from ConditionVariableBroadcast()
would still cause the necessary wakeup.

How about something like the attached? Recovery and subscription tests
don't complain with the patch.

Thanks for the patch. I noticed one place where the logic is different from before and
just to confirm:

	if (AllowCascadeReplication())
-		WalSndWakeup(switchedTLI, true);
+		ConditionVariableBroadcast(&WalSndCtl->cv);

After the change, we wakeup physical walsender regardless of switchedTLI flag.
Is this intentional ? if so, I think It would be better to update the comments above this.

Best Regards,
Hou zj

On Wed, May 10, 2023 at 3:41 PM Zhijie Hou (Fujitsu)
<houzj.fnst@fujitsu.com> wrote:

On Wednesday, May 10, 2023 2:36 PM Bharath Rupireddy <bharath.rupireddyforpostgres@gmail.com> wrote:

My current guess is that mis-using a condition variable is the best bet. I
think it should work to use ConditionVariablePrepareToSleep() before a
WalSndWait(), and then ConditionVariableCancelSleep(). I.e. to never use
ConditionVariableSleep(). The latch set from ConditionVariableBroadcast()
would still cause the necessary wakeup.

How about something like the attached? Recovery and subscription tests
don't complain with the patch.

Thanks for the patch. I noticed one place where the logic is different from before and
just to confirm:

if (AllowCascadeReplication())
-               WalSndWakeup(switchedTLI, true);
+               ConditionVariableBroadcast(&WalSndCtl->cv);

After the change, we wakeup physical walsender regardless of switchedTLI flag.
Is this intentional ? if so, I think It would be better to update the comments above this.

This raises the question of whether we need this condition variable
logic for physical walsenders?

--
With Regards,
Amit Kapila.

On Wed, May 10, 2023 at 7:33 PM Amit Kapila <amit.kapila16@gmail.com> wrote:

On Wed, May 10, 2023 at 3:41 PM Zhijie Hou (Fujitsu)
<houzj.fnst@fujitsu.com> wrote:

On Wednesday, May 10, 2023 2:36 PM Bharath Rupireddy <bharath.rupireddyforpostgres@gmail.com> wrote:

My current guess is that mis-using a condition variable is the best bet. I
think it should work to use ConditionVariablePrepareToSleep() before a
WalSndWait(), and then ConditionVariableCancelSleep(). I.e. to never use
ConditionVariableSleep(). The latch set from ConditionVariableBroadcast()
would still cause the necessary wakeup.

How about something like the attached? Recovery and subscription tests
don't complain with the patch.

Thanks for the patch. I noticed one place where the logic is different from before and
just to confirm:

if (AllowCascadeReplication())
-               WalSndWakeup(switchedTLI, true);
+               ConditionVariableBroadcast(&WalSndCtl->cv);

After the change, we wakeup physical walsender regardless of switchedTLI flag.
Is this intentional ? if so, I think It would be better to update the comments above this.

This raises the question of whether we need this condition variable
logic for physical walsenders?

It sounds like a good idea. We can have two condition variables for
logical and physical walsenders, and selectively wake up walsenders
sleeping on the condition variables. It should work, it seems like
much of a hack, though.

Regards,

[1]: /messages/by-id/2d314c22b9e03415aa1c7d8fd1f698dae60effa7.camel@j-davis.com

--
Masahiko Sawada
Amazon Web Services: https://aws.amazon.com

On Wednesday, May 10, 2023 3:03 AM Andres Freund <andres@anarazel.de> wrote:

Hi,

Unfortunately I have found the following commit to have caused a
performance
regression:

commit e101dfac3a53c20bfbf1ca85d30a368c2954facf
Author: Andres Freund <andres@anarazel.de>
Date: 2023-04-08 00:24:24 -0700

For cascading replication, wake physical and logical walsenders separately

Physical walsenders can't send data until it's been flushed; logical
walsenders can't decode and send data until it's been applied. On the
standby, the WAL is flushed first, which will only wake up physical
walsenders; and then applied, which will only wake up logical
walsenders.

Previously, all walsenders were awakened when the WAL was flushed. That
was fine for logical walsenders on the primary; but on the standby the
flushed WAL would have been not applied yet, so logical walsenders were
awakened too early.

Per idea from Jeff Davis and Amit Kapila.

Author: "Drouvot, Bertrand" <bertranddrouvot.pg@gmail.com>
Reviewed-By: Jeff Davis <pgsql@j-davis.com>
Reviewed-By: Robert Haas <robertmhaas@gmail.com>
Reviewed-by: Amit Kapila <amit.kapila16@gmail.com>
Reviewed-by: Masahiko Sawada <sawada.mshk@gmail.com>
Discussion:
/messages/by-id/CAA4eK1+zO5LUeisabX10c81LU-fWMKO4M9Wyg1cdkb
W7Hqh6vQ@mail.gmail.com

The problem is that, on a standby, after the change - as needed to for the
approach to work - the call to WalSndWakeup() in ApplyWalRecord() happens
for
every record, instead of only happening when the timeline is changed (or WAL
is flushed or ...).

WalSndWakeup() iterates over all walsender slots, regardless of whether in
use. For each of the walsender slots it acquires a spinlock.

When replaying a lot of small-ish WAL records I found the startup process to
spend the majority of the time in WalSndWakeup(). I've not measured it very
precisely yet, but the overhead is significant (~35% slowdown), even with the
default max_wal_senders. If that's increased substantially, it obviously gets
worse.

I did some simple tests for this to see the performance impact on
the streaming replication, just share it here for reference.

1) sync primary-standby setup, load data on primary and count the time spent on
replication. the degradation will be more obvious as the value of max_wal_senders
increases.

max_wal_senders before(ms) after(ms) degradation
100 13394.4013 14141.2615 5.58%
200 13280.8507 14597.1173 9.91%
300 13535.0232 16735.7379 23.65%

2) Similar as 1) but count the time that the standby startup process spent on
replaying WAL(via gprof).

10 senders
===========
before
% cumulative self self total
time seconds seconds calls s/call s/call name
4.12 0.45 0.11 1 0.11 2.46 PerformWalRecovery

after
% cumulative self self total
time seconds seconds calls s/call s/call name
17.99 0.59 0.59 4027383 0.00 0.00 WalSndWakeup
8.23 0.86 0.27 1 0.27 3.11 PerformWalRecovery

100 senders
===========
before
% cumulative self self total
time seconds seconds calls s/call s/call name
5.56 0.36 0.18 1 0.18 2.91 PerformWalRecovery

after
% cumulative self self total
time seconds seconds calls s/call s/call name
64.65 4.39 4.39 4027383 0.00 0.00 WalSndWakeup
2.95 4.59 0.20 1 0.20 6.62 PerformWalRecovery

Will test after applying the latest patch in this thread later.

Best Regards,
Hou zj

On Wed, May 10, 2023 at 3:23 PM Drouvot, Bertrand
<bertranddrouvot.pg@gmail.com> wrote:

My current guess is that mis-using a condition variable is the best bet. I
think it should work to use ConditionVariablePrepareToSleep() before a
WalSndWait(), and then ConditionVariableCancelSleep(). I.e. to never use
ConditionVariableSleep(). The latch set from ConditionVariableBroadcast()
would still cause the necessary wakeup.

How about something like the attached? Recovery and subscription tests
don't complain with the patch.

I launched a full Cirrus CI test with it but it failed on one environment (did not look in details,
just sharing this here): https://cirrus-ci.com/task/6570140767092736

Yeah, v1 had ConditionVariableInit() such that the CV was getting
initialized for every backend as opposed to just once after the WAL
sender shmem was created.

Also I have a few comments:

Indeed, v1 was a WIP patch. Please have a look at the attached v2
patch, which has comments and passing CI runs on all platforms -
https://github.com/BRupireddy/postgres/tree/optimize_walsender_wakeup_logic_v2.

On Wed, May 10, 2023 at 3:41 PM Zhijie Hou (Fujitsu)
<houzj.fnst@fujitsu.com> wrote:

if (AllowCascadeReplication())
-               WalSndWakeup(switchedTLI, true);
+               ConditionVariableBroadcast(&WalSndCtl->cv);

After the change, we wakeup physical walsender regardless of switchedTLI flag.
Is this intentional ? if so, I think It would be better to update the comments above this.

That's not the case with the attached v2 patch. Please have a look.

On Thu, May 11, 2023 at 10:27 AM Masahiko Sawada <sawada.mshk@gmail.com> wrote:

We can have two condition variables for
logical and physical walsenders, and selectively wake up walsenders
sleeping on the condition variables. It should work, it seems like
much of a hack, though.

Andres, rightly put it - 'mis-using' CV infrastructure. It is simple,
works, and makes the WalSndWakeup() easy solving the performance
regression.

--
Bharath Rupireddy
PostgreSQL Contributors Team
RDS Open Source Databases
Amazon Web Services: https://aws.amazon.com

On Friday, May 12, 2023 7:58 PM Bharath Rupireddy <bharath.rupireddyforpostgres@gmail.com> wrote:

On Wed, May 10, 2023 at 3:23 PM Drouvot, Bertrand
<bertranddrouvot.pg@gmail.com> wrote:

My current guess is that mis-using a condition variable is the best
bet. I think it should work to use
ConditionVariablePrepareToSleep() before a WalSndWait(), and then
ConditionVariableCancelSleep(). I.e. to never use
ConditionVariableSleep(). The latch set from

ConditionVariableBroadcast() would still cause the necessary wakeup.

How about something like the attached? Recovery and subscription
tests don't complain with the patch.

I launched a full Cirrus CI test with it but it failed on one
environment (did not look in details, just sharing this here):
https://cirrus-ci.com/task/6570140767092736

Yeah, v1 had ConditionVariableInit() such that the CV was getting initialized for
every backend as opposed to just once after the WAL sender shmem was
created.

Also I have a few comments:

Indeed, v1 was a WIP patch. Please have a look at the attached v2 patch, which
has comments and passing CI runs on all platforms -
https://github.com/BRupireddy/postgres/tree/optimize_walsender_wakeup_
logic_v2.

On Wed, May 10, 2023 at 3:41 PM Zhijie Hou (Fujitsu) <houzj.fnst@fujitsu.com>
wrote:

if (AllowCascadeReplication())
-               WalSndWakeup(switchedTLI, true);
+               ConditionVariableBroadcast(&WalSndCtl->cv);

After the change, we wakeup physical walsender regardless of switchedTLI

flag.

Is this intentional ? if so, I think It would be better to update the comments

above this.

That's not the case with the attached v2 patch. Please have a look.

Thanks for updating the patch. I did some simple primary->standby replication test for the
patch and can see the degradation doesn't happen in the replication after applying it[1]max_wal_senders = 100 before regression(ms) after regression(ms) v2 patch(ms) 13394.4013 14141.2615 13455.2543 Compared with before regression 5.58% 0.45%.

One nitpick in the comment:

+ * walsenders. It makes WalSndWakeup() callers life easy.

callers life easy => callers' life easy.

[1]: max_wal_senders = 100 before regression(ms) after regression(ms) v2 patch(ms) 13394.4013 14141.2615 13455.2543 Compared with before regression 5.58% 0.45%
max_wal_senders = 100
before regression(ms) after regression(ms) v2 patch(ms)
13394.4013 14141.2615 13455.2543
Compared with before regression 5.58% 0.45%

max_wal_senders = 200
before regression(ms) after regression(ms) v2 patch(ms)
13280.8507 14597.1173 13632.0606
Compared with before regression 9.91% 1.64%

max_wal_senders = 300
before regression(ms) after regression(ms) v2 patch(ms)
13535.0232 16735.7379 13705.7135
Compared with before regression 23.65% 1.26%

Best Regards,
Hou zj

On Fri, May 12, 2023 at 11:58 PM Bharath Rupireddy
<bharath.rupireddyforpostgres@gmail.com> wrote:

Andres, rightly put it - 'mis-using' CV infrastructure. It is simple,
works, and makes the WalSndWakeup() easy solving the performance
regression.

Yeah, this seems OK, and better than the complicated alternatives. If
one day we want to implement CVs some other way so that this
I-know-that-CVs-are-really-made-out-of-latches abstraction leak
becomes a problem, and we still need this, well then we can make a
separate latch-wait-list thing.

Hi,

On 5/15/23 4:19 AM, Zhijie Hou (Fujitsu) wrote:

On Friday, May 12, 2023 7:58 PM Bharath Rupireddy <bharath.rupireddyforpostgres@gmail.com> wrote:

On Wed, May 10, 2023 at 3:23 PM Drouvot, Bertrand

That's not the case with the attached v2 patch. Please have a look.

Thanks for V2! It does look good to me and I like the fact that
WalSndWakeup() does not need to loop on all the Walsenders slot
anymore (for both the physical and logical cases).

Thanks for updating the patch. I did some simple primary->standby replication test for the
patch and can see the degradation doesn't happen in the replication after applying it[1].

Thanks for the performance regression measurement!

Regards,

--
Bertrand Drouvot
PostgreSQL Contributors Team
RDS Open Source Databases
Amazon Web Services: https://aws.amazon.com

On Mon, May 15, 2023 at 1:49 PM Thomas Munro <thomas.munro@gmail.com> wrote:

On Fri, May 12, 2023 at 11:58 PM Bharath Rupireddy
<bharath.rupireddyforpostgres@gmail.com> wrote:

Andres, rightly put it - 'mis-using' CV infrastructure. It is simple,
works, and makes the WalSndWakeup() easy solving the performance
regression.

Yeah, this seems OK, and better than the complicated alternatives. If
one day we want to implement CVs some other way so that this
I-know-that-CVs-are-really-made-out-of-latches abstraction leak
becomes a problem, and we still need this, well then we can make a
separate latch-wait-list thing.

+1

Regards,

--
Masahiko Sawada
Amazon Web Services: https://aws.amazon.com

On Mon, May 15, 2023 at 6:14 PM Masahiko Sawada <sawada.mshk@gmail.com> wrote:

On Mon, May 15, 2023 at 1:49 PM Thomas Munro <thomas.munro@gmail.com> wrote:

On Fri, May 12, 2023 at 11:58 PM Bharath Rupireddy
<bharath.rupireddyforpostgres@gmail.com> wrote:

Andres, rightly put it - 'mis-using' CV infrastructure. It is simple,
works, and makes the WalSndWakeup() easy solving the performance
regression.

Yeah, this seems OK, and better than the complicated alternatives. If
one day we want to implement CVs some other way so that this
I-know-that-CVs-are-really-made-out-of-latches abstraction leak
becomes a problem, and we still need this, well then we can make a
separate latch-wait-list thing.

+1

Thanks for acknowledging the approach.

On Mon, May 15, 2023 at 2:11 PM Drouvot, Bertrand
<bertranddrouvot.pg@gmail.com> wrote:

Thanks for V2! It does look good to me and I like the fact that
WalSndWakeup() does not need to loop on all the Walsenders slot
anymore (for both the physical and logical cases).

Indeed, it doesn't have to.

On Mon, May 15, 2023 at 7:50 AM Zhijie Hou (Fujitsu)
<houzj.fnst@fujitsu.com> wrote:

Thanks for updating the patch. I did some simple primary->standby replication test for the
patch and can see the degradation doesn't happen in the replication after applying it[1].

One nitpick in the comment:

+ * walsenders. It makes WalSndWakeup() callers life easy.

callers life easy => callers' life easy.

Changed.

[1]
max_wal_senders = 100
before regression(ms) after regression(ms) v2 patch(ms)
13394.4013 14141.2615 13455.2543
Compared with before regression 5.58% 0.45%

max_wal_senders = 200
before regression(ms) after regression(ms) v2 patch(ms)
13280.8507 14597.1173 13632.0606
Compared with before regression 9.91% 1.64%

max_wal_senders = 300
before regression(ms) after regression(ms) v2 patch(ms)
13535.0232 16735.7379 13705.7135
Compared with before regression 23.65% 1.26%

Yes, the numbers with v2 patch look close to where we were before.
Thanks for confirming. Just wondering, where does this extra
0.45%/1.64%/1.26% coming from?

Please find the attached v3 with the review comment addressed.

Do we need to add an open item for this issue in
https://wiki.postgresql.org/wiki/PostgreSQL_16_Open_Items? If yes, can
anyone in this loop add one?

--
Bharath Rupireddy
PostgreSQL Contributors Team
RDS Open Source Databases
Amazon Web Services: https://aws.amazon.com

Hi,

On 5/15/23 4:39 PM, Bharath Rupireddy wrote:

On Mon, May 15, 2023 at 6:14 PM Masahiko Sawada <sawada.mshk@gmail.com> wrote:

On Mon, May 15, 2023 at 1:49 PM Thomas Munro <thomas.munro@gmail.com> wrote:

Do we need to add an open item for this issue in
https://wiki.postgresql.org/wiki/PostgreSQL_16_Open_Items? If yes, can
anyone in this loop add one?

I do think we need one for this issue and then just added it.

Regards,

--
Bertrand Drouvot
PostgreSQL Contributors Team
RDS Open Source Databases
Amazon Web Services: https://aws.amazon.com

Hi,

On 2023-05-10 08:39:08 +0200, Drouvot, Bertrand wrote:

On 5/9/23 11:00 PM, Andres Freund wrote:

Hi,

On 2023-05-09 13:38:24 -0700, Jeff Davis wrote:

On Tue, 2023-05-09 at 12:02 -0700, Andres Freund wrote:

I don't think the approach of not having any sort of "registry" of
whether
anybody is waiting for the replay position to be updated is
feasible. Iterating over all walsenders slots is just too expensive -

Would it work to use a shared counter for the waiters (or, two
counters, one for physical and one for logical), and just early exit if
the count is zero?

That doesn't really fix the problem - once you have a single walsender
connected, performance is bad again.

Just to clarify, do you mean that if there is only one remaining active walsender that, say,
has been located at slot n, then we’d still have to loop from 0 to n in WalSndWakeup()?

I understood Jeff's proposal to just have an early exit if there are no
walsenders connected at all. But yes, even if we stopped iterating after
finding the number of slots we needed to, having to iterate over empty slots
would be an issue.

But TBH, even if we only did work for connected walsenders, I think this would
still be a performance issue. Acquiring O(#connected-walsenders) spinlocks for
every record is just too expensive.

Greetings,

Andres Freund

Hi,

On 2023-05-11 09:42:39 +0000, Zhijie Hou (Fujitsu) wrote:

I did some simple tests for this to see the performance impact on
the streaming replication, just share it here for reference.

1) sync primary-standby setup, load data on primary and count the time spent on
replication. the degradation will be more obvious as the value of max_wal_senders
increases.

FWIW, using syncrep likely under-estimates the overhead substantially, because
that includes a lot overhead on the WAL generating side. I saw well over 20%
overhead for the default max_wal_senders=10.

I just created a standby, shut it down, then ran a deterministically-sized
workload on the primary, started the standby, and measured how long it took to
catch up. I just used the log messages to measure the time.

2) Similar as 1) but count the time that the standby startup process spent on
replaying WAL(via gprof).

I don't think that's the case here, but IME gprof's overhead is so high, that
it can move bottlenecks quite drastically. The problem is that it adds code to
every function enter/exit - for simple functions, that overhead is much higher
than the "original" cost of the function.

gprof style instrumentation is good for things like code coverage, but for
performance evaluation it's normally better to use a sampling profiler like
perf. That also causes slowdowns, but largely only in places that already take
up substantial execution time.

Greetings,

Andres Freund

On Wed, 2023-05-17 at 12:34 -0700, Andres Freund wrote:

I understood Jeff's proposal to just have an early exit if there are
no
walsenders connected at all.

My suggestion was we early exit unless there is at least one *waiting*
walsender of the appropriate type. In other words, increment the
counter on entry to WalSndWait() and decrement on exit. I didn't look
in detail yet, so perhaps it's not easy/cheap to do that safely.

Regards,
Jeff Davis

Hi,

Thanks for working on the patch!

On 2023-05-15 20:09:00 +0530, Bharath Rupireddy wrote:

[1]
max_wal_senders = 100
before regression(ms) after regression(ms) v2 patch(ms)
13394.4013 14141.2615 13455.2543
Compared with before regression 5.58% 0.45%

max_wal_senders = 200
before regression(ms) after regression(ms) v2 patch(ms)
13280.8507 14597.1173 13632.0606
Compared with before regression 9.91% 1.64%

max_wal_senders = 300
before regression(ms) after regression(ms) v2 patch(ms)
13535.0232 16735.7379 13705.7135
Compared with before regression 23.65% 1.26%

Yes, the numbers with v2 patch look close to where we were before.
Thanks for confirming. Just wondering, where does this extra
0.45%/1.64%/1.26% coming from?

We still do more work for each WAL record than before, so I'd expect something
small. I'd say right now the main overhead with the patch comes from the
spinlock acquisitions in ConditionVariableBroadcast(), which happen even when
nobody is waiting.

I'll try to come up with a benchmark without the issues I pointed out in
/messages/by-id/20230517194331.ficfy5brpfq5lrmz@awork3.anarazel.de

+		ConditionVariableInit(&WalSndCtl->physicalWALSndCV);
+		ConditionVariableInit(&WalSndCtl->logicalWALSndCV);

It's not obvious to me that it's worth having two CVs, because it's more
expensive to find no waiters in two CVs than to find no waiters in one CV.

+	/*
+	 * We use condition variable (CV) to efficiently wake up walsenders in
+	 * WalSndWakeup().
+	 *
+	 * Every walsender prepares to sleep on a shared memory CV. Note that it
+	 * just prepares to sleep on the CV (i.e., adds itself to the CV's
+	 * waitlist), but not actually waits on the CV (IOW, it never calls
+	 * ConditionVariableSleep()). It still uses WaitEventSetWait() for waiting,
+	 * because CV infrastructure doesn't handle FeBe socket events currently.
+	 * The processes (startup process, walreceiver etc.) wanting to wake up
+	 * walsenders use ConditionVariableBroadcast(), which in turn calls
+	 * SetLatch(), helping walsenders come out of WaitEventSetWait().
+	 *
+	 * This approach is simple and efficient because, one doesn't have to loop
+	 * through all the walsenders slots, with a spinlock acquisition and
+	 * release for every iteration, just to wake up only the waiting
+	 * walsenders. It makes WalSndWakeup() callers' life easy.
+	 *
+	 * XXX: When available, WaitEventSetWait() can be replaced with its CV's
+	 * counterpart.

I don't really understand that XXX - the potential bright future would be to
add support for CVs into wait event sets, not to replace WES with a CV?

Greetings,

Andres Freund

Hi,

On 2023-05-17 12:53:15 -0700, Andres Freund wrote:

I'll try to come up with a benchmark without the issues I pointed out in
/messages/by-id/20230517194331.ficfy5brpfq5lrmz@awork3.anarazel.de

Here we go:

setup:

create primary
SELECT pg_create_physical_replication_slot('reserve', true);
create standby using pg_basebackup

create WAL:
psql -c CREATE TABLE testtable_logged(other_data int default 1);' && \
c=16; PGOPTIONS='-c synchronous_commit=off' /path-to-pgbench --random-seed=0 -n -c$c -j$c -t1000 -P1 -f <( echo "INSERT INTO testtable_logged SELECT generate_series(1, 1000)" ) && \
psql -c "SELECT pg_create_restore_point('end');"

benchmark:
rm -rf /tmp/test && \
cp -ar /srv/dev/pgdev-dev-standby /tmp/test && \
cp -ar /srv/dev/pgdev-dev/pg_wal/* /tmp/test/pg_wal/ && \
sync && \
/usr/bin/time -f '%es' /path-to-postgres -D /tmp/test -c recovery_target_action=shutdown -c recovery_target_name=end -c shared_buffers=1GB -c fsync=off

That way I can measure how long it takes to replay exactly the same WAL, and
also take profiles of exactly the same work, without influencing time results.

I copy the WAL files to the primary to ensure that walreceiver (standby) /
walsender (primary) performance doesn't make the result variability higher.

max_walsenders=10 max_walsenders=100
e101dfac3a5 reverted 7.01s 7.02s
093e5c57d50 / HEAD 8.25s 19.91s
bharat-v3 7.14s 7.13s

So indeed, bharat-v3 largely fixes the issue.

The regression of v3 compared to e101dfac3a5 reverted seems pretty constant at
~0.982x, independent of the concrete max_walsenders value. Which makes sense,
the work is constant.

To make it more extreme, I also tested a workload that is basically free to replay:

c=16; /srv/dev/build/m-opt/src/bin/pgbench/pgbench --random-seed=0 -n -c$c -j$c -t5000 -P1 -f <( echo "SELECT pg_logical_emit_message(false, 'c', 'a') FROM generate_series(1, 1000)" ) && psql -c "SELECT pg_create_restore_point('end');"

max_walsenders=10 max_walsenders=100
e101dfac3a5 reverted 1.70s 1.70s
093e5c57d50 / HEAD 3.00s 14.56s
bharat-v3 1.88s 1.88s

In this extreme workload we still regress by ~0.904x.

I'm not sure how much it's worth worrying about that - this is a quite
unrealistic testcase.

FWIW, if I just make WalSndWakeup() do nothing, I still see a very small, but
reproducible, overhead: 1.72s - that's just the cost of the additional
external function call.

If I add a no-waiters fastpath using proclist_is_empty() to
ConditionVariableBroadcast(), I get 1.77s. So the majority of the remaining
slowdown indeed comes from the spinlock acquisition in
ConditionVariableBroadcast().

Greetings,

Andres Freund

On Thu, May 18, 2023 at 1:23 AM Andres Freund <andres@anarazel.de> wrote:

On 2023-05-15 20:09:00 +0530, Bharath Rupireddy wrote:

[1]
max_wal_senders = 100
before regression(ms) after regression(ms) v2 patch(ms)
13394.4013 14141.2615 13455.2543
Compared with before regression 5.58% 0.45%

max_wal_senders = 200
before regression(ms) after regression(ms) v2 patch(ms)
13280.8507 14597.1173 13632.0606
Compared with before regression 9.91% 1.64%

max_wal_senders = 300
before regression(ms) after regression(ms) v2 patch(ms)
13535.0232 16735.7379 13705.7135
Compared with before regression 23.65% 1.26%

Yes, the numbers with v2 patch look close to where we were before.
Thanks for confirming. Just wondering, where does this extra
0.45%/1.64%/1.26% coming from?

We still do more work for each WAL record than before, so I'd expect something
small. I'd say right now the main overhead with the patch comes from the
spinlock acquisitions in ConditionVariableBroadcast(), which happen even when
nobody is waiting.

+             ConditionVariableInit(&WalSndCtl->physicalWALSndCV);
+             ConditionVariableInit(&WalSndCtl->logicalWALSndCV);

It's not obvious to me that it's worth having two CVs, because it's more
expensive to find no waiters in two CVs than to find no waiters in one CV.

I disagree. In the tight per-WAL record recovery loop, WalSndWakeup
wakes up logical walsenders for every WAL record, but it wakes up
physical walsenders only if the applied WAL record causes a TLI
switch. Therefore, the extra cost of spinlock acquire-release for per
WAL record applies only for logical walsenders. On the other hand, if
we were to use a single CV, we would be unnecessarily waking up (if at
all they are sleeping) physical walsenders for every WAL record -
which is costly IMO.

I still think separate CVs are good for selective wake ups given there
can be not so many TLI switch WAL records.

+      *
+      * XXX: When available, WaitEventSetWait() can be replaced with its CV's
+      * counterpart.

I don't really understand that XXX - the potential bright future would be to
add support for CVs into wait event sets, not to replace WES with a CV?

Yes, I meant it and modified that part to:

* XXX: A desirable future improvement would be to add support for CVs into
* WaitEventSetWait().

FWIW, if I just make WalSndWakeup() do nothing, I still see a very small, but
reproducible, overhead: 1.72s - that's just the cost of the additional
external function call.

Hm, this is unavoidable.

If I add a no-waiters fastpath using proclist_is_empty() to
ConditionVariableBroadcast(), I get 1.77s. So the majority of the remaining
slowdown indeed comes from the spinlock acquisition in
ConditionVariableBroadcast().

Acquiring spinlock for every replayed WAL record seems not great. In
general, this problem exists for CV infrastructure as a whole if
ConditionVariableBroadcast()/CVB() is called in a loop/hot path. I
think this can be proven easily by doing something like - select
pg_replication_origin_session_setup()/pg_wal_replay_resume()/pg_create_physical_replication_slot()
from generate_series(1, 1000000...);, all of these functions end up in
CVB().

Do you think adding a fastpath exit when no waiters to CVB() is worth
implementing? Something like - an atomic state variable to each CV,
similar to LWLock's state variable, setting it when adding waiters and
resetting it when removing waiters, CVB() atomically reading the state
for fastpath (of course, we need memory barriers here). This might
complicate things as each CV structure gets an extra state variable (4
bytes), memory barriers, and atomic writes and reads.

Or given the current uses of CVB() with no callers except recovery
calling it in a hot path with patch, maybe we can add an atomic waiter
count to WalSndCtl, incrementing it atomically in WalSndWait() before
the wait, decrementing it after the wait, and a fastpath in
WalSndWakeup() reading it atomically to avoid CVB() calls. IIUC, this
is something Jeff proposed upthread.

Thoughts?

Please find the attached v4 patch addressing the review comment (not
the fastpath one).

--
Bharath Rupireddy
PostgreSQL Contributors Team
RDS Open Source Databases
Amazon Web Services: https://aws.amazon.com

At Thu, 18 May 2023 20:11:11 +0530, Bharath Rupireddy <bharath.rupireddyforpostgres@gmail.com> wrote in

+             ConditionVariableInit(&WalSndCtl->physicalWALSndCV);
+             ConditionVariableInit(&WalSndCtl->logicalWALSndCV);

It's not obvious to me that it's worth having two CVs, because it's more
expensive to find no waiters in two CVs than to find no waiters in one CV.

I disagree. In the tight per-WAL record recovery loop, WalSndWakeup
wakes up logical walsenders for every WAL record, but it wakes up
physical walsenders only if the applied WAL record causes a TLI
switch. Therefore, the extra cost of spinlock acquire-release for per
WAL record applies only for logical walsenders. On the other hand, if
we were to use a single CV, we would be unnecessarily waking up (if at
all they are sleeping) physical walsenders for every WAL record -
which is costly IMO.

As I was reading this, I start thinking that one reason for the
regression could be to exccessive frequency of wakeups during logical
replication. In physical replication, we make sure to avoid exccessive
wakeups when the stream is tightly packed. I'm just wondering why
logical replication doesn't (or can't) do the same thing, IMHO.

regards.

--
Kyotaro Horiguchi
NTT Open Source Software Center

On Friday, May 19, 2023 11:08 AM Kyotaro Horiguchi <horikyota.ntt@gmail.com> wrote:

At Thu, 18 May 2023 20:11:11 +0530, Bharath Rupireddy
<bharath.rupireddyforpostgres@gmail.com> wrote in

+             ConditionVariableInit(&WalSndCtl->physicalWALSndCV);
+             ConditionVariableInit(&WalSndCtl->logicalWALSndCV);

It's not obvious to me that it's worth having two CVs, because it's more
expensive to find no waiters in two CVs than to find no waiters in one CV.

I disagree. In the tight per-WAL record recovery loop, WalSndWakeup
wakes up logical walsenders for every WAL record, but it wakes up
physical walsenders only if the applied WAL record causes a TLI
switch. Therefore, the extra cost of spinlock acquire-release for per
WAL record applies only for logical walsenders. On the other hand, if
we were to use a single CV, we would be unnecessarily waking up (if at
all they are sleeping) physical walsenders for every WAL record -
which is costly IMO.

As I was reading this, I start thinking that one reason for the
regression could be to exccessive frequency of wakeups during logical
replication. In physical replication, we make sure to avoid exccessive
wakeups when the stream is tightly packed. I'm just wondering why
logical replication doesn't (or can't) do the same thing, IMHO.

I thought(from the e101dfa's commit message) physical walsenders can't send
data until it's been flushed, so it only gets wakeup at the time of flush or TLI
switch. For logical walsender, it can start to decode changes after the change
is applied, and to avoid the case if the walsender is asleep, and there's work
to be done, it wakeup logical walsender when applying each record.

Or maybe you mean to wakeup(ConditionVariableBroadcast) walsender after
applying some wal records like[1]--- a/src/backend/access/transam/xlogrecovery.c +++ b/src/backend/access/transam/xlogrecovery.c @@ -1833,6 +1833,7 @@ ApplyWalRecord(XLogReaderState *xlogreader, XLogRecord *record, TimeLineID *repl { ErrorContextCallback errcallback; bool switchedTLI = false; + static int nreplay = 0;, But it seems it may delay the wakeup of
walsender a bit(the walsender may be asleep before reaching the threshold).

[1] 
--- a/src/backend/access/transam/xlogrecovery.c
+++ b/src/backend/access/transam/xlogrecovery.c
@@ -1833,6 +1833,7 @@ ApplyWalRecord(XLogReaderState *xlogreader, XLogRecord *record, TimeLineID *repl
 {
 	ErrorContextCallback errcallback;
 	bool		switchedTLI = false;
+	static int	nreplay = 0;

 	/* Setup error traceback support for ereport() */
 	errcallback.callback = rm_redo_error_callback;
@@ -1957,8 +1958,12 @@ ApplyWalRecord(XLogReaderState *xlogreader, XLogRecord *record, TimeLineID *repl
 	 *    be created otherwise)
 	 * ------
 	 */
-	if (AllowCascadeReplication())
+	if (AllowCascadeReplication() &&
+		nreplay++ == 100)
+	{
 		WalSndWakeup(switchedTLI, true);
+		nreplay = 0;
+	}

Best Regards,
Hou zj

Hi,

On 2023-05-19 12:07:56 +0900, Kyotaro Horiguchi wrote:

At Thu, 18 May 2023 20:11:11 +0530, Bharath Rupireddy <bharath.rupireddyforpostgres@gmail.com> wrote in

+             ConditionVariableInit(&WalSndCtl->physicalWALSndCV);
+             ConditionVariableInit(&WalSndCtl->logicalWALSndCV);

It's not obvious to me that it's worth having two CVs, because it's more
expensive to find no waiters in two CVs than to find no waiters in one CV.

I disagree. In the tight per-WAL record recovery loop, WalSndWakeup
wakes up logical walsenders for every WAL record, but it wakes up
physical walsenders only if the applied WAL record causes a TLI
switch. Therefore, the extra cost of spinlock acquire-release for per
WAL record applies only for logical walsenders. On the other hand, if
we were to use a single CV, we would be unnecessarily waking up (if at
all they are sleeping) physical walsenders for every WAL record -
which is costly IMO.

As I was reading this, I start thinking that one reason for the
regression could be to exccessive frequency of wakeups during logical
replication. In physical replication, we make sure to avoid exccessive
wakeups when the stream is tightly packed. I'm just wondering why
logical replication doesn't (or can't) do the same thing, IMHO.

It's possible we could try to reduce the frequency by issuing wakeups only at
specific points. The most obvious thing to do would be to wake only when
waiting for more WAL or when crossing a page boundary, or such. Unfortunately
that could easily lead to deadlocks, because the startup process might be
blocked waiting for a lock, held by a backend doing logical decoding - which
can't progress until the startup process wakes the backend up.

So I don't think this is promising avenue in the near term.

Greetings,

Andres Freund

Hi,

On 2023-05-18 20:11:11 +0530, Bharath Rupireddy wrote:

Please find the attached v4 patch addressing the review comment (not
the fastpath one).

I pushed a mildly edited version of this. I didn't like the name of the CVs
much, so I renamed them to wal_flush_cv/wal_replay_cv. I also did some minor
comment polishing.

Greetings,

Andres Freund

Hi,

On Monday, May 22, 2023 12:11 AM Andres Freund <andres@anarazel.de> wrote:

On 2023-05-19 12:07:56 +0900, Kyotaro Horiguchi wrote:

At Thu, 18 May 2023 20:11:11 +0530, Bharath Rupireddy

<bharath.rupireddyforpostgres@gmail.com> wrote in

+

ConditionVariableInit(&WalSndCtl->physicalWALSndCV);

+ ConditionVariableInit(&WalSndCtl->logicalWALSndCV);

It's not obvious to me that it's worth having two CVs, because it's more
expensive to find no waiters in two CVs than to find no waiters in one CV.

I disagree. In the tight per-WAL record recovery loop, WalSndWakeup
wakes up logical walsenders for every WAL record, but it wakes up
physical walsenders only if the applied WAL record causes a TLI
switch. Therefore, the extra cost of spinlock acquire-release for per
WAL record applies only for logical walsenders. On the other hand, if
we were to use a single CV, we would be unnecessarily waking up (if at
all they are sleeping) physical walsenders for every WAL record -
which is costly IMO.

As I was reading this, I start thinking that one reason for the
regression could be to exccessive frequency of wakeups during logical
replication. In physical replication, we make sure to avoid exccessive
wakeups when the stream is tightly packed. I'm just wondering why
logical replication doesn't (or can't) do the same thing, IMHO.

It's possible we could try to reduce the frequency by issuing wakeups only at
specific points. The most obvious thing to do would be to wake only when
waiting for more WAL or when crossing a page boundary, or such.
Unfortunately
that could easily lead to deadlocks, because the startup process might be
blocked waiting for a lock, held by a backend doing logical decoding - which
can't progress until the startup process wakes the backend up.

Just out of curiosity about the mentioned deadlock scenario, no comment on the
committed patch.

About "a backend doing logical decoding", do you mean the case when a user
start a backend and invoke pg_logical_slot_get_changes() to do the logical
decoding ? If so, it seems the logical decoding in a backend won't be waked up
by startup process because the backend won't be registered as a walsender so
the backend won't be found in WalSndWakeup().

Or do you mean the deadlock between the real logical walsender and startup
process ? (I might miss something) I think the logical decoding doesn't lock
the target user relation when decoding because it normally can get the needed
information from WAL. Besides, the walsender sometimes will lock the system
table(e.g. use RelidByRelfilenumber() to get the relid) but it will unlock it
after finishing systable scan.

So, if possible, would you be able to share some details about the deadlock
case you mentioned earlier? it's helpful as it can prevent similar problems in
the future development.

Best Regards,
Hou zj

Hi,

On 2023-05-22 12:15:07 +0000, Zhijie Hou (Fujitsu) wrote:

About "a backend doing logical decoding", do you mean the case when a user
start a backend and invoke pg_logical_slot_get_changes() to do the logical
decoding ? If so, it seems the logical decoding in a backend won't be waked up
by startup process because the backend won't be registered as a walsender so
the backend won't be found in WalSndWakeup().

I meant logical decoding happening inside a walsender instance.

Or do you mean the deadlock between the real logical walsender and startup
process ? (I might miss something) I think the logical decoding doesn't lock
the target user relation when decoding because it normally can get the needed
information from WAL.

It does lock catalog tables briefly. There's no guarantee that such locks are
released immediately. I forgot the details, but IIRC there's some outfuncs
(enum?) that intentionally delay releasing locks till transaction commit.

Greetings,

Andres Freund

On Tuesday, May 23, 2023 1:53 AM Andres Freund <andres@anarazel.de> wrote:

On 2023-05-22 12:15:07 +0000, Zhijie Hou (Fujitsu) wrote:

About "a backend doing logical decoding", do you mean the case when a

user

start a backend and invoke pg_logical_slot_get_changes() to do the logical
decoding ? If so, it seems the logical decoding in a backend won't be waked

up

by startup process because the backend won't be registered as a walsender

so

the backend won't be found in WalSndWakeup().

I meant logical decoding happening inside a walsender instance.

Or do you mean the deadlock between the real logical walsender and startup
process ? (I might miss something) I think the logical decoding doesn't lock
the target user relation when decoding because it normally can get the

needed

information from WAL.

It does lock catalog tables briefly. There's no guarantee that such locks are
released immediately. I forgot the details, but IIRC there's some outfuncs
(enum?) that intentionally delay releasing locks till transaction commit.

Thanks for the explanation !

I understand that the startup process can take lock on the catalog(when
replaying record) which may conflict with the lock in walsender.

But in walsender, I think we only start transaction after entering
ReorderBufferProcessTXN(), and the transaction started here will be released
soon after processing and outputting the decoded transaction's data(as the
comment in ReorderBufferProcessTXN() says:" all locks acquired in here to be
released, not reassigned to the parent and we do not want any database access
have persistent effects.").

Besides, during the process and output of the decoded transaction, the
walsender won't wait for the wakeup of startup process(e.g.
WalSndWaitForWal()), it only waits if the data is being sent to subscriber. So
it seems the lock conflict here won't cause the deadlock for now, although it
may have a risk if we change this logic later. Sorry if I missed something, and
thanks again for your patience in explaining.

Best Regards,
Hou zj

Hi,

On 2023-05-24 05:53:51 +0000, Zhijie Hou (Fujitsu) wrote:

On Tuesday, May 23, 2023 1:53 AM Andres Freund <andres@anarazel.de> wrote:

On 2023-05-22 12:15:07 +0000, Zhijie Hou (Fujitsu) wrote:

About "a backend doing logical decoding", do you mean the case when a

user

start a backend and invoke pg_logical_slot_get_changes() to do the logical
decoding ? If so, it seems the logical decoding in a backend won't be waked

up

by startup process because the backend won't be registered as a walsender

so

the backend won't be found in WalSndWakeup().

I meant logical decoding happening inside a walsender instance.

Or do you mean the deadlock between the real logical walsender and startup
process ? (I might miss something) I think the logical decoding doesn't lock
the target user relation when decoding because it normally can get the

needed

information from WAL.

It does lock catalog tables briefly. There's no guarantee that such locks are
released immediately. I forgot the details, but IIRC there's some outfuncs
(enum?) that intentionally delay releasing locks till transaction commit.

Thanks for the explanation !

I understand that the startup process can take lock on the catalog(when
replaying record) which may conflict with the lock in walsender.

But in walsender, I think we only start transaction after entering
ReorderBufferProcessTXN(), and the transaction started here will be released
soon after processing and outputting the decoded transaction's data(as the
comment in ReorderBufferProcessTXN() says:" all locks acquired in here to be
released, not reassigned to the parent and we do not want any database access
have persistent effects.").

It's possible that there's no immediate danger - but I wouldn't want to bet on
it staying that way. Think about things like streaming out large transactions
etc. There also are potential dangers outside of plain things like locks -
there could be a recovery conflicts on the snapshot or such (although that
normally should be prevented via hot_standby_feedback or such).

Even if there's no hard deadlock issue - not waking up a
walsender-in-logical-decoding that's currently waiting because (replay_count %
N) != 0 means that the walsender might be delayed for quite a while - there
might not be any further records from the primary in the near future.

I don't think any approach purely based on record counts has any chance to
work well. You could combine it with something else, e.g. with always waking
up in XLogPageRead() and WaitForWALToBecomeAvailable(). But then you end up
with something relatively complicated again.

Greetings,

Andres Freund