Re: Logical replication stops dropping used initial-sync replication slots

On Tue, Mar 22, 2022 at 12:26:46PM +0100, hubert depesz lubaczewski wrote:
> On Tue, Mar 22, 2022 at 12:32:41PM +0530, vignesh C wrote:
> > > That wouldn't do me any good. The server I'm trying to upgrade now is
> > > test bench to make sure that I can upgrade using logical replication *at
> > > all*.
> > > Once I will have verified that I can, I have couple hundred servers to
> > > upgrade, that will have concurrent access all the time.
> > Is it possible to get a reproducible test or a script for this problem?
>
> Well, given that we're talking about 38GB database with 60k tables
> i find that unlikely.
>
> But I'll try if I can figure out a way to replicate the problem with
> something that is shareable.

OK. I don't think it will be simple/possible to replicate.

Reason:

Did setup 10 separate environments, all with the same database on bionic
12.9.

Then I created publication with all tables in specific schemas, and
subscribed to it from separate focal pg 14.2 servers.

In total, used 20 servers to replicate the test 10 times.

Effect: in one case replication didn't finish initial sync.

Currently, it's 2022-03-25 08:32:14.10081+00, and on the one source that
had failed with subscription i see:
slot_name | plugin | slot_type | datoid | database | temporary | active | active_pid | xmin | catalog_xmin | restart_lsn | confirmed_flush_lsn
---------------------------------------------+----------+-----------+--------+----------+-----------+--------+------------+------+--------------+--------------+---------------------
focal14 | pgoutput | logical | 16606 | dbname | f | f | | | 161822728 | 8E9/3E70BB58 | 8E9/3E70BB58
pg_3548429_sync_3343043_7077521990523695096 | pgoutput | logical | 16606 | dbname | f | t | 32385 | | 161824826 | 8F0/18327650 | 8F0/1ABF89C0
pg_3548429_sync_3079712_7077521990523695096 | pgoutput | logical | 16606 | dbname | f | t | 32378 | | 161824826 | 8F0/18327650 | 8F0/1ABF89C0
pg_3548429_sync_3145162_7077521990523695096 | pgoutput | logical | 16606 | dbname | f | t | 32386 | | 161824826 | 8F0/18327650 | 8F0/1ABF89C0
pg_3548429_sync_2993718_7077521990523695096 | pgoutput | logical | 16606 | dbname | f | t | 32387 | | 161824826 | 8F0/18327650 | 8F0/1ABF89C0
pg_3548429_sync_3355696_7077521990523695096 | pgoutput | logical | 16606 | dbname | f | t | 32379 | | 161824826 | 8F0/18327650 | 8F0/1ABF89C0
pg_3548429_sync_3099460_7077521990523695096 | pgoutput | logical | 16606 | dbname | f | t | 32380 | | 161824826 | 8F0/18327650 | 8F0/1ABF89C0
pg_3548429_sync_3162651_7077521990523695096 | pgoutput | logical | 16606 | dbname | f | t | 32381 | | 161824826 | 8F0/18327650 | 8F0/1ABF89C0
pg_3548429_sync_3157454_7077521990523695096 | pgoutput | logical | 16606 | dbname | f | t | 32382 | | 161824826 | 8F0/18327650 | 8F0/1ABF89C0
pg_3548429_sync_3084198_7077521990523695096 | pgoutput | logical | 16606 | dbname | f | t | 32383 | | 161824826 | 8F0/18327650 | 8F0/1ABF89C0
pg_3548429_sync_3142573_7077521990523695096 | pgoutput | logical | 16606 | dbname | f | t | 32384 | | 161824826 | 8F0/18327650 | 8F0/1ABF89C0
(11 rows)

pg_stat_replication shows 10 sync connections, and that's it. their sent_lsn,
write_lsn, flush_lsn, replay_lsn seems to be progressing nicely, but nothing is
changing.

pg_stat_activity contains:

=# select xact_start, query_start, backend_type, query from pg_stat_activity where state is distinct from 'idle';
xact_start │ query_start │ backend_type │ query
═══════════════════════════════╪═══════════════════════════════╪══════════════════════════════╪══════════════════════════════════════════════════════════════════════════════════════════════════════════════════════════════════════════════
[null] │ [null] │ autovacuum launcher │
[null] │ 2022-03-24 20:45:30.757582+00 │ walsender │ START_REPLICATION SLOT "pg_3548429_sync_2993718_7077521990523695096" LOGICAL 8E9/40FF0170 (proto_version '1', publication_names '"focal14"')
[null] │ [null] │ pglogical supervisor │
[null] │ [null] │ logical replication launcher │
[null] │ 2022-03-24 20:45:30.730818+00 │ walsender │ START_REPLICATION SLOT "pg_3548429_sync_3343043_7077521990523695096" LOGICAL 8E9/40FF0100 (proto_version '1', publication_names '"focal14"')
[null] │ 2022-03-24 20:45:31.65015+00 │ walsender │ START_REPLICATION SLOT "pg_3548429_sync_3079712_7077521990523695096" LOGICAL 8E9/40FEFF60 (proto_version '1', publication_names '"focal14"')
[null] │ 2022-03-24 20:45:30.733366+00 │ walsender │ START_REPLICATION SLOT "pg_3548429_sync_3145162_7077521990523695096" LOGICAL 8E9/40FF0138 (proto_version '1', publication_names '"focal14"')
[null] │ 2022-03-24 20:45:30.76285+00 │ walsender │ START_REPLICATION SLOT "pg_3548429_sync_3355696_7077521990523695096" LOGICAL 8E9/40FEFF98 (proto_version '1', publication_names '"focal14"')
[null] │ 2022-03-24 20:45:31.663299+00 │ walsender │ START_REPLICATION SLOT "pg_3548429_sync_3099460_7077521990523695096" LOGICAL 8E9/40FEFFD0 (proto_version '1', publication_names '"focal14"')
[null] │ 2022-03-24 20:45:31.676412+00 │ walsender │ START_REPLICATION SLOT "pg_3548429_sync_3162651_7077521990523695096" LOGICAL 8E9/40FF0020 (proto_version '1', publication_names '"focal14"')
[null] │ 2022-03-24 20:45:31.691807+00 │ walsender │ START_REPLICATION SLOT "pg_3548429_sync_3157454_7077521990523695096" LOGICAL 8E9/40FF0058 (proto_version '1', publication_names '"focal14"')
[null] │ 2022-03-24 20:45:31.69548+00 │ walsender │ START_REPLICATION SLOT "pg_3548429_sync_3084198_7077521990523695096" LOGICAL 8E9/40FF0090 (proto_version '1', publication_names '"focal14"')
[null] │ 2022-03-24 20:45:30.974833+00 │ walsender │ START_REPLICATION SLOT "pg_3548429_sync_3142573_7077521990523695096" LOGICAL 8E9/40FF00C8 (proto_version '1', publication_names '"focal14"')
2022-03-25 08:35:27.971161+00 │ 2022-03-25 08:35:27.971161+00 │ client backend │ select xact_start, query_start, backend_type, query from pg_stat_activity where state is distinct from 'idle';
[null] │ [null] │ background writer │
[null] │ [null] │ checkpointer │
[null] │ [null] │ walwriter │
(17 rows)

So, it looks to me that there is some random-ish condition that causes
the problem.

I tried to insulate pgs from the world as well as I could: no
monitoring, no cron, no external access. Just replication and my simple
load generator, running loop:

CREATE TABLE depesz_test as SELECT i, repeat('payload', 50) as payload FROM generate_series(1,100000) i;
CREATE INDEX depesz_test_idx on depesz_test(i);
DROP TABLE depesz_test;

every minute.

I'm out of ideas. The good-ish news is that when I tried replication in
smaller sets (30k tables, not 60k), and/or with just
2 max_sync_workers_per_subscription, and not 10, it never failed. so
I guess I'll go that way.

Best regards,

depesz