diff --git a/src/test/isolation/expected/insert-conflict-specconflict.out b/src/test/isolation/expected/insert-conflict-specconflict.out index 5726bdb8e8..20cc421b87 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'; +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'; 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'; +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'; 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'; +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'; 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/expected/plpgsql-toast.out b/src/test/isolation/expected/plpgsql-toast.out index 43411533f1..fc557da5e7 100644 --- a/src/test/isolation/expected/plpgsql-toast.out +++ b/src/test/isolation/expected/plpgsql-toast.out @@ -22,7 +22,7 @@ do $$ delete from test1; commit; perform pg_advisory_lock(1); - raise notice 'x = %', x; + raise notice 'length(x) = %', length(x); end; $$; @@ -35,6 +35,7 @@ step unlock: pg_advisory_unlock t +s1: NOTICE: length(x) = 6000 step assign1: <... completed> starting permutation: lock assign2 vacuum unlock @@ -59,7 +60,7 @@ do $$ delete from test1; commit; perform pg_advisory_lock(1); - raise notice 'x = %', x; + raise notice 'length(x) = %', length(x); end; $$; @@ -72,6 +73,7 @@ step unlock: pg_advisory_unlock t +s1: NOTICE: length(x) = 6000 step assign2: <... completed> starting permutation: lock assign3 vacuum unlock @@ -97,7 +99,7 @@ do $$ delete from test1; commit; perform pg_advisory_lock(1); - raise notice 'r = %', r; + raise notice 'length(r) = %', length(r::text); end; $$; @@ -110,6 +112,7 @@ step unlock: pg_advisory_unlock t +s1: NOTICE: length(r) = 6004 step assign3: <... completed> starting permutation: lock assign4 vacuum unlock @@ -134,7 +137,7 @@ do $$ delete from test1; commit; perform pg_advisory_lock(1); - raise notice 'r = %', r; + raise notice 'length(r) = %', length(r::text); end; $$; @@ -147,6 +150,7 @@ step unlock: pg_advisory_unlock t +s1: NOTICE: length(r) = 6004 step assign4: <... completed> starting permutation: lock assign5 vacuum unlock @@ -173,7 +177,7 @@ do $$ delete from test1; commit; perform pg_advisory_lock(1); - raise notice 'r = %', r; + raise notice 'length(r) = %', length(r::text); end; $$; @@ -186,4 +190,5 @@ step unlock: pg_advisory_unlock t +s1: NOTICE: length(r) = 6002 step assign5: <... completed> diff --git a/src/test/isolation/expected/vacuum-concurrent-drop.out b/src/test/isolation/expected/vacuum-concurrent-drop.out index bb92e80b92..cf348d7e5d 100644 --- a/src/test/isolation/expected/vacuum-concurrent-drop.out +++ b/src/test/isolation/expected/vacuum-concurrent-drop.out @@ -10,7 +10,7 @@ step drop_and_commit: DROP TABLE part2; COMMIT; -WARNING: skipping vacuum of "part2" --- relation no longer exists +s2: WARNING: skipping vacuum of "part2" --- relation no longer exists step vac_specified: <... completed> starting permutation: lock vac_all_parts drop_and_commit @@ -35,7 +35,7 @@ step drop_and_commit: DROP TABLE part2; COMMIT; -WARNING: skipping analyze of "part2" --- relation no longer exists +s2: WARNING: skipping analyze of "part2" --- relation no longer exists step analyze_specified: <... completed> starting permutation: lock analyze_all_parts drop_and_commit @@ -60,7 +60,7 @@ step drop_and_commit: DROP TABLE part2; COMMIT; -WARNING: skipping vacuum of "part2" --- relation no longer exists +s2: WARNING: skipping vacuum of "part2" --- relation no longer exists step vac_analyze_specified: <... completed> starting permutation: lock vac_analyze_all_parts drop_and_commit diff --git a/src/test/isolation/isolationtester.c b/src/test/isolation/isolationtester.c index d32dbb7d68..1d1cc12306 100644 --- a/src/test/isolation/isolationtester.c +++ b/src/test/isolation/isolationtester.c @@ -48,6 +48,8 @@ static int step_qsort_cmp(const void *a, const void *b); static int step_bsearch_cmp(const void *a, const void *b); static void printResultSet(PGresult *res); +static void isotesterNoticeProcessor(void *arg, const char *message); +static void blackholeNoticeProcessor(void *arg, const char *message); /* close all connections and exit */ static void @@ -172,16 +174,19 @@ main(int argc, char **argv) } /* - * Suppress NOTIFY messages, which otherwise pop into results at odd - * places. + * Set up notice processors for the user-defined connections, so that + * messages can get printed prefixed with the session names. The + * control connection gets a "blackhole" processor instead (hides all + * messages). */ - res = PQexec(conns[i], "SET client_min_messages = warning;"); - if (PQresultStatus(res) != PGRES_COMMAND_OK) - { - fprintf(stderr, "message level setup failed: %s", PQerrorMessage(conns[i])); - exit_nicely(); - } - PQclear(res); + if (i != 0) + PQsetNoticeProcessor(conns[i], + isotesterNoticeProcessor, + (void *) (testspec->sessions[i - 1]->name)); + else + PQsetNoticeProcessor(conns[i], + blackholeNoticeProcessor, + NULL); /* Get the backend pid for lock wait checking. */ res = PQexec(conns[i], "SELECT pg_backend_pid()"); @@ -751,6 +756,28 @@ try_complete_step(Step *step, int flags) if (waiting) /* waiting to acquire a lock */ { + /* + * Since it takes time to perform the lock-check query, + * some data --- notably, NOTICE messages --- might have + * arrived since we looked. We must call PQconsumeInput + * and then PQisBusy to collect and process any such + * messages. In the (unlikely) case that PQisBusy then + * returns false, we might as well go examine the + * available result. + */ + if (!PQconsumeInput(conn)) + { + fprintf(stderr, "PQconsumeInput failed: %s\n", + PQerrorMessage(conn)); + exit(1); + } + if (!PQisBusy(conn)) + break; + + /* + * conn is still busy, so conclude that the step really is + * waiting. + */ if (!(flags & STEP_RETRY)) printf("step %s: %s \n", step->name, step->sql); @@ -881,3 +908,17 @@ printResultSet(PGresult *res) printf("\n"); } } + +/* notice processor, prefixes each message with the session name */ +static void +isotesterNoticeProcessor(void *arg, const char *message) +{ + printf("%s: %s", (char *) arg, message); +} + +/* notice processor, hides the message */ +static void +blackholeNoticeProcessor(void *arg, const char *message) +{ + /* do nothing */ +} diff --git a/src/test/isolation/specs/plpgsql-toast.spec b/src/test/isolation/specs/plpgsql-toast.spec index e6228c9ef6..fe7090addb 100644 --- a/src/test/isolation/specs/plpgsql-toast.spec +++ b/src/test/isolation/specs/plpgsql-toast.spec @@ -40,7 +40,7 @@ do $$ delete from test1; commit; perform pg_advisory_lock(1); - raise notice 'x = %', x; + raise notice 'length(x) = %', length(x); end; $$; } @@ -56,7 +56,7 @@ do $$ delete from test1; commit; perform pg_advisory_lock(1); - raise notice 'x = %', x; + raise notice 'length(x) = %', length(x); end; $$; } @@ -73,7 +73,7 @@ do $$ delete from test1; commit; perform pg_advisory_lock(1); - raise notice 'r = %', r; + raise notice 'length(r) = %', length(r::text); end; $$; } @@ -89,7 +89,7 @@ do $$ delete from test1; commit; perform pg_advisory_lock(1); - raise notice 'r = %', r; + raise notice 'length(r) = %', length(r::text); end; $$; } @@ -107,7 +107,7 @@ do $$ delete from test1; commit; perform pg_advisory_lock(1); - raise notice 'r = %', r; + raise notice 'length(r) = %', length(r::text); end; $$; }