Thread: BUG #18155: Logical Apply Worker Timeout During TableSync Causes Either Stuckness or Data Loss
BUG #18155: Logical Apply Worker Timeout During TableSync Causes Either Stuckness or Data Loss
From
PG Bug reporting form
Date:
The following bug has been logged on the website: Bug reference: 18155 Logged by: Drew Callahan Email address: callaan@amazon.com PostgreSQL version: 16.0 Operating system: Ubuntu Description: Depending on the Major Version an untimely timeout or termination of the main apply worker when the table apply worker is waiting for the subscription relstate to change to SUBREL_STATE_CATCHUP can lead to one of two really painful experiences. If on Rel14+, the untimely exit can lead to the main apply worker becoming indefinitely stuck while it waits for a table apply worker, that has already exited and won't be launched again, to change the subscription relstate to SUBREL_STATE_SYNCDONE. In order to unwedge, a system restart is required to clear the corrupted transient subscription relstate data. If on Rel13+, then the untimely exit can lead to silent data loss. This will occur if the table apply worker performed a copy at LSN X. If the main apply worker is now at LSN Y > X, the system requires the table sync worker to apply all changes between X & Y that were skipped by the main apply worker in a catch up phase. Due to the untimely exit, the table apply worker will assume that the main apply worker was actually behind, skip the catch up work, and exit. As a result, all data between X & Y will be lost for that table. The cause of both issues is that wait_for_worker_state_change() is handled like a void function by the table apply worker. However, if the main apply worker does not currently exist on the system due to some issue such as a timeout triggering it to safely exit, then the function will return *before* the state change has occurred and return false. The fix for this issue is relatively, we just need to validate the state actually did change. If it did not, then we can circle back later to check again which is relatively cheap on Rel14+. Pasted a potential solution below. A solution on Rel13- would want to introduce a retry loop in wait_for_worker_state_change() to avoid having to do the entire COPY again first which is very expensive on large tables. diff --git a/src/backend/replication/logical/tablesync.c b/src/backend/replication/logical/tablesync.c index e2cee92cf2..25be978e15 100644 --- a/src/backend/replication/logical/tablesync.c +++ b/src/backend/replication/logical/tablesync.c @@ -1529,10 +1529,30 @@ copy_table_done: SpinLockRelease(&MyLogicalRepWorker->relmutex); /* - * Finally, wait until the leader apply worker tells us to catch up and - * then return to let LogicalRepApplyLoop do it. + * Finally, wait until the main apply worker tells us to catch up and then + * return to let LogicalRepApplyLoop do it. If this wait fails due to the + * apply worker not being up, we fail this attempt and force a retry. */ - wait_for_worker_state_change(SUBREL_STATE_CATCHUP); + if (!wait_for_worker_state_change(SUBREL_STATE_CATCHUP)) + { + ereport(ERROR, + (errcode(ERRCODE_INTERNAL_ERROR), + errmsg("logical replication table synchronization worker for subscription \"%s\", relid \"%u\" " + "unable to finish due to main apply worker being unavailable.", + MySubscription->name, MyLogicalRepWorker->relid), + errhint("this worker will attempt to sync the table again once logical replication has resumed"))); + } + + if (MyLogicalRepWorker->relstate != SUBREL_STATE_CATCHUP) + { + ereport(ERROR, + (errcode(ERRCODE_INTERNAL_ERROR), + errmsg("logical replication table synchronization worker for subscription \"%s\", relid \"%u\" " + "unable to make progress while apply worker is down", + MySubscription->name, MyLogicalRepWorker->relid), + errhint("this worker will attempt to sync the table again once logical replication has resumed"))); + } + return slotname; }
Re: BUG #18155: Logical Apply Worker Timeout During TableSync Causes Either Stuckness or Data Loss
From
Amit Kapila
Date:
On Fri, Oct 13, 2023 at 6:43 AM PG Bug reporting form <noreply@postgresql.org> wrote: > > Depending on the Major Version an untimely timeout or termination of the > main apply worker when the table apply worker is waiting for the > subscription relstate to change to SUBREL_STATE_CATCHUP can lead to one of > two really painful experiences. > > If on Rel14+, the untimely exit can lead to the main apply worker becoming > indefinitely stuck while it waits for a table apply worker, that has already > exited and won't be launched again, to change the subscription relstate to > SUBREL_STATE_SYNCDONE. In order to unwedge, a system restart is required to > clear the corrupted transient subscription relstate data. > > If on Rel13+, then the untimely exit can lead to silent data loss. This will > occur if the table apply worker performed a copy at LSN X. If the main apply > worker is now at LSN Y > X, the system requires the table sync worker to > apply all changes between X & Y that were skipped by the main apply worker > in a catch up phase. Due to the untimely exit, the table apply worker will > assume that the main apply worker was actually behind, skip the catch up > work, and exit. As a result, all data between X & Y will be lost for that > table. > > The cause of both issues is that wait_for_worker_state_change() is handled > like a void function by the table apply worker. However, if the main apply > worker does not currently exist on the system due to some issue such as a > timeout triggering it to safely exit, then the function will return *before* > the state change has occurred and return false. > But even if wait_for_worker_state_change() returns false, ideally table sync worker shouldn't exit without marking the relstate as SYNCDONE. The table sync worker should keep looping till the state changes to SUBREL_STATE_CATCHUP. See process_syncing_tables_for_sync() which doesn't allow to exit the table sync worker exit. Your observation doesn't match with this analysis, so can you please share how did you reach to the conclusion that the table sync worker will exit and won't restart? -- With Regards, Amit Kapila.
Re: BUG #18155: Logical Apply Worker Timeout During TableSync Causes Either Stuckness or Data Loss
From
"Callahan, Drew"
Date:
Hi Amit, Thanks for commenting, you're correct. I had misremembered the case and upon review found that I had the situation inverted for Rel14. We saw that none of the main apply workers were launching and all of the table apply workers were not transitioning out of the syncwait state. As a result, they kept replaying changes since the logic only checks if we have crossed the LSN if in the CATCHUP state. slot_name | plugin | slot_type | datoid | database | temporary | active | active_pid | xmin| catalog_xmin | restart_lsn | confirmed_flush_lsn | pg_current_wal_lsn | pg_current_wal_flush_lsn | pg_current_wal_insert_lsn| pg_wal_lsn_diff -----------------------------------------+----------+-----------+--------+----------+-----------+--------+------------+------+--------------+---------------+---------------------+--------------------+--------------------------+---------------------------+----------------- main_slot_5 | pgoutput | logical | 16396 | users | f | f | | | 1512105843 | 22D5/33FC5B60 | 22D5/34C8D910 | 2304/94DF6830 | 2304/94DF6830 | 2304/94E68B18 | 203488955600 main_slot_3 | pgoutput | logical | 16396 | users | f | f | | | 1515152530 | 22D5/71A15460 | 22D5/7323FA88 | 2304/94DF6830 | 2304/94DF6830 | 2304/94E68B18 | 202454733776 main_slot_1 | pgoutput | logical | 16396 | users | f | f | | | 1515398672 | 22D5/76AB8500 | 22D5/77806A10 | 2304/94DF6830 | 2304/94DF6830 | 2304/94E68B18 | 202370179888 main_slot_2 | pgoutput | logical | 16396 | users | f | f | | | 1515398672 | 22D5/76AB8500 | 22D5/77039830 | 2304/94DF6830 | 2304/94DF6830 | 2304/94E68B18 | 202370179888 main_slot_0 | pgoutput | logical | 16396 | users | f | f | | | 1515277554 | 22D5/74320CF8 | 22D5/74539970 | 2304/94DF6830 | 2304/94DF6830 | 2304/94E68B18 | 202411694904 main_slot_4 | pgoutput | logical | 16396 | users | f | f | | | 1509956699 | 22D5/8643A70 | 22D5/AEFE230 | 2304/94DF6830 | 2304/94DF6830 | 2304/94E68B18 | 204220345792 pg_21077_sync_20174_7063584474467025194 | pgoutput | logical | 16396 | users | f | t | 97665 | | 2116325349 | 2304/94B86518 | 2304/94DF6830 | 2304/94DF6830 | 2304/94DF6830 | 2304/94E68B18 | 2556696 pg_21173_sync_20205_7063584474467025194 | pgoutput | logical | 16396 | users | f | t | 8349 | | 2116325349 | 2304/94B86518 | 2304/94DF6830 | 2304/94DF6830 | 2304/94DF6830 | 2304/94E68B18 | 2556696 pg_21121_sync_20141_7063584474467025194 | pgoutput | logical | 16396 | users | f | t | 4319 | | 2116325349 | 2304/94B86518 | 2304/94DF6830 | 2304/94DF6830 | 2304/94DF6830 | 2304/94E68B18 | 2556696 pg_21178_sync_20206_7063584474467025194 | pgoutput | logical | 16396 | users | f | t | 8279 | | 2116325349 | 2304/94B86518 | 2304/94DF6830 | 2304/94DF6830 | 2304/94DF6830 | 2304/94E68B18 | 2556696 pg_21081_sync_20101_7063584474467025194 | pgoutput | logical | 16396 | users | f | t | 4065 | | 2116325349 | 2304/94B86518 | 2304/94DF6830 | 2304/94DF6830 | 2304/94DF6830 | 2304/94E68B18 | 2556696 pg_21081_sync_20109_7063584474467025194 | pgoutput | logical | 16396 | users | f | t | 8302 | | 2116325349 | 2304/94B86518 | 2304/94DF6830 | 2304/94DF6830 | 2304/94DF6830 | 2304/94E68B18 | 2556696 pg_21173_sync_20195_7063584474467025194 | pgoutput | logical | 16396 | users | f | t | 4385 | | 2116325349 | 2304/94B86518 | 2304/94DF6830 | 2304/94DF6830 | 2304/94DF6830 | 2304/94E68B18 | 2556696 pg_21077_sync_20183_7063584474467025194 | pgoutput | logical | 16396 | users | f | t | 6690 | | 2116325349 | 2304/94B86518 | 2304/94DF6830 | 2304/94DF6830 | 2304/94DF6830 | 2304/94E68B18 | 2556696 pg_21178_sync_20198_7063584474467025194 | pgoutput | logical | 16396 | users | f | t | 4548 | | 2116325349 | 2304/94B86518 | 2304/94DF6830 | 2304/94DF6830 | 2304/94DF6830 | 2304/94E68B18 | 2556696 pg_21077_sync_20152_7063584474467025194 | pgoutput | logical | 16396 | users | f | t | 97564 | | 2116325349 | 2304/94B86518 | 2304/94DF6830 | 2304/94DF6830 | 2304/94DF6830 | 2304/94E68B18 | 2556696 pg_21121_sync_20149_7063584474467025194 | pgoutput | logical | 16396 | users | f | t | 8384 | | 2116325349 | 2304/94B86518 | 2304/94DF6830 | 2304/94DF6830 | 2304/94DF6830 | 2304/94E68B18 | 2556696 pg_21077_sync_20159_7063584474467025194 | pgoutput | logical | 16396 | users | f | t | 5559 | | 2116325349 | 2304/94B86518 | 2304/94DF6830 | 2304/94DF6830 | 2304/94DF6830 | 2304/94E68B18 | 2556696 (18 rows) On the server side, we did not see evidence of WALSenders being launched. As a result, the gap kept increasing further and further since they workers would not transition to the catchup state after several hours due to this. Thanks, Drew On Fri, Oct 13, 2023 at 6:43 AM PG Bug reporting form <noreply@postgresql.org <mailto:noreply@postgresql.org>> wrote: > > Depending on the Major Version an untimely timeout or termination of the > main apply worker when the table apply worker is waiting for the > subscription relstate to change to SUBREL_STATE_CATCHUP can lead to one of > two really painful experiences. > > If on Rel14+, the untimely exit can lead to the main apply worker becoming > indefinitely stuck while it waits for a table apply worker, that has already > exited and won't be launched again, to change the subscription relstate to > SUBREL_STATE_SYNCDONE. In order to unwedge, a system restart is required to > clear the corrupted transient subscription relstate data. > > If on Rel13+, then the untimely exit can lead to silent data loss. This will > occur if the table apply worker performed a copy at LSN X. If the main apply > worker is now at LSN Y > X, the system requires the table sync worker to > apply all changes between X & Y that were skipped by the main apply worker > in a catch up phase. Due to the untimely exit, the table apply worker will > assume that the main apply worker was actually behind, skip the catch up > work, and exit. As a result, all data between X & Y will be lost for that > table. > > The cause of both issues is that wait_for_worker_state_change() is handled > like a void function by the table apply worker. However, if the main apply > worker does not currently exist on the system due to some issue such as a > timeout triggering it to safely exit, then the function will return *before* > the state change has occurred and return false. > But even if wait_for_worker_state_change() returns false, ideally table sync worker shouldn't exit without marking the relstate as SYNCDONE. The table sync worker should keep looping till the state changes to SUBREL_STATE_CATCHUP. See process_syncing_tables_for_sync() which doesn't allow to exit the table sync worker exit. Your observation doesn't match with this analysis, so can you please share how did you reach to the conclusion that the table sync worker will exit and won't restart? -- With Regards, Amit Kapila.
Re: BUG #18155: Logical Apply Worker Timeout During TableSync Causes Either Stuckness or Data Loss
From
Amit Kapila
Date:
On Tue, Oct 17, 2023 at 4:46 AM Callahan, Drew <callaan@amazon.com> wrote: > > On the server side, we did not see evidence of WALSenders being launched. As a result, the gap kept increasing further > and further since they workers would not transition to the catchup state after several hours due to this. > One possibility is that the system has reached 'max_logical_replication_workers' limit due to which it is not allowing to launch the apply worker. If so, then consider increasing the value of 'max_logical_replication_workers'. You can query 'pg_stat_subscription' to know more information about workers. See the description of subscriber-side parameters [1]. [1] - https://www.postgresql.org/docs/devel/runtime-config-replication.html#RUNTIME-CONFIG-REPLICATION-SUBSCRIBER -- With Regards, Amit Kapila.
Re: BUG #18155: Logical Apply Worker Timeout During TableSync Causes Either Stuckness or Data Loss
From
Michael Paquier
Date:
On Tue, Oct 17, 2023 at 09:50:52AM +0530, Amit Kapila wrote: > On Tue, Oct 17, 2023 at 4:46 AM Callahan, Drew <callaan@amazon.com> wrote: >> On the server side, we did not see evidence of WALSenders being launched. As a result, the gap kept increasing further >> and further since they workers would not transition to the catchup state after several hours due to this. > > One possibility is that the system has reached > 'max_logical_replication_workers' limit due to which it is not > allowing to launch the apply worker. If so, then consider increasing > the value of 'max_logical_replication_workers'. You can query > 'pg_stat_subscription' to know more information about workers. See the > description of subscriber-side parameters [1]. Hmm. So you basically mean that not being able to launch new workers prevents the existing workers to move on with their individual sync, freeing slots once their sync is done for other tables. Then, this causes all all of the existing workers to remain in a syncwait state, further increasing the gap in WAL replay. Am I getting that right? -- Michael
Attachment
Re: BUG #18155: Logical Apply Worker Timeout During TableSync Causes Either Stuckness or Data Loss
From
Michael Paquier
Date:
On Wed, Oct 18, 2023 at 10:22:14AM +0900, Michael Paquier wrote: > On Tue, Oct 17, 2023 at 09:50:52AM +0530, Amit Kapila wrote: >> On Tue, Oct 17, 2023 at 4:46 AM Callahan, Drew <callaan@amazon.com> wrote: >>> On the server side, we did not see evidence of WALSenders being launched. As a result, the gap kept increasing further >>> and further since they workers would not transition to the catchup state after several hours due to this. >> >> One possibility is that the system has reached >> 'max_logical_replication_workers' limit due to which it is not >> allowing to launch the apply worker. If so, then consider increasing >> the value of 'max_logical_replication_workers'. You can query >> 'pg_stat_subscription' to know more information about workers. See the >> description of subscriber-side parameters [1]. > > Hmm. So you basically mean that not being able to launch new workers > prevents the existing workers to move on with their individual sync, > freeing slots once their sync is done for other tables. Then, this > causes all all of the existing workers to remain in a syncwait state, > further increasing the gap in WAL replay. Am I getting that right? I was looking more at what we could do here, played with the apply and sync workers and I really doubt that just ERROR-ing in a sync worker is a good idea on v14~ just for the sake of freeing bgworker slots, which would have the effect of spawning more apply workers. I mean, if your system is under pressure because of a lack of bgworker slots, assuming that a set of N apply workers are gone, leaving M sync workers (M >= N) lying around without being able to get updates from an apply worker, ERRORs in sync workers would give more room to spawn apply workers, but then the launcher worker may fight for the free'd slots to attempt to spawn sync workers for the fresh apply workers, no? It also seems to make the reasoning around the table states harder to think about, as any future apply workers need to handle more error cases related to sync workers. I got a few extra questions about all that: - How did the apply worker stop? That can be said to be the origin of the issue. - Did logicalrep_worker_launch() provide some WARNINGs because the cluster is running out of slots, preventing the spawn of a new apply worker to replace the one that's down, so as the table sync workers are able to move on with their sync phases? I guess it did.. The frequency would offer hints about the pressure put on the system. -- Michael