Re: wake up logical workers after ALTER SUBSCRIPTION

Nathan Bossart <nathandbossart(at)gmail(dot)com> writes:
> 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.

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