On Sat, 20 Apr 2024 at 10:30, Alexander Lakhin <exclusion@gmail.com> wrote:
>
> Hello Michael and Robert,
>
> 20.04.2024 05:57, Michael Paquier wrote:
> > On Fri, Apr 19, 2024 at 01:57:41PM -0400, Robert Haas wrote:
> >> It looks to me like in the first run it took 3 minutes for the
> >> replay_lsn to catch up to the desired value, and in the second run,
> >> two seconds. I think I have seen previous instances where something
> >> similar happened, although in those cases I did not stop to record any
> >> details. Have others seen this? Is there something we can/should do
> >> about it?
> > FWIW, I've also seen delays as well with this test on a few occasions.
> > Thanks for mentioning it.
>
> It reminds me of
> https://www.postgresql.org/message-id/858a7622-2c81-1687-d1df-1322dfcb2e72%40gmail.com
Thanks Alexander for the test, I was able to reproduce the issue with
the test you shared and also verify that the patch at [1] fixes the
same. This is the same issue where the apply worker for test_tab2_sub
was getting started after 180 seconds because the common latch (which
is used for worker attached, subscription creation/modification and
apply worker process exit) was getting reset when the other
subscription test_tab1_sub's worker gets started. The same can be seen
from the logs:
2024-04-22 20:47:52.009 IST [323280] 026_stats.pl LOG: statement: BEGIN;
2024-04-22 20:47:52.009 IST [323280] 026_stats.pl LOG: statement:
SELECT pg_sleep(0.5);
2024-04-22 20:47:52.426 IST [323281] LOG: logical replication apply
worker for subscription "test_tab1_sub" has started
2024-04-22 20:47:52.511 IST [323280] 026_stats.pl LOG: statement:
CREATE TABLE test_tab2(a int primary key);
2024-04-22 20:47:52.518 IST [323280] 026_stats.pl LOG: statement:
INSERT INTO test_tab2 VALUES (1);
2024-04-22 20:47:52.519 IST [323280] 026_stats.pl LOG: statement: COMMIT;
2024-04-22 20:47:52.540 IST [323286] 026_stats.pl LOG: statement:
CREATE SUBSCRIPTION test_tab2_sub CONNECTION 'port=56685
host=/tmp/RwzpQrVMYH dbname=postgres' PUBLICATION test_tab2_pub
2024-04-22 20:50:52.658 IST [326265] LOG: logical replication apply
worker for subscription "test_tab2_sub" has started
2024-04-22 20:50:52.668 IST [326267] LOG: logical replication table
synchronization worker for subscription "test_tab2_sub", table
"test_tab2" has started
[1] - https://www.postgresql.org/message-id/CALDaNm10R7L0Dxq%2B-J%3DPp3AfM_yaokpbhECvJ69QiGH8-jQquw%40mail.gmail.com
Regards,
Vignesh