Skip to content

Commit 3071763

Browse files
tglsfdctglsfdc
committed
Fix isolationtester race condition for notices sent before blocking.
If a test sends a notice just before blocking, it's possible on slow machines for isolationtester to detect the blocked state before it's consumed the notice. (For this to happen, the notice would have to arrive after isolationtester has waited for data for 10ms, so on fast/lightly-loaded machines it's hard to reproduce the failure.) But, if we have seen the backend as blocked, it's certainly already sent any notices it's going to send. Therefore, one more round of PQconsumeInput and PQisBusy should be enough to collect and process any such notices. This appears to explain the instability noted in commit ebd4992, so undo the hack therein to not print notices from insert-conflict-specconflict. Patch by me, diagnosis by Andres Freund. Discussion: https://postgr.es/m/14616.1564251339@sss.pgh.pa.us
1 parent ebd4992 commit 3071763

File tree

3 files changed

+60
-6
lines changed

3 files changed

+60
-6
lines changed

‎src/test/isolation/expected/insert-conflict-specconflict.out‎

Lines changed: 38 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -13,7 +13,11 @@ pg_advisory_locksess lock
1313
step controller_show: SELECT * FROM upserttest;
1414
key data
1515

16+
s1: NOTICE: called for k1
17+
s1: NOTICE: blocking 3
1618
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 ...>
19+
s2: NOTICE: called for k1
20+
s2: NOTICE: blocking 3
1721
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 ...>
1822
step controller_show: SELECT * FROM upserttest;
1923
key data
@@ -30,10 +34,14 @@ step controller_unlock_1_3: SELECT pg_advisory_unlock(1, 3);
3034
pg_advisory_unlock
3135

3236
t
37+
s1: NOTICE: called for k1
38+
s1: NOTICE: blocking 2
3339
step controller_unlock_2_3: SELECT pg_advisory_unlock(2, 3);
3440
pg_advisory_unlock
3541

3642
t
43+
s2: NOTICE: called for k1
44+
s2: NOTICE: blocking 2
3745
step controller_show: SELECT * FROM upserttest;
3846
key data
3947

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

5260
t
61+
s1: NOTICE: called for k1
62+
s1: NOTICE: blocking 2
63+
s1: NOTICE: called for k1
64+
s1: NOTICE: blocking 2
5365
step s1_upsert: <... completed>
5466
step controller_show: SELECT * FROM upserttest;
5567
key data
@@ -69,7 +81,11 @@ pg_advisory_locksess lock
6981
step controller_show: SELECT * FROM upserttest;
7082
key data
7183

84+
s1: NOTICE: called for k1
85+
s1: NOTICE: blocking 3
7286
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 ...>
87+
s2: NOTICE: called for k1
88+
s2: NOTICE: blocking 3
7389
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 ...>
7490
step controller_show: SELECT * FROM upserttest;
7591
key data
@@ -86,10 +102,14 @@ step controller_unlock_1_3: SELECT pg_advisory_unlock(1, 3);
86102
pg_advisory_unlock
87103

88104
t
105+
s1: NOTICE: called for k1
106+
s1: NOTICE: blocking 2
89107
step controller_unlock_2_3: SELECT pg_advisory_unlock(2, 3);
90108
pg_advisory_unlock
91109

92110
t
111+
s2: NOTICE: called for k1
112+
s2: NOTICE: blocking 2
93113
step controller_show: SELECT * FROM upserttest;
94114
key data
95115

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

108128
t
129+
s2: NOTICE: called for k1
130+
s2: NOTICE: blocking 2
131+
s2: NOTICE: called for k1
132+
s2: NOTICE: blocking 2
109133
step s2_upsert: <... completed>
110134
step controller_show: SELECT * FROM upserttest;
111135
key data
@@ -127,7 +151,11 @@ key data
127151

128152
step s1_begin: BEGIN;
129153
step s2_begin: BEGIN;
154+
s1: NOTICE: called for k1
155+
s1: NOTICE: blocking 3
130156
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 ...>
157+
s2: NOTICE: called for k1
158+
s2: NOTICE: blocking 3
131159
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 ...>
132160
step controller_show: SELECT * FROM upserttest;
133161
key data
@@ -144,10 +172,14 @@ step controller_unlock_1_3: SELECT pg_advisory_unlock(1, 3);
144172
pg_advisory_unlock
145173

146174
t
175+
s1: NOTICE: called for k1
176+
s1: NOTICE: blocking 2
147177
step controller_unlock_2_3: SELECT pg_advisory_unlock(2, 3);
148178
pg_advisory_unlock
149179

150180
t
181+
s2: NOTICE: called for k1
182+
s2: NOTICE: blocking 2
151183
step controller_show: SELECT * FROM upserttest;
152184
key data
153185

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

165197
t
198+
s2: NOTICE: called for k1
199+
s2: NOTICE: blocking 2
200+
s2: NOTICE: called for k1
201+
s2: NOTICE: blocking 2
166202
step controller_show: SELECT * FROM upserttest;
167203
key data
168204

169205
step s1_commit: COMMIT;
206+
s2: NOTICE: called for k1
207+
s2: NOTICE: blocking 2
170208
step s2_upsert: <... completed>
171209
step controller_show: SELECT * FROM upserttest;
172210
key data

‎src/test/isolation/isolationtester.c‎

Lines changed: 22 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -752,6 +752,28 @@ try_complete_step(Step *step, int flags)
752752

753753
if (waiting) /* waiting to acquire a lock */
754754
{
755+
/*
756+
* Since it takes time to perform the lock-check query,
757+
* some data --- notably, NOTICE messages --- might have
758+
* arrived since we looked. We must call PQconsumeInput
759+
* and then PQisBusy to collect and process any such
760+
* messages. In the (unlikely) case that PQisBusy then
761+
* returns false, we might as well go examine the
762+
* available result.
763+
*/
764+
if (!PQconsumeInput(conn))
765+
{
766+
fprintf(stderr, "PQconsumeInput failed: %s\n",
767+
PQerrorMessage(conn));
768+
exit(1);
769+
}
770+
if (!PQisBusy(conn))
771+
break;
772+
773+
/*
774+
* conn is still busy, so conclude that the step really is
775+
* waiting.
776+
*/
755777
if (!(flags & STEP_RETRY))
756778
printf("step %s: %s <waiting ...>\n",
757779
step->name, step->sql);

‎src/test/isolation/specs/insert-conflict-specconflict.spec‎

Lines changed: 0 additions & 6 deletions
Original file line numberDiff line numberDiff line change
@@ -51,9 +51,6 @@ session "s1"
5151
setup
5252
{
5353
SET default_transaction_isolation = 'read committed';
54-
-- on very slow machines, the notices come out in unpredictable order,
55-
-- so hide them
56-
SET client_min_messages = warning;
5754
SET spec.session = 1;
5855
}
5956
step "s1_begin" { BEGIN; }
@@ -64,9 +61,6 @@ session "s2"
6461
setup
6562
{
6663
SET default_transaction_isolation = 'read committed';
67-
-- on very slow machines, the notices come out in unpredictable order,
68-
-- so hide them
69-
SET client_min_messages = warning;
7064
SET spec.session = 2;
7165
}
7266
step "s2_begin" { BEGIN; }

0 commit comments

Comments
 (0)