Andres Freund <[email protected]> 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 UPDATE SET 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 UPDATE SET 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 UPDATE SET 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 UPDATE SET 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 UPDATE SET 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 UPDATE SET 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 UPDATE SET 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 UPDATE SET 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
