Re: Testing LISTEN/NOTIFY more effectively

Andres Freund <andres@anarazel.de> writes:
> On 2019-07-27 15:39:44 -0400, Tom Lane wrote:
>> Unfortunately, I just found out that on a slow enough machine
>> (prairiedog's host) there *is* some variation in when that test's
>> notices come out.  I am unsure whether that's to be expected or
>> whether there's something wrong there

> Hm. Any chance you could show the diff? I don't immediately see why.

Sure.  If I remove the client_min_messages hack from HEAD, then on
my dev workstation I get the attached test diff; that reproduces
quite reliably on a couple of machines.  However, running that
diff on prairiedog's host gets the failure attached second more
often than not.  (Sometimes it will pass.)

            regards, tom lane

diff --git a/src/test/isolation/expected/insert-conflict-specconflict.out
b/src/test/isolation/expected/insert-conflict-specconflict.out
index 5726bdb..20cc421 100644
--- a/src/test/isolation/expected/insert-conflict-specconflict.out
+++ b/src/test/isolation/expected/insert-conflict-specconflict.out
@@ -13,7 +13,11 @@ pg_advisory_locksess           lock
 step controller_show: SELECT * FROM upserttest;
 key            data

+s1: NOTICE:  called for k1
+s1: NOTICE:  blocking 3
 step s1_upsert: INSERT INTO upserttest(key, data) VALUES('k1', 'inserted s1') ON CONFLICT (blurt_and_lock(key)) DO
UPDATESET data = upserttest.data || ' with conflict update s1'; <waiting ...> 
+s2: NOTICE:  called for k1
+s2: NOTICE:  blocking 3
 step s2_upsert: INSERT INTO upserttest(key, data) VALUES('k1', 'inserted s2') ON CONFLICT (blurt_and_lock(key)) DO
UPDATESET data = upserttest.data || ' with conflict update s2'; <waiting ...> 
 step controller_show: SELECT * FROM upserttest;
 key            data
@@ -30,10 +34,14 @@ step controller_unlock_1_3: SELECT pg_advisory_unlock(1, 3);
 pg_advisory_unlock

 t
+s1: NOTICE:  called for k1
+s1: NOTICE:  blocking 2
 step controller_unlock_2_3: SELECT pg_advisory_unlock(2, 3);
 pg_advisory_unlock

 t
+s2: NOTICE:  called for k1
+s2: NOTICE:  blocking 2
 step controller_show: SELECT * FROM upserttest;
 key            data

@@ -50,6 +58,10 @@ step controller_unlock_1_2: SELECT pg_advisory_unlock(1, 2);
 pg_advisory_unlock

 t
+s1: NOTICE:  called for k1
+s1: NOTICE:  blocking 2
+s1: NOTICE:  called for k1
+s1: NOTICE:  blocking 2
 step s1_upsert: <... completed>
 step controller_show: SELECT * FROM upserttest;
 key            data
@@ -69,7 +81,11 @@ pg_advisory_locksess           lock
 step controller_show: SELECT * FROM upserttest;
 key            data

+s1: NOTICE:  called for k1
+s1: NOTICE:  blocking 3
 step s1_upsert: INSERT INTO upserttest(key, data) VALUES('k1', 'inserted s1') ON CONFLICT (blurt_and_lock(key)) DO
UPDATESET data = upserttest.data || ' with conflict update s1'; <waiting ...> 
+s2: NOTICE:  called for k1
+s2: NOTICE:  blocking 3
 step s2_upsert: INSERT INTO upserttest(key, data) VALUES('k1', 'inserted s2') ON CONFLICT (blurt_and_lock(key)) DO
UPDATESET data = upserttest.data || ' with conflict update s2'; <waiting ...> 
 step controller_show: SELECT * FROM upserttest;
 key            data
@@ -86,10 +102,14 @@ step controller_unlock_1_3: SELECT pg_advisory_unlock(1, 3);
 pg_advisory_unlock

 t
+s1: NOTICE:  called for k1
+s1: NOTICE:  blocking 2
 step controller_unlock_2_3: SELECT pg_advisory_unlock(2, 3);
 pg_advisory_unlock

 t
+s2: NOTICE:  called for k1
+s2: NOTICE:  blocking 2
 step controller_show: SELECT * FROM upserttest;
 key            data

@@ -106,6 +126,10 @@ step controller_unlock_2_2: SELECT pg_advisory_unlock(2, 2);
 pg_advisory_unlock

 t
+s2: NOTICE:  called for k1
+s2: NOTICE:  blocking 2
+s2: NOTICE:  called for k1
+s2: NOTICE:  blocking 2
 step s2_upsert: <... completed>
 step controller_show: SELECT * FROM upserttest;
 key            data
@@ -127,7 +151,11 @@ key            data

 step s1_begin: BEGIN;
 step s2_begin: BEGIN;
+s1: NOTICE:  called for k1
+s1: NOTICE:  blocking 3
 step s1_upsert: INSERT INTO upserttest(key, data) VALUES('k1', 'inserted s1') ON CONFLICT (blurt_and_lock(key)) DO
UPDATESET data = upserttest.data || ' with conflict update s1'; <waiting ...> 
+s2: NOTICE:  called for k1
+s2: NOTICE:  blocking 3
 step s2_upsert: INSERT INTO upserttest(key, data) VALUES('k1', 'inserted s2') ON CONFLICT (blurt_and_lock(key)) DO
UPDATESET data = upserttest.data || ' with conflict update s2'; <waiting ...> 
 step controller_show: SELECT * FROM upserttest;
 key            data
@@ -144,10 +172,14 @@ step controller_unlock_1_3: SELECT pg_advisory_unlock(1, 3);
 pg_advisory_unlock

 t
+s1: NOTICE:  called for k1
+s1: NOTICE:  blocking 2
 step controller_unlock_2_3: SELECT pg_advisory_unlock(2, 3);
 pg_advisory_unlock

 t
+s2: NOTICE:  called for k1
+s2: NOTICE:  blocking 2
 step controller_show: SELECT * FROM upserttest;
 key            data

@@ -163,10 +195,16 @@ step controller_unlock_2_2: SELECT pg_advisory_unlock(2, 2);
 pg_advisory_unlock

 t
+s2: NOTICE:  called for k1
+s2: NOTICE:  blocking 2
+s2: NOTICE:  called for k1
+s2: NOTICE:  blocking 2
 step controller_show: SELECT * FROM upserttest;
 key            data

 step s1_commit: COMMIT;
+s2: NOTICE:  called for k1
+s2: NOTICE:  blocking 2
 step s2_upsert: <... completed>
 step controller_show: SELECT * FROM upserttest;
 key            data
diff --git a/src/test/isolation/specs/insert-conflict-specconflict.spec
b/src/test/isolation/specs/insert-conflict-specconflict.spec
index 2d16fae..3a70484 100644
--- a/src/test/isolation/specs/insert-conflict-specconflict.spec
+++ b/src/test/isolation/specs/insert-conflict-specconflict.spec
@@ -51,9 +51,6 @@ session "s1"
 setup
 {
   SET default_transaction_isolation = 'read committed';
-  -- on very slow machines, the notices come out in unpredictable order,
-  -- so hide them
-  SET client_min_messages = warning;
   SET spec.session = 1;
 }
 step "s1_begin"  { BEGIN; }
@@ -64,9 +61,6 @@ session "s2"
 setup
 {
   SET default_transaction_isolation = 'read committed';
-  -- on very slow machines, the notices come out in unpredictable order,
-  -- so hide them
-  SET client_min_messages = warning;
   SET spec.session = 2;
 }
 step "s2_begin"  { BEGIN; }
diff -U3 /Users/tgl/pgsql/src/test/isolation/expected/insert-conflict-specconflict.out
/Users/tgl/pgsql/src/test/isolation/output_iso/results/insert-conflict-specconflict.out
--- /Users/tgl/pgsql/src/test/isolation/expected/insert-conflict-specconflict.out    2019-07-27 18:28:49.000000000
-0400
+++ /Users/tgl/pgsql/src/test/isolation/output_iso/results/insert-conflict-specconflict.out    2019-07-27
18:41:51.000000000-0400 
@@ -13,15 +13,15 @@
 step controller_show: SELECT * FROM upserttest;
 key            data

-s1: NOTICE:  called for k1
-s1: NOTICE:  blocking 3
 step s1_upsert: INSERT INTO upserttest(key, data) VALUES('k1', 'inserted s1') ON CONFLICT (blurt_and_lock(key)) DO
UPDATESET data = upserttest.data || ' with conflict update s1'; <waiting ...> 
-s2: NOTICE:  called for k1
-s2: NOTICE:  blocking 3
 step s2_upsert: INSERT INTO upserttest(key, data) VALUES('k1', 'inserted s2') ON CONFLICT (blurt_and_lock(key)) DO
UPDATESET data = upserttest.data || ' with conflict update s2'; <waiting ...> 
+s1: NOTICE:  called for k1
+s1: NOTICE:  blocking 3
 step controller_show: SELECT * FROM upserttest;
 key            data

+s2: NOTICE:  called for k1
+s2: NOTICE:  blocking 3
 step controller_unlock_1_1: SELECT pg_advisory_unlock(1, 1);
 pg_advisory_unlock