Feedback-ID: id4a34324:Fastmail
Date: Thu, 27 Jul 2023 19:23:32 -0700
From: Andres Freund <andres@anarazel.de>
To: Bharath Rupireddy <bharath.rupireddyforpostgres@gmail.com>
Cc: Masahiro Ikeda <ikedamsh@oss.nttdata.com>, michael@paquier.xyz,
	pgsql-hackers@lists.postgresql.org
Subject: Re: Support worker_spi to execute the function dynamically.
Message-ID: <20230728022332.egqzobhskmlf6ntr@awork3.anarazel.de>
References: <ZLi6iHwMAqhfYVdn@paquier.xyz>
 <CALj2ACWj7qF-YYVi05okBFJnPugkwsM8PSrEwfHs-tQqKO80Uw@mail.gmail.com>
 <46e53055d8d1c92704d3cd2709c722e7@oss.nttdata.com>
 <CALj2ACV0fr-9OTZqtWu-9XrtUbBZCYb0UK859gfvJ0oqm3YvUA@mail.gmail.com>
 <ZLn2v/eMkqmny4J6@paquier.xyz>
 <CALj2ACVUxgcQaGh3HpBJ6Xg9FRqj7UNDomd5E1y=tRKs2wcntA@mail.gmail.com>
 <ZLokkzw6pmvDU9bM@paquier.xyz>
 <CALj2ACVWW2NU78kJ=xEbz8qcZgWeae+cVp8TYbvGTdpYjVKjjA@mail.gmail.com>
 <e4e5bee9d241a00a0edd9ee4e90fe69c@oss.nttdata.com>
 <CALj2ACWR9ncAiDF73unqdJF1dmsA2R0efGXX2624X+YVxcAVWg@mail.gmail.com>
MIME-Version: 1.0
Content-Type: multipart/mixed; boundary="3ze2tblfw5hlebx5"
Content-Disposition: inline
In-Reply-To: <CALj2ACWR9ncAiDF73unqdJF1dmsA2R0efGXX2624X+YVxcAVWg@mail.gmail.com>
Archived-At: <https://www.postgresql.org/message-id/20230728022332.egqzobhskmlf6ntr%40awork3.anarazel.de>
Precedence: bulk


--3ze2tblfw5hlebx5
Content-Type: text/plain; charset=us-ascii
Content-Disposition: inline

Hi,

The new test fails with my AIO branch occasionally. But I'm fairly certain
that's just due to timing differences.

Excerpt from the log:

2023-07-27 21:43:00.385 UTC [42339] LOG:  worker_spi worker 3 initialized with schema3.counted
2023-07-27 21:43:00.399 UTC [42344] 001_worker_spi.pl LOG:  statement: SELECT datname, count(datname) FROM pg_stat_activity
	            WHERE backend_type = 'worker_spi' GROUP BY datname;
2023-07-27 21:43:00.403 UTC [42340] LOG:  worker_spi worker 2 initialized with schema2.counted
2023-07-27 21:43:00.407 UTC [42341] LOG:  worker_spi worker 1 initialized with schema1.counted
2023-07-27 21:43:00.420 UTC [42346] 001_worker_spi.pl LOG:  statement: SELECT worker_spi_launch(1);
2023-07-27 21:43:00.423 UTC [42347] LOG:  worker_spi dynamic worker 1 initialized with schema1.counted
2023-07-27 21:43:00.432 UTC [42349] 001_worker_spi.pl LOG:  statement: SELECT worker_spi_launch(2);
2023-07-27 21:43:00.437 UTC [42350] LOG:  worker_spi dynamic worker 2 initialized with schema2.counted
2023-07-27 21:43:00.443 UTC [42347] ERROR:  duplicate key value violates unique constraint "pg_namespace_nspname_index"
2023-07-27 21:43:00.443 UTC [42347] DETAIL:  Key (nspname)=(schema1) already exists.
2023-07-27 21:43:00.443 UTC [42347] CONTEXT:  SQL statement "CREATE SCHEMA "schema1" CREATE TABLE "counted" (		type text CHECK (type IN ('total', 'delta')), 		value	integer)CREATE UNIQUE INDEX "counted_unique_total" ON "counted" (type) WHERE type = 'total'"


As written, dynamic and static workers race each other. It doesn't make a lot
of sense to me to use the same ids for either?

The attached patch reproduces the problem on master.

Note that without the sleep(3) in the test the workers don't actually finish
starting, the test shuts down the cluster before that happens...

Greetings,

Andres Freund

--3ze2tblfw5hlebx5
Content-Type: text/x-diff; charset=us-ascii
Content-Disposition: attachment; filename="repro.diff"

diff --git i/src/test/modules/worker_spi/t/001_worker_spi.pl w/src/test/modules/worker_spi/t/001_worker_spi.pl
index c2938713134..093a038b005 100644
--- i/src/test/modules/worker_spi/t/001_worker_spi.pl
+++ w/src/test/modules/worker_spi/t/001_worker_spi.pl
@@ -52,6 +52,7 @@ $node->append_conf(
 shared_preload_libraries = 'worker_spi'
 worker_spi.database = 'mydb'
 worker_spi.total_workers = 3
+log_statement=all
 });
 $node->restart;
 
@@ -68,6 +69,9 @@ ok( $node->poll_query_until(
 # check their existence.
 my $worker1_pid = $node->safe_psql('mydb', 'SELECT worker_spi_launch(1);');
 my $worker2_pid = $node->safe_psql('mydb', 'SELECT worker_spi_launch(2);');
+
+sleep(3);
+
 ok( $node->poll_query_until(
 		'mydb',
 		qq[SELECT datname, count(datname)  FROM pg_stat_activity
diff --git i/src/test/modules/worker_spi/worker_spi.c w/src/test/modules/worker_spi/worker_spi.c
index 903dcddef97..ebd2120ec11 100644
--- i/src/test/modules/worker_spi/worker_spi.c
+++ w/src/test/modules/worker_spi/worker_spi.c
@@ -120,6 +120,8 @@ initialize_worker_spi(worktable *table)
 			elog(FATAL, "failed to create my schema");
 
 		debug_query_string = NULL;	/* rest is not statement-specific */
+
+		pg_usleep(USECS_PER_SEC*1);
 	}
 
 	SPI_finish();
@@ -127,6 +129,8 @@ initialize_worker_spi(worktable *table)
 	CommitTransactionCommand();
 	debug_query_string = NULL;
 	pgstat_report_activity(STATE_IDLE, NULL);
+
+	elog(LOG, "done");
 }
 
 void

--3ze2tblfw5hlebx5--