Re: Perform streaming logical transactions by background workers and parallel apply

On Thu, Jan 5, 2023 at 9:07 AM houzj.fnst@fujitsu.com
<houzj.fnst@fujitsu.com> wrote:
>
> On Wednesday, January 4, 2023 9:29 PM Dilip Kumar <dilipbalaut@gmail.com> wrote:

> > I think this looks good to me.
>
> Thanks for the comments.
> Attach the new version patch set which changed the comments as suggested.

Thanks for the updated patch, while testing this I see one strange
behavior which seems like bug to me, here is the step to reproduce

1. start 2 servers(config: logical_decoding_work_mem=64kB)
./pg_ctl -D data/ -c -l pub_logs start
./pg_ctl -D data1/ -c -l sub_logs start

2. Publisher:
create table t(a int PRIMARY KEY ,b text);
CREATE OR REPLACE FUNCTION large_val() RETURNS TEXT LANGUAGE SQL AS
'select array_agg(md5(g::text))::text from generate_series(1, 256) g';
create publication test_pub for table t
with(PUBLISH='insert,delete,update,truncate');
alter table t replica identity FULL ;
insert into t values (generate_series(1,2000),large_val()) ON CONFLICT
(a) DO UPDATE SET a=EXCLUDED.a*300;

3. Subscription Server:
create table t(a int,b text);
create subscription test_sub CONNECTION 'host=localhost port=5432
dbname=postgres' PUBLICATION test_pub WITH ( slot_name =
test_slot_sub1,streaming=parallel);

4. Publication Server:
begin ;
savepoint a;
delete from t;
savepoint b;
insert into t values (generate_series(1,5000),large_val()) ON CONFLICT
(a) DO UPDATE SET a=EXCLUDED.a*30000;  -- (while executing this start
publisher in 2-3 secs)

Restart the publication server, while the transaction is still in an
uncommitted state.
./pg_ctl -D data/ -c -l pub_logs stop -mi
./pg_ctl -D data/ -c -l pub_logs start -mi

after this, the parallel apply worker stuck in waiting on stream lock
forever (even after 10 mins) -- see below, from subscriber logs I can
see one of the parallel apply worker [75677] started but never
finished [no error], after that I have performed more operation [same
insert] which got applied by new parallel apply worked which got
started and finished within 1 second.

dilipku+  75660      1  0 13:39 ?        00:00:00
/home/dilipkumar/work/PG/install/bin/postgres -D data
dilipku+  75661  75660  0 13:39 ?        00:00:00 postgres: checkpointer
dilipku+  75662  75660  0 13:39 ?        00:00:00 postgres: background writer
dilipku+  75664  75660  0 13:39 ?        00:00:00 postgres: walwriter
dilipku+  75665  75660  0 13:39 ?        00:00:00 postgres: autovacuum launcher
dilipku+  75666  75660  0 13:39 ?        00:00:00 postgres: logical
replication launcher
dilipku+  75675  75595  0 13:39 ?        00:00:00 postgres: logical
replication apply worker for subscription 16389
dilipku+  75676  75660  0 13:39 ?        00:00:00 postgres: walsender
dilipkumar postgres ::1(42192) START_REPLICATION
dilipku+  75677  75595  0 13:39 ?        00:00:00 postgres: logical
replication parallel apply worker for subscription 16389  waiting


Subscriber logs:
2023-01-05 13:39:07.261 IST [75595] LOG:  background worker "logical
replication worker" (PID 75649) exited with exit code 1
2023-01-05 13:39:12.272 IST [75675] LOG:  logical replication apply
worker for subscription "test_sub" has started
2023-01-05 13:39:12.307 IST [75677] LOG:  logical replication parallel
apply worker for subscription "test_sub" has started
2023-01-05 13:43:31.003 IST [75596] LOG:  checkpoint starting: time
2023-01-05 13:46:32.045 IST [76337] LOG:  logical replication parallel
apply worker for subscription "test_sub" has started
2023-01-05 13:46:35.214 IST [76337] LOG:  logical replication parallel
apply worker for subscription "test_sub" has finished
2023-01-05 13:46:50.241 IST [76384] LOG:  logical replication parallel
apply worker for subscription "test_sub" has started
2023-01-05 13:46:53.676 IST [76384] LOG:  logical replication parallel
apply worker for subscription "test_sub" has finished

-- 
Regards,
Dilip Kumar
EnterpriseDB: http://www.enterprisedb.com