Subject: wake up logical workers after ALTER SUBSCRIPTION

From: Nathan Bossart <[email-masked]>
Date: Mon, 21 Nov 2022 16:41:19 -0800

Hi hackers,

While working on avoiding unnecessary wakeups in logical/worker.c (as was
done for walreceiver.c in 05a7be9), I noticed that the tests began taking
much longer.  This seems to be caused by the reduced frequency of calls to
maybe_reread_subscription() in LogicalRepApplyLoop().  Presently,
LogicalRepApplyLoop() only waits for up to a second, so the subscription
info is re-read by workers relatively frequently.  If LogicalRepApplyLoop()
sleeps for longer, the subscription info may not be read for much longer.

I think the fix for this problem can be considered independently, as
relying on frequent wakeups seems less than ideal, and the patch seems to
provide a small improvement even before applying the
avoid-unnecessary-wakeups patch.  On my machine, the attached patch
improved 'check-world -j8' run time by ~12 seconds (from 3min 8sec to 2min
56 sec) and src/test/subscription test time by ~17 seconds (from 139
seconds to 122 seconds).

I put the new logic in launcher.c, but it might make more sense to put it
in logical/worker.c.  I think that might require some new #includes in a
couple of files, but otherwise, the patch would likely look about the same.

Thoughts?

-- 
Nathan Bossart
Amazon Web Services: https://aws.amazon.com

---

From: Thomas Munro <[email-masked]>
Date: Tue, 22 Nov 2022 15:16:05 +1300

On Tue, Nov 22, 2022 at 1:41 PM Nathan Bossart <[email-masked]> wrote:
> On my machine, the attached patch

Nice!

Maybe a comment to explain why a single variable is enough?  And an
assertion that it wasn't already set?  And a note to future self: this
would be a candidate user of the nearby SetLatches() patch (which is
about moving SetLatch() syscalls out from under LWLocks, though this
one may not be very hot).

---

From: Nathan Bossart <[email-masked]>
Date: Mon, 21 Nov 2022 18:50:33 -0800

On Tue, Nov 22, 2022 at 03:16:05PM +1300, Thomas Munro wrote:
> Maybe a comment to explain why a single variable is enough?

This crossed my mind shortly after sending my previous message.  Looking
closer, I see that several types of ALTER SUBSCRIPTION do not call
PreventInTransactionBlock(), so a single variable might not be enough.
Perhaps we can put a list in TopTransactionContext.  I'll do some more
investigation and report back.

---

From: "Hayato Kuroda (Fujitsu)" <[email-masked]>
Date: Tue, 22 Nov 2022 03:03:52 +0000

Hi Nathan,

I have done almost same thing locally for [1], but I thought your code seemed better.

Just One comment: IIUC the statement "ALTER SUBSCRIPTION" can be executed
inside the transaction. So if two subscriptions are altered in the same
transaction, only one of them will awake. Is it expected behavior?

I think we can hold a suboid list and record oids when the subscription are
altered, and then the backend process can consume all of list cells at the end of
the transaction.

How do you think?

[1]: https://commitfest.postgresql.org/40/3581/

Best Regards,
Hayato Kuroda
FUJITSU LIMITED

---

From: Nathan Bossart <[email-masked]>
Date: Mon, 21 Nov 2022 20:39:16 -0800

> altered, and then the backend process can consume all of list cells at the end of

I think you are correct.  I did it this way in v2.  I've also moved the
bulk of the logic to logical/worker.c.

---

From: "Hayato Kuroda (Fujitsu)" <[email-masked]>
Date: Tue, 22 Nov 2022 06:49:29 +0000

Dear Nathan,

> bulk of the logic to logical/worker.c.

Thanks for updating! It becomes better. Further comments:

01. AlterSubscription()

```
+	LogicalRepWorkersWakeupAtCommit(subid);
+
```

Currently subids will be recorded even if the subscription is not modified.
I think LogicalRepWorkersWakeupAtCommit() should be called inside the if (update_tuple).

02. LogicalRepWorkersWakeupAtCommit()

```
+	oldcxt = MemoryContextSwitchTo(TopTransactionContext);
+	on_commit_wakeup_workers_subids = lappend_oid(on_commit_wakeup_workers_subids,
+												  subid);
```

If the subscription is altered twice in the same transaction, the same subid will be recorded twice.
I'm not sure whether it may be caused some issued, but list_member_oid() can be used to avoid that.

Best Regards,
Hayato Kuroda
FUJITSU LIMITED

---

From: "Takamichi Osumi (Fujitsu)" <[email-masked]>
Date: Tue, 22 Nov 2022 07:18:40 +0000

