Message-ID: <369ae611-8822-f499-87cd-58ad0d60c60c@enterprisedb.com>
Date: Fri, 18 Mar 2022 18:12:20 +0100
MIME-Version: 1.0
User-Agent: Mozilla/5.0 (X11; Linux x86_64; rv:91.0) Gecko/20100101
 Thunderbird/91.6.2
Subject: Re: Column Filtering in Logical Replication
Content-Language: en-US
From: Tomas Vondra <tomas.vondra@enterprisedb.com>
To: Amit Kapila <amit.kapila16@gmail.com>
Cc: "houzj.fnst@fujitsu.com" <houzj.fnst@fujitsu.com>,
 Peter Eisentraut <peter.eisentraut@enterprisedb.com>,
 Alvaro Herrera <alvherre@alvh.no-ip.org>,
 Justin Pryzby <pryzby@telsasoft.com>, Rahila Syed <rahilasyed90@gmail.com>,
 Peter Smith <smithpb2250@gmail.com>,
 pgsql-hackers <pgsql-hackers@postgresql.org>,
 "shiy.fnst@fujitsu.com" <shiy.fnst@fujitsu.com>
References: <202201120041.p24wvsfcsope@alvherre.pgsql>
 <OS0PR01MB571614E4A39DD33669D5AFD6940A9@OS0PR01MB5716.jpnprd01.prod.outlook.com>
 <e4b0fb99-3d74-7333-1e71-74f990b641ee@enterprisedb.com>
 <78b8d385-57cb-9a3f-cfe5-9f300f15eced@enterprisedb.com>
 <822a8e40-287c-59ff-0ea9-35eb759f4fe6@enterprisedb.com>
 <CAA4eK1J9UDnM-xN7viu4eO_DDL_PqMG9F6ZsskqEU7snujXi+A@mail.gmail.com>
 <2b8471f9-3849-c91f-ef82-9181d4bca0a7@enterprisedb.com>
 <CAA4eK1KUpOnFam+2bBuGGX-_pZbmO_ShJV6G=GT-RyM7gQSvWg@mail.gmail.com>
 <16e83ce3-8415-b732-37b2-c3329a2c13a1@enterprisedb.com>
 <OS0PR01MB57164514E1DE1E579B0B6C46940F9@OS0PR01MB5716.jpnprd01.prod.outlook.com>
 <CAA4eK1KvFAygPbFu=cUvnqhmTLPpjzqp8p4UNSsLkiZmvFp8oQ@mail.gmail.com>
 <bc6918cc-2025-6c91-2ca4-c237af67e97d@enterprisedb.com>
 <f217341d-6841-390d-3dd2-89f9d1de17fe@enterprisedb.com>
 <f90d2b03-4462-ce95-a524-d91464e797c8@enterprisedb.com>
 <CAA4eK1LpBFU49Ohbnk=dv_v9YP+Kqh1+Sf8i++_s-QhD1Gy4Qw@mail.gmail.com>
 <3162f7f0-86ac-e3a9-dc55-0a660cb9bab1@enterprisedb.com>
In-Reply-To: <3162f7f0-86ac-e3a9-dc55-0a660cb9bab1@enterprisedb.com>
Content-Type: text/plain; charset=UTF-8
Content-Transfer-Encoding: 7bit
Archived-At: <https://www.postgresql.org/message-id/369ae611-8822-f499-87cd-58ad0d60c60c%40enterprisedb.com>
Precedence: bulk


On 3/18/22 15:43, Tomas Vondra wrote:
> 
> 
> On 3/18/22 06:52, Amit Kapila wrote:
>> On Fri, Mar 18, 2022 at 12:47 AM Tomas Vondra
>> <tomas.vondra@enterprisedb.com> wrote:
>>>
>>> I pushed the second fix. Interestingly enough, wrasse failed in the
>>> 013_partition test. I don't see how that could be caused by this
>>> particular commit, though - see the pgsql-committers thread [1].
>>>
>>
>> I have a theory about what's going on here. I think this is due to a
>> test added in your previous commit c91f71b9dc. The newly added test
>> added hangs in tablesync because there was no apply worker to set the
>> state to SUBREL_STATE_CATCHUP which blocked tablesync workers from
>> proceeding.
>>
>> See below logs from pogona [1].
>> 2022-03-18 01:33:15.190 CET [2551176][client
>> backend][3/74:0][013_partition.pl] LOG:  statement: ALTER SUBSCRIPTION
>> sub2 SET PUBLICATION pub_lower_level, pub_all
>> 2022-03-18 01:33:15.354 CET [2551193][logical replication
>> worker][4/57:0][] LOG:  logical replication apply worker for
>> subscription "sub2" has started
>> 2022-03-18 01:33:15.605 CET [2551176][client
>> backend][:0][013_partition.pl] LOG:  disconnection: session time:
>> 0:00:00.415 user=bf database=postgres host=[local]
>> 2022-03-18 01:33:15.607 CET [2551209][logical replication
>> worker][3/76:0][] LOG:  logical replication table synchronization
>> worker for subscription "sub2", table "tab4_1" has started
>> 2022-03-18 01:33:15.609 CET [2551211][logical replication
>> worker][5/11:0][] LOG:  logical replication table synchronization
>> worker for subscription "sub2", table "tab3" has started
>> 2022-03-18 01:33:15.617 CET [2551193][logical replication
>> worker][4/62:0][] LOG:  logical replication apply worker for
>> subscription "sub2" will restart because of a parameter change
>>
>> You will notice that the apply worker is never restarted after a
>> parameter change. The reason was that the particular subscription
>> reaches the limit of max_sync_workers_per_subscription after which we
>> don't allow to restart the apply worker. I think you might want to
>> increase the values of
>> max_sync_workers_per_subscription/max_logical_replication_workers to
>> make it work.
>>
> 
> Hmmm. So the theory is that in most runs we manage to sync the tables
> faster than starting the workers, so we don't hit the limit. But on some
> machines the sync worker takes a bit longer, we hit the limit. Seems
> possible, yes. Unfortunately we don't seem to log anything when we hit
> the limit, so hard to say for sure :-( I suggest we add a WARNING
> message to logicalrep_worker_launch or something. Not just because of
> this test, it seems useful in general.
> 
> However, how come we don't retry the sync? Surely we don't just give up
> forever, that'd be a pretty annoying behavior. Presumably we just end up
> sleeping for a long time before restarting the sync worker, somewhere.
> 

I tried lowering the max_sync_workers_per_subscription to 1 and making
the workers to run for a couple seconds (doing some CPU intensive
stuff), but everything still works just fine.

Looking a bit closer at the logs (from pogona and other), I doubt this
is about hitting the max_sync_workers_per_subscription limit. Notice we
start two sync workers, but neither of them ever completes. So we never
update the sync status or start syncing the remaining tables.

So the question is why those two sync workers never complete - I guess
there's some sort of lock wait (deadlock?) or infinite loop.


regards

-- 
Tomas Vondra
EnterpriseDB: http://www.enterprisedb.com
The Enterprise PostgreSQL Company