Received: from malur.postgresql.org ([217.196.149.56]) by arkaria.postgresql.org with esmtps (TLS1.2:ECDHE_RSA_AES_256_CBC_SHA1:256) (Exim 4.89) (envelope-from ) id 1hrVVY-0001qZ-PC for pgsql-hackers@arkaria.postgresql.org; Sat, 27 Jul 2019 22:49:44 +0000 Received: from localhost ([127.0.0.1] helo=malur.postgresql.org) by malur.postgresql.org with esmtp (Exim 4.89) (envelope-from ) id 1hrVUY-0002kY-VW for pgsql-hackers@arkaria.postgresql.org; Sat, 27 Jul 2019 22:48:42 +0000 Received: from makus.postgresql.org ([2001:4800:3e1:1::229]) by malur.postgresql.org with esmtps (TLS1.2:ECDHE_RSA_AES_256_CBC_SHA1:256) (Exim 4.89) (envelope-from ) id 1hrVUY-0002Rv-Fd for pgsql-hackers@lists.postgresql.org; Sat, 27 Jul 2019 22:48:42 +0000 Received: from sss.pgh.pa.us ([66.207.139.130]) by makus.postgresql.org with esmtps (TLS1.2:ECDHE_RSA_AES_256_CBC_SHA1:256) (Exim 4.92) (envelope-from ) id 1hrVUR-0000Db-Oj for pgsql-hackers@lists.postgresql.org; Sat, 27 Jul 2019 22:48:41 +0000 Received: from sss1.sss.pgh.pa.us (localhost [127.0.0.1]) by sss.pgh.pa.us (8.14.4/8.14.4) with ESMTP id x6RMmUco006359; Sat, 27 Jul 2019 18:48:30 -0400 From: Tom Lane To: Andres Freund cc: pgsql-hackers@lists.postgresql.org, Peter Geoghegan Subject: Re: Testing LISTEN/NOTIFY more effectively In-reply-to: <20190727201936.f2oa7h5tkshmeyiq@alap3.anarazel.de> References: <31304.1564246011@sss.pgh.pa.us> <20190727174202.jiwr4jgp3x7gvp22@alap3.anarazel.de> <5720.1564249986@sss.pgh.pa.us> <14616.1564251339@sss.pgh.pa.us> <20190727185502.bciewsyxz642hyq6@alap3.anarazel.de> <13344.1564256384@sss.pgh.pa.us> <20190727201936.f2oa7h5tkshmeyiq@alap3.anarazel.de> Comments: In-reply-to Andres Freund message dated "Sat, 27 Jul 2019 13:19:36 -0700" MIME-Version: 1.0 Content-Type: multipart/mixed; boundary="----- =_aaaaaaaaaa0" Content-ID: <5955.1564267653.0@sss.pgh.pa.us> Date: Sat, 27 Jul 2019 18:48:30 -0400 Message-ID: <6358.1564267710@sss.pgh.pa.us> List-Id: List-Help: List-Subscribe: List-Post: List-Owner: List-Archive: Precedence: bulk ------- =_aaaaaaaaaa0 Content-Type: text/plain; charset="us-ascii" Content-ID: <5955.1564267653.1@sss.pgh.pa.us> Andres Freund 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 ------- =_aaaaaaaaaa0 Content-Type: text/x-diff; name="show-the-intended-notices.patch"; charset="us-ascii" Content-ID: <5955.1564267653.2@sss.pgh.pa.us> Content-Description: show-the-intended-notices.patch Content-Transfer-Encoding: quoted-printable 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 UPDATE SET data =3D upserttest.d= ata || ' with conflict update s1'; +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 UPDATE SET data =3D upserttest.d= ata || ' with conflict update s2'; 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 UPDATE SET data =3D upserttest.d= ata || ' with conflict update s1'; +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 UPDATE SET data =3D upserttest.d= ata || ' with conflict update s2'; 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 UPDATE SET data =3D upserttest.d= ata || ' with conflict update s1'; +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 UPDATE SET data =3D upserttest.d= ata || ' with conflict update s2'; step controller_show: SELECT * FROM upserttest; key data = @@ -144,10 +172,14 @@ step controller_unlock_1_3: SELECT pg_advisory_unloc= k(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_unloc= k(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 =3D 'read committed'; - -- on very slow machines, the notices come out in unpredictable order, - -- so hide them - SET client_min_messages =3D warning; SET spec.session =3D 1; } step "s1_begin" { BEGIN; } @@ -64,9 +61,6 @@ session "s2" setup { SET default_transaction_isolation =3D 'read committed'; - -- on very slow machines, the notices come out in unpredictable order, - -- so hide them - SET client_min_messages =3D warning; SET spec.session =3D 2; } step "s2_begin" { BEGIN; } ------- =_aaaaaaaaaa0 Content-Type: text/x-diff; name="regression.diffs"; charset="us-ascii" Content-ID: <5955.1564267653.3@sss.pgh.pa.us> Content-Description: regression.diffs Content-Transfer-Encoding: quoted-printable diff -U3 /Users/tgl/pgsql/src/test/isolation/expected/insert-conflict-spec= conflict.out /Users/tgl/pgsql/src/test/isolation/output_iso/results/insert= -conflict-specconflict.out --- /Users/tgl/pgsql/src/test/isolation/expected/insert-conflict-specconfl= ict.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 UPDATE SET data =3D upserttest.d= ata || ' with conflict update s1'; -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 UPDATE SET data =3D upserttest.d= ata || ' with conflict update s2'; +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 = ------- =_aaaaaaaaaa0--