On Tuesday, November 22, 2022 1:39 PM Nathan Bossart <[email-masked]> wrote:
> > Just One comment: IIUC the statement "ALTER SUBSCRIPTION" can be
> > executed inside the transaction. So if two subscriptions are altered
> > in the same transaction, only one of them will awake. Is it expected
> behavior?
> >
> > I think we can hold a suboid list and record oids when the
> > subscription are altered, and then the backend process can consume all
> > of list cells at the end of the transaction.
> 
> I think you are correct.  I did it this way in v2.  I've also moved the bulk of
> the logic to logical/worker.c.
Hi, thanks for updating.

I just quickly had a look at your patch and had one minor question.

With this patch, when we execute alter subscription in a sub transaction
and additionally rollback to it, is there any possibility that
we'll wake up the workers that don't need to do so ?

I'm not sure if this brings about some substantial issue,
but just wondering if there is any need of improvement for this.

Best Regards,
	Takamichi Osumi

---

From: "[email-masked]" <[email-masked]>
Date: Tue, 22 Nov 2022 07:25:36 +0000

On Tuesday, November 22, 2022 2:49 PM Hayato Kuroda (Fujitsu) <[email-masked]>
> 
> Dear Nathan,
> 
> > I think you are correct.  I did it this way in v2.  I've also moved
> > the bulk of the logic to logical/worker.c.
> 

I think an exception would be REFRESH PULLICATION in which case update_tuple is
false, but it seems better to wake up apply worker in this case as well,
because the apply worker is also responsible to start table sync workers for
newly subscribed tables(in process_syncing_tables()).

Besides, it seems not a must to wake up apply worker for ALTER SKIP TRANSACTION,
Although there might be no harm for waking up in this case.

> +	on_commit_wakeup_workers_subids =
> lappend_oid(on_commit_wakeup_workers_subids,
> +
> 		  subid);
> ```
> 

+1, list_append_unique_oid might be better.

Best regards,
Hou zj

---

From: Amit Kapila <[email-masked]>
Date: Tue, 22 Nov 2022 16:59:28 +0530

On Tue, Nov 22, 2022 at 6:11 AM Nathan Bossart <[email-masked]> wrote:
> maybe_reread_subscription() in LogicalRepApplyLoop().
>

I think it would be interesting to know why tests started taking more
time after a reduced frequency of calls to
maybe_reread_subscription(). IIRC, we anyway call
maybe_reread_subscription for each xact.

-- 
With Regards,
Amit Kapila.

---

From: Nathan Bossart <[email-masked]>
Date: Wed, 23 Nov 2022 12:50:27 -0800

> Although there might be no harm for waking up in this case.

In v3, I moved the call to LogicalRepWorkersWakeupAtCommit() to the end of
the function.  This should avoid waking up workers in some cases where it's
unnecessary (e.g., if ALTER SUBSCRIPTION ERRORs in a subtransaction), but
there are still cases where we'll wake up the workers unnecessarily.  I
think this is unlikely to cause any real problems in practice.

> +1, list_append_unique_oid might be better.

Done in v3.

---

From: Nathan Bossart <[email-masked]>
Date: Wed, 23 Nov 2022 13:05:26 -0800

> maybe_reread_subscription for each xact.

At the moment, commands like ALTER SUBSCRIPTION don't wake up the logical
workers for the target subscription, so the next call to
maybe_reread_subscription() may not happen for a while.  Presently, we'll
only sleep up to a second in the apply loop, but with my new
prevent-unnecessary-wakeups patch, we may sleep for much longer.  This
causes wait_for_subscription_sync to take more time after some ALTER
SUBSCRIPTION commands.

---

From: "Hayato Kuroda (Fujitsu)" <[email-masked]>
Date: Thu, 24 Nov 2022 05:26:27 +0000

Dear Nathan,

Thank you for updating the patch!

> think this is unlikely to cause any real problems in practice.

I understood you could accept false-positive event to avoid missing true-negative
like ALTER SUBSCRIPTION REFRESH. +1.

> > +1, list_append_unique_oid might be better.

I have no comments for the v3 patch.

Best Regards,
Hayato Kuroda
FUJITSU LIMITED

---

From: Nathan Bossart <[email-masked]>
Date: Sun, 27 Nov 2022 15:45:28 -0800

> I have no comments for the v3 patch.

Thanks for reviewing!  Does anyone else have thoughts on the patch?

---

From: Nathan Bossart <[email-masked]>
Date: Tue, 29 Nov 2022 20:10:28 -0800

I spent some more time on the prevent-unnecessary-wakeups patch for
logical/worker.c that I've been alluding to in this thread, and I found a
few more places where we depend on the worker periodically waking up.  This
seems to be a common technique, so I'm beginning to wonder whether these
changes are worthwhile.  I think there's a good chance it would become a
game of whac-a-mole.

---

From: Thomas Munro <[email-masked]>
Date: Wed, 30 Nov 2022 17:23:16 +1300

> changes are worthwhile.  I think there's a good chance it would become a

Aren't they all bugs, though, making our tests and maybe even real
systems slower than they need to be?

---

From: Thomas Munro <[email-masked]>
Date: Wed, 30 Nov 2022 17:27:40 +1300

> systems slower than they need to be?

(Which isn't to suggest that it's your job to fix them, but please do
share what you have if you run out of whack-a-mole steam, since we
seem to have several people keen to finish those moles off.)

---

From: "Hayato Kuroda (Fujitsu)" <[email-masked]>
Date: Wed, 30 Nov 2022 04:48:03 +0000

Dear Nathan,

> changes are worthwhile.  I think there's a good chance it would become a

I think at least this feature is needed for waking up workers that are slept due to the min_apply_delay.
The author supposed this patch and pinned our thread[1].

[1]: https://www.postgresql.org/message-id/TYCPR01MB8373775ECC6972289AF8CB30ED0F9%40TYCPR01MB8373.jpnprd01.prod.outlook.com

Best Regards,
Hayato Kuroda
FUJITSU LIMITED

---

From: Nathan Bossart <[email-masked]>
Date: Tue, 29 Nov 2022 21:04:41 -0800

>> systems slower than they need to be?

Yeah, you're right, it's probably worth proceeding with this particular
thread even if we don't end up porting the suppress-unnecessary-wakeups
patch to logical/worker.c.

> seem to have several people keen to finish those moles off.)

I don't mind fixing it!  There are a couple more I'd like to track down
before posting another revision.

---

From: Nathan Bossart <[email-masked]>
Date: Thu, 1 Dec 2022 16:21:30 -0800

> before posting another revision.

Okay, here is a new version of the patch.  This seems to clear up
everything that I could find via the tests.

Thanks to this effort, I discovered that we need to include
wal_retrieve_retry_interval in our wait time calculations after failed
tablesyncs (for the suppress-unnecessary-wakeups patch).  I'll make that
change and post that patch in a new thread.

---

From: Nathan Bossart <[email-masked]>
Date: Fri, 2 Dec 2022 11:21:01 -0800

> everything that I could find via the tests.

I cleaned up the patch a bit.

---

From: Melih Mutlu <[email-masked]>
Date: Tue, 6 Dec 2022 19:44:46 +0300

Hi Nathan,

@@ -410,6 +411,12 @@ ExecRenameStmt(RenameStmt *stmt)
>     stmt->newname);
>   table_close(catalog, RowExclusiveLock);
>
> + /*
> + * Wake up the logical replication workers to handle this
> + * change quickly.
> + */
> + LogicalRepWorkersWakeupAtCommit(address.objectId);

Is it really necessary to wake logical workers up when renaming other than
subscription or publication? address.objectId will be a valid subid only
when renaming a subscription.

@@ -322,6 +323,9 @@ UpdateSubscriptionRelState(Oid subid, Oid relid, char
> state,
>
>   /* Cleanup. */
>   table_close(rel, NoLock);
> +
> + /* Wake up the logical replication workers to handle this change
> quickly. */

I wonder why a wakeup call is needed every time a subscription relation is
updated.
It seems to me that there are two places where UpdateSubscriptionRelState
is called and we need another worker to wake up:
- When a relation is in SYNCWAIT state, it waits for the apply worker to
wake up and change the relation state to CATCHUP. Then tablesync worker
needs to wake up to continue from CATCHUP state.
- When the state is SYNCDONE and the apply worker has to wake up to change
the state to READY.

I think we already call logicalrep_worker_wakeup_ptr wherever it's needed
for the above cases? What am I missing here?

Best,
--
Melih Mutlu
Microsoft

---

From: Nathan Bossart <[email-masked]>
Date: Tue, 6 Dec 2022 11:25:51 -0800

Thanks for reviewing!

> when renaming a subscription.

Oops, that is a mistake.  I only meant to wake up the workers for ALTER
SUBSCRIPTION RENAME.  I think I've fixed this in v6.

> for the above cases? What am I missing here?

IIUC we must restart all the apply workers for a subscription to enable
two_phase mode.  It looks like finish_sync_worker() only wakes up its own
apply worker.  I moved this logic to where the sync worker marks the state
as SYNCDONE and added a check that two_phase mode is pending.  Even so,
there can still be unnecessary wakeups, but this adjustment should limit
them.

---

From: Nathan Bossart <[email-masked]>
Date: Tue, 6 Dec 2022 13:29:54 -0800

> there can still be unnecessary wakeups, but this adjustment should limit

Actually, that's not quite right.  The sync worker will wake up the apply
worker to change the state from SYNCDONE to READY.  AllTablesyncsReady()
checks that all tables are READY, so we need to wake up all the workers
when an apply worker changes the state to READY.  Each worker will then
evaluate whether to restart for two_phase mode.

---

From: Melih Mutlu <[email-masked]>
Date: Wed, 7 Dec 2022 14:07:11 +0300

Hi,

> evaluate whether to restart for two_phase mode.

Right. I didn't think about the two phase case thoroughly. Waking up all
apply workers can help.

Do we also need to wake up all sync workers too? Even if not, I'm not
actually sure whether doing that would harm anything though.
Just asking since currently the patch wakes up all workers including sync
workers if any still exists.

Best,
--
Melih Mutlu
Microsoft

---

From: Nathan Bossart <[email-masked]>
Date: Wed, 7 Dec 2022 10:11:45 -0800

> workers if any still exists.

After sleeping on this, I think we can do better.  IIUC we can simply check
for AllTablesyncsReady() at the end of process_syncing_tables_for_apply()
and wake up the logical replication workers (which should just consiѕt of
setting the current process's latch) if we are ready for two_phase mode.

---

From: Tom Lane <[email-masked]>
Date: Tue, 13 Dec 2022 18:32:08 -0500

> setting the current process's latch) if we are ready for two_phase mode.

I independently rediscovered the need for something like this after
wondering why the subscription/t/031_column_list.pl test seemed to
take so much longer than its siblings.  I found that a considerable
amount of the elapsed time was wasted because we were waiting up to
a full second (NAPTIME_PER_CYCLE) for the logrep worker to notice
that something had changed in the local subscription state.  At least
on my machine, it seems that the worst-case timing is reliably hit
multiple times during this test.  Now admittedly, this is probably not
a significant problem in real-world usage; but it's sure annoying that
it eats time during check-world.

However, this patch seems to still be leaving quite a bit on the
table.  Here's the timings I see for the subscription suite in HEAD
(test is just "time make check PROVE_FLAGS=--timer" with an
assert-enabled build):

+++ tap check in src/test/subscription +++
[18:07:38] t/001_rep_changes.pl ............... ok     6659 ms ( 0.00 usr  0.00 sys +  0.89 cusr  0.52 csys =  1.41 CPU)
[18:07:45] t/002_types.pl ..................... ok     1572 ms ( 0.00 usr  0.00 sys +  0.70 cusr  0.27 csys =  0.97 CPU)
[18:07:47] t/003_constraints.pl ............... ok     1436 ms ( 0.01 usr  0.00 sys +  0.74 cusr  0.25 csys =  1.00 CPU)
[18:07:48] t/004_sync.pl ...................... ok     3007 ms ( 0.00 usr  0.00 sys +  0.75 cusr  0.31 csys =  1.06 CPU)
[18:07:51] t/005_encoding.pl .................. ok     1468 ms ( 0.00 usr  0.00 sys +  0.74 cusr  0.21 csys =  0.95 CPU)
[18:07:53] t/006_rewrite.pl ................... ok     1494 ms ( 0.00 usr  0.00 sys +  0.72 cusr  0.24 csys =  0.96 CPU)
[18:07:54] t/007_ddl.pl ....................... ok     2005 ms ( 0.00 usr  0.00 sys +  0.73 cusr  0.24 csys =  0.97 CPU)
[18:07:56] t/008_diff_schema.pl ............... ok     1746 ms ( 0.01 usr  0.00 sys +  0.70 cusr  0.28 csys =  0.99 CPU)
[18:07:58] t/009_matviews.pl .................. ok     1878 ms ( 0.00 usr  0.00 sys +  0.71 cusr  0.24 csys =  0.95 CPU)
[18:08:00] t/010_truncate.pl .................. ok     2999 ms ( 0.00 usr  0.00 sys +  0.77 cusr  0.38 csys =  1.15 CPU)
[18:08:03] t/011_generated.pl ................. ok     1467 ms ( 0.00 usr  0.00 sys +  0.71 cusr  0.24 csys =  0.95 CPU)
[18:08:04] t/012_collation.pl ................. skipped: ICU not supported by this build
[18:08:04] t/013_partition.pl ................. ok     4787 ms ( 0.01 usr  0.00 sys +  1.29 cusr  0.71 csys =  2.01 CPU)
[18:08:09] t/014_binary.pl .................... ok     2564 ms ( 0.00 usr  0.00 sys +  0.72 cusr  0.28 csys =  1.00 CPU)
[18:08:12] t/015_stream.pl .................... ok     2531 ms ( 0.01 usr  0.00 sys +  0.73 cusr  0.27 csys =  1.01 CPU)
[18:08:14] t/016_stream_subxact.pl ............ ok     1590 ms ( 0.00 usr  0.00 sys +  0.70 cusr  0.24 csys =  0.94 CPU)
[18:08:16] t/017_stream_ddl.pl ................ ok     1610 ms ( 0.00 usr  0.00 sys +  0.72 cusr  0.25 csys =  0.97 CPU)
[18:08:17] t/018_stream_subxact_abort.pl ...... ok     1827 ms ( 0.00 usr  0.00 sys +  0.73 cusr  0.24 csys =  0.97 CPU)
[18:08:19] t/019_stream_subxact_ddl_abort.pl .. ok     1474 ms ( 0.00 usr  0.00 sys +  0.71 cusr  0.24 csys =  0.95 CPU)
[18:08:21] t/020_messages.pl .................. ok     2423 ms ( 0.01 usr  0.00 sys +  0.74 cusr  0.25 csys =  1.00 CPU)
[18:08:23] t/021_twophase.pl .................. ok     4799 ms ( 0.00 usr  0.00 sys +  0.82 cusr  0.39 csys =  1.21 CPU)
[18:08:28] t/022_twophase_cascade.pl .......... ok     4346 ms ( 0.00 usr  0.00 sys +  1.12 cusr  0.54 csys =  1.66 CPU)
[18:08:32] t/023_twophase_stream.pl ........... ok     3656 ms ( 0.01 usr  0.00 sys +  0.78 cusr  0.32 csys =  1.11 CPU)
[18:08:36] t/024_add_drop_pub.pl .............. ok     3585 ms ( 0.00 usr  0.00 sys +  0.73 cusr  0.29 csys =  1.02 CPU)
[18:08:39] t/025_rep_changes_for_schema.pl .... ok     3631 ms ( 0.00 usr  0.00 sys +  0.77 cusr  0.34 csys =  1.11 CPU)
[18:08:43] t/026_stats.pl ..................... ok     4096 ms ( 0.00 usr  0.00 sys +  0.77 cusr  0.32 csys =  1.09 CPU)
[18:08:47] t/027_nosuperuser.pl ............... ok     4824 ms ( 0.01 usr  0.00 sys +  0.77 cusr  0.39 csys =  1.17 CPU)
[18:08:52] t/028_row_filter.pl ................ ok     5321 ms ( 0.00 usr  0.00 sys +  0.90 cusr  0.50 csys =  1.40 CPU)
[18:08:57] t/029_on_error.pl .................. ok     3748 ms ( 0.00 usr  0.00 sys +  0.75 cusr  0.32 csys =  1.07 CPU)
[18:09:01] t/030_origin.pl .................... ok     4496 ms ( 0.00 usr  0.00 sys +  1.09 cusr  0.45 csys =  1.54 CPU)
[18:09:06] t/031_column_list.pl ............... ok    13802 ms ( 0.01 usr  0.00 sys +  1.00 cusr  0.69 csys =  1.70 CPU)
[18:09:19] t/100_bugs.pl ...................... ok     5195 ms ( 0.00 usr  0.00 sys +  2.05 cusr  0.76 csys =  2.81 CPU)
[18:09:25]
All tests successful.
Files=32, Tests=379, 107 wallclock secs ( 0.09 usr  0.02 sys + 26.10 cusr 10.98 csys = 37.19 CPU)
Result: PASS

real    1m47.503s
user    0m27.068s
sys     0m11.452s

With the v8 patch, I get:

+++ tap check in src/test/subscription +++
[18:11:15] t/001_rep_changes.pl ............... ok     5505 ms ( 0.01 usr  0.00 sys +  0.90 cusr  0.49 csys =  1.40 CPU)
[18:11:21] t/002_types.pl ..................... ok     1574 ms ( 0.00 usr  0.00 sys +  0.71 cusr  0.26 csys =  0.97 CPU)
[18:11:23] t/003_constraints.pl ............... ok     1442 ms ( 0.00 usr  0.00 sys +  0.71 cusr  0.28 csys =  0.99 CPU)
[18:11:24] t/004_sync.pl ...................... ok     2087 ms ( 0.01 usr  0.00 sys +  0.74 cusr  0.30 csys =  1.05 CPU)
[18:11:26] t/005_encoding.pl .................. ok     1465 ms ( 0.00 usr  0.00 sys +  0.71 cusr  0.23 csys =  0.94 CPU)
[18:11:28] t/006_rewrite.pl ................... ok     1489 ms ( 0.00 usr  0.00 sys +  0.73 cusr  0.24 csys =  0.97 CPU)
[18:11:29] t/007_ddl.pl ....................... ok     2007 ms ( 0.00 usr  0.00 sys +  0.73 cusr  0.23 csys =  0.96 CPU)
[18:11:31] t/008_diff_schema.pl ............... ok     1644 ms ( 0.00 usr  0.00 sys +  0.72 cusr  0.27 csys =  0.99 CPU)
[18:11:33] t/009_matviews.pl .................. ok     1878 ms ( 0.00 usr  0.00 sys +  0.70 cusr  0.25 csys =  0.95 CPU)
[18:11:35] t/010_truncate.pl .................. ok     3006 ms ( 0.00 usr  0.00 sys +  0.79 cusr  0.37 csys =  1.16 CPU)
[18:11:38] t/011_generated.pl ................. ok     1470 ms ( 0.00 usr  0.00 sys +  0.72 cusr  0.23 csys =  0.95 CPU)
[18:11:39] t/012_collation.pl ................. skipped: ICU not supported by this build
[18:11:39] t/013_partition.pl ................. ok     4656 ms ( 0.01 usr  0.00 sys +  1.30 cusr  0.69 csys =  2.00 CPU)
[18:11:44] t/014_binary.pl .................... ok     2570 ms ( 0.00 usr  0.00 sys +  0.74 cusr  0.27 csys =  1.01 CPU)
[18:11:46] t/015_stream.pl .................... ok     2535 ms ( 0.00 usr  0.00 sys +  0.74 cusr  0.26 csys =  1.00 CPU)
[18:11:49] t/016_stream_subxact.pl ............ ok     1601 ms ( 0.00 usr  0.00 sys +  0.71 cusr  0.26 csys =  0.97 CPU)
[18:11:51] t/017_stream_ddl.pl ................ ok     1608 ms ( 0.00 usr  0.00 sys +  0.70 cusr  0.26 csys =  0.96 CPU)
[18:11:52] t/018_stream_subxact_abort.pl ...... ok     1834 ms ( 0.00 usr  0.00 sys +  0.72 cusr  0.26 csys =  0.98 CPU)
[18:11:54] t/019_stream_subxact_ddl_abort.pl .. ok     1476 ms ( 0.00 usr  0.00 sys +  0.71 cusr  0.24 csys =  0.95 CPU)
[18:11:55] t/020_messages.pl .................. ok     1489 ms ( 0.00 usr  0.00 sys +  0.73 cusr  0.24 csys =  0.97 CPU)
[18:11:57] t/021_twophase.pl .................. ok     4289 ms ( 0.00 usr  0.00 sys +  0.82 cusr  0.38 csys =  1.20 CPU)
[18:12:01] t/022_twophase_cascade.pl .......... ok     3835 ms ( 0.01 usr  0.00 sys +  1.17 cusr  0.49 csys =  1.67 CPU)
[18:12:05] t/023_twophase_stream.pl ........... ok     3158 ms ( 0.00 usr  0.00 sys +  0.79 cusr  0.32 csys =  1.11 CPU)
[18:12:08] t/024_add_drop_pub.pl .............. ok     2553 ms ( 0.00 usr  0.00 sys +  0.72 cusr  0.28 csys =  1.00 CPU)
[18:12:11] t/025_rep_changes_for_schema.pl .... ok     2703 ms ( 0.01 usr  0.00 sys +  0.77 cusr  0.32 csys =  1.10 CPU)
[18:12:13] t/026_stats.pl ..................... ok     4101 ms ( 0.00 usr  0.00 sys +  0.77 cusr  0.31 csys =  1.08 CPU)
[18:12:18] t/027_nosuperuser.pl ............... ok     4822 ms ( 0.00 usr  0.00 sys +  0.80 cusr  0.36 csys =  1.16 CPU)
[18:12:22] t/028_row_filter.pl ................ ok     4396 ms ( 0.00 usr  0.00 sys +  0.90 cusr  0.50 csys =  1.40 CPU)
[18:12:27] t/029_on_error.pl .................. ok     4382 ms ( 0.00 usr  0.00 sys +  0.75 cusr  0.33 csys =  1.08 CPU)
[18:12:31] t/030_origin.pl .................... ok     2735 ms ( 0.00 usr  0.00 sys +  1.10 cusr  0.40 csys =  1.50 CPU)
[18:12:34] t/031_column_list.pl ............... ok    10281 ms ( 0.01 usr  0.00 sys +  1.01 cusr  0.60 csys =  1.62 CPU)
[18:12:44] t/100_bugs.pl ...................... ok     5214 ms ( 0.00 usr  0.00 sys +  2.05 cusr  0.79 csys =  2.84 CPU)
[18:12:49]
All tests successful.
Files=32, Tests=379, 94 wallclock secs ( 0.10 usr  0.02 sys + 26.21 cusr 10.72 csys = 37.05 CPU)
Result: PASS

real    1m35.275s
user    0m27.177s
sys     0m11.182s

That's better, but not by an impressive amount: there's still an
annoyingly large amount of daylight between the CPU time expended
and the elapsed time (and I'm not even considering the possibility
that some of that CPU time could be parallelized).

I poked into it some more, and what I'm seeing now is traces like

2022-12-13 18:12:35.936 EST [2547426] 031_column_list.pl LOG:  statement: ALTER SUBSCRIPTION sub1 SET PUBLICATION pub2, pub3
2022-12-13 18:12:35.941 EST [2547327] LOG:  logical replication apply worker for subscription "sub1" will restart because of a parameter change
2022-12-13 18:12:35.944 EST [2547429] 031_column_list.pl LOG:  statement: SELECT count(1) = 0 FROM pg_subscription_rel WHERE srsubstate NOT IN ('r', 's');
2022-12-13 18:12:36.048 EST [2547431] 031_column_list.pl LOG:  statement: SELECT count(1) = 0 FROM pg_subscription_rel WHERE srsubstate NOT IN ('r', 's');
2022-12-13 18:12:36.151 EST [2547433] 031_column_list.pl LOG:  statement: SELECT count(1) = 0 FROM pg_subscription_rel WHERE srsubstate NOT IN ('r', 's');
2022-12-13 18:12:36.255 EST [2547435] 031_column_list.pl LOG:  statement: SELECT count(1) = 0 FROM pg_subscription_rel WHERE srsubstate NOT IN ('r', 's');
2022-12-13 18:12:36.359 EST [2547437] 031_column_list.pl LOG:  statement: SELECT count(1) = 0 FROM pg_subscription_rel WHERE srsubstate NOT IN ('r', 's');
2022-12-13 18:12:36.443 EST [2547441] LOG:  logical replication apply worker for subscription "sub1" has started
2022-12-13 18:12:36.446 EST [2547443] LOG:  logical replication table synchronization worker for subscription "sub1", table "tab5" has started
2022-12-13 18:12:36.451 EST [2547443] LOG:  logical replication table synchronization worker for subscription "sub1", table "tab5" has finished
2022-12-13 18:12:36.463 EST [2547446] 031_column_list.pl LOG:  statement: SELECT count(1) = 0 FROM pg_subscription_rel WHERE srsubstate NOT IN ('r', 's');

Before, there was up to 1 second (with multiple "SELECT count(1) = 0"
probes from the test script) between the ALTER SUBSCRIPTION command
and the "apply worker will restart" log entry.  That wait is pretty
well zapped, but instead now we're waiting hundreds of ms for the
"apply worker has started" message.

I've not chased it further than that, but I venture that the apply
launcher also needs a kick in the pants, and/or there needs to be
an interlock to ensure that it doesn't wake until after the old
apply worker quits.

			regards, tom lane

---

From: Nathan Bossart <[email-masked]>
Date: Tue, 13 Dec 2022 16:01:45 -0800

> an interlock to ensure that it doesn't wake until after the old

This is probably because the tests set wal_retrieve_retry_interval to
500ms.  Lowering that to 1ms in Cluster.pm seems to wipe out this
particular wait, and the total src/test/subscription test time drops from
119 seconds to 95 seconds on my machine.  This probably lowers the amount
of test coverage we get on the wal_retrieve_retry_interval code paths, but
if that's a concern, perhaps we should write a test specifically for
wal_retrieve_retry_interval.

---

From: Tom Lane <[email-masked]>
Date: Tue, 13 Dec 2022 19:20:14 -0500

> 119 seconds to 95 seconds on my machine.

That's not really the direction we should be going in, though.  Ideally
there should be *no* situation where we are waiting for a timeout to
elapse for a process to wake up and notice it ought to do something.
If we have timeouts at all, they should be backstops for the possibility
of a lost interrupt, and it should be possible to set them quite high
without any visible impact on normal operation.  (This gets back to
the business about minimizing idle power consumption, which Simon was
bugging us about recently but that's been on the radar screen for years.)

I certainly don't think that "wake the apply launcher every 1ms"
is a sane configuration.  Unless I'm missing something basic about
its responsibilities, it should seldom need to wake at all in
normal operation.

			regards, tom lane

---

From: Nathan Bossart <[email-masked]>
Date: Tue, 13 Dec 2022 16:41:05 -0800

> its responsibilities, it should seldom need to wake at all in

This parameter appears to control how often the apply launcher starts new
workers.  If it starts new workers in a loop iteration, it updates its
last_start_time variable, and it won't start any more workers until another
wal_retrieve_retry_interval has elapsed.  If no new workers need to be
started, it only wakes up every 3 minutes.

---

From: Nathan Bossart <[email-masked]>
Date: Wed, 14 Dec 2022 09:10:23 -0800

> started, it only wakes up every 3 minutes.

Looking closer, I see that wal_retrieve_retry_interval is used for three
purposes.  It's main purpose seems to be preventing busy-waiting in
WaitForWALToBecomeAvailable(), as that's what's documented.  But it's also
used for logical replication.  The apply launcher uses it as I've describe
above, and the apply workers use it when launching sync workers.  Unlike
the apply launcher, the apply workers store the last start time for each
table's sync worker and use that to determine whether to start a new one.

My first thought is that the latter two uses should be moved to a new
parameter, and the apply launcher should store the last start time for each
apply worker like the apply workers do for the table-sync workers.  In any
case, it probably makes sense to lower this parameter's value for testing
so that tests that restart these workers frequently aren't waiting for so
long.

I can put a patch together if this seems like a reasonable direction to go.

---

From: Tom Lane <[email-masked]>
Date: Wed, 14 Dec 2022 12:42:32 -0500

> I can put a patch together if this seems like a reasonable direction to go.

No, I'm still of the opinion that waiting for the launcher to timeout
before doing something is fundamentally wrong design.  We should signal
it when we want it to do something.  That's not different from what
you're fixing about the workers; why don't you see that it's appropriate
for the launcher too?

			regards, tom lane

---

From: Nathan Bossart <[email-masked]>
Date: Wed, 14 Dec 2022 09:45:35 -0800

> you're fixing about the workers; why don't you see that it's appropriate

I'm reasonably certain the launcher is already signaled like you describe.
It'll just wait to start new workers if it's been less than
wal_retrieve_retry_interval milliseconds since the last time it started
workers.

---

From: Tom Lane <[email-masked]>
Date: Wed, 14 Dec 2022 13:23:18 -0500

> wal_retrieve_retry_interval milliseconds since the last time it started

Oh.  What in the world is the rationale for that?

			regards, tom lane

---

From: Nathan Bossart <[email-masked]>
Date: Wed, 14 Dec 2022 10:37:59 -0800

> Oh.  What in the world is the rationale for that?

My assumption is that this is meant to avoid starting workers as fast as
possible if they repeatedly crash.  I didn't see much discussion in the
original logical replication thread [0], but I do see follow-up discussion
about creating a separate GUC for this [1] [2].

[0] https://postgr.es/m/b8132323-b577-428c-b2aa-bf41a66b18e7%402ndquadrant.com
[1] https://postgr.es/m/CAD21AoAjTTGm%2BOx70b2OGWvb77vPcRdYeRv3gkAWx76nXDo%2BEA%40mail.gmail.com
[2] https://postgr.es/m/CAD21AoDCnyRJDUY%3DESVVe68AukvOP2dFomTeBFpAd1TiFbjsGg%40mail.gmail.com

---

From: Tom Lane <[email-masked]>
Date: Wed, 14 Dec 2022 14:02:58 -0500

> possible if they repeatedly crash.

I can see the point of rate-limiting if the workers are failing to connect
or crashing while trying to process data.  But it's not very sane to
apply the same policy to an intentional worker exit-for-reconfiguration.

Maybe we could have workers that are exiting for that reason set a
flag saying "please restart me without delay"?

A *real* fix would be to not exit at all, at least for reconfigurations
that don't change the connection parameters, but instead cope with
recomputing whatever needs recomputed in the workers' state.  I can
believe that that'd be a lot of work though.

			regards, tom lane

---

From: Nathan Bossart <[email-masked]>
Date: Wed, 14 Dec 2022 15:17:27 -0800

> flag saying "please restart me without delay"?

That helps a bit, but there are still delays when starting workers for new
subscriptions.  I think we'd need to create a new array in shared memory
for subscription OIDs that need their workers started immediately.

I'm not totally sure this is worth the effort.  These delays surface in the
tests because the workers are started so frequently.  In normal operation,
this is probably unusual, so the launcher would typically start new workers
immediately.  But if you and/or others feel this is worthwhile, I don't
mind working on the patch.

---

From: Nathan Bossart <[email-masked]>
Date: Thu, 15 Dec 2022 14:47:21 -0800

I tried setting wal_retrieve_retry_interval to 1ms for all TAP tests
(similar to what was done in 2710ccd), and I noticed that the recovery
tests consistently took much longer.  Upon further inspection, it looks
like the same (or a very similar) race condition described in e5d494d's
commit message [0].  With some added debug logs, I see that all of the
callers of MaybeStartWalReceiver() complete before SIGCHLD is processed, so
ServerLoop() waits for a minute before starting the WAL receiver.

A simple fix is to have DetermineSleepTime() take the WalReceiverRequested
flag into consideration.  The attached 0002 patch shortens the sleep time
to 100ms if it looks like we are waiting on a SIGCHLD.  I'm not certain
this is the best approach, but it seems to fix the tests.

On my machine, I see the following improvements in the tests (all units in
seconds):
                     HEAD  patched (v9)
    check-world -j8  165   138
    subscription     120   75
    recovery         111   108

[0] https://postgr.es/m/21344.1498494720%40sss.pgh.pa.us

---

From: Nathan Bossart <[email-masked]>
Date: Sun, 18 Dec 2022 15:36:07 -0800

> this is the best approach, but it seems to fix the tests.

This seems to have somehow broken the archiving tests on Windows, so
obviously I owe some better analysis here.  I didn't see anything obvious
in the logs, but I will continue to dig.

---

From: Nathan Bossart <[email-masked]>
Date: Sat, 31 Dec 2022 15:50:19 -0800

> in the logs, but I will continue to dig.

On Windows, WaitForWALToBecomeAvailable() seems to depend on the call to
WaitLatch() for wal_retrieve_retry_interval to ensure that signals are
dispatched (i.e., pgwin32_dispatch_queued_signals()).  My first instinct is
to just always call WaitLatch() in this code path, even if
wal_retrieve_rety_interval milliseconds have already elapsed.  The attached
0003 does this.