Обсуждение: Testing LISTEN/NOTIFY more effectively
Since we have three or four different NOTIFY improvement proposals
floating around in the current CF, I got a bit distressed at the lack
of test coverage for that functionality. While the code coverage
report makes it look like commands/async.c isn't so badly covered,
that's all coming from src/test/regress/sql/async.sql and
src/test/isolation/specs/async-notify.spec. A look at those files
shows that nowhere is there any actual verification that "NOTIFY foo"
results in a report of "foo" being received; let alone any
more-advanced questions such as whether de-duplication of reports
happens.
The reason for this is that psql's report of a notification event
includes the sending backend's PID, making it impossible for the
test output to be stable; neither the core nor isolation regression
test frameworks can cope with unpredictable output.
We've occasionally batted around ideas for making it possible for
these test frameworks to verify not-entirely-fixed output, and that
would be a good thing to do, but I'm not volunteering for that today.
So, if we'd like to have more thorough NOTIFY coverage without going
to that much work, what to do? I thought of a few alternatives:
1. Write a TAP test instead of using the old test frameworks, and
use regexps to check the expected output. But this seems ugly and
hard to get right. In particular, our TAP infrastructure doesn't
seem to be (easily?) capable of running concurrent psql sessions,
so it doesn't seem like there's any good way to test cross-session
notifies that way.
2. Change psql so that there's a way to get NOTIFY messages without
the sending PID. For testing purposes, it'd be sufficient to know
whether the sending PID is our own backend's PID or not. This idea
is not horrible, and it might even be useful for outside purposes
if we made it flexible enough; which leads to thoughts like allowing
the psql user to set a format-style string, similar to the PROMPT
strings but with escapes for channel name, payload, etc. I foresee
bikeshedding, but we could probably come to an agreement on a feature
like that.
3. On the other hand, that doesn't help much for the isolation tester
because it doesn't go through psql. In fact, AFAICS it doesn't have
any provision for dealing with notify messages at all; probably,
in the async-notify.spec test, the listening session builds up a
queue of notifies that it never reads. So we could imagine addressing
the testing gap strictly inside the isolation-tester framework, if we
added the ability for it to detect and print notifications in a
test-friendly format (no explicit PIDs).
I'm finding alternative #3 the most attractive, because we really
want isolation-style testing for LISTEN/NOTIFY, and this solution
doesn't require designing a psql feature that we'd need to get
consensus on.
Before I start coding that, any thoughts or better ideas?
regards, tom lane
Hi, On 2019-07-27 12:46:51 -0400, Tom Lane wrote: > So, if we'd like to have more thorough NOTIFY coverage without going > to that much work, what to do? I thought of a few alternatives: > > 1. Write a TAP test instead of using the old test frameworks, and > use regexps to check the expected output. But this seems ugly and > hard to get right. In particular, our TAP infrastructure doesn't > seem to be (easily?) capable of running concurrent psql sessions, > so it doesn't seem like there's any good way to test cross-session > notifies that way. It's not that hard to have concurrent psql sessions - e.g. src/test/recovery/t/013_crash_restart.pl does so. Writing tests by interactively controlling psql is pretty painful regardless. I'm inclined to think that this is better tested using isolationtester than a tap test. > 2. Change psql so that there's a way to get NOTIFY messages without > the sending PID. For testing purposes, it'd be sufficient to know > whether the sending PID is our own backend's PID or not. This idea > is not horrible, and it might even be useful for outside purposes > if we made it flexible enough; which leads to thoughts like allowing > the psql user to set a format-style string, similar to the PROMPT > strings but with escapes for channel name, payload, etc. I foresee > bikeshedding, but we could probably come to an agreement on a feature > like that. I was wondering about just tying it to VERBOSITY. But that'd not allow us to see whether our backend was the sender. I'm mildly inclined to think that that might still be a good idea, even if we mostly go with 3) - some basic plain regression test coverage of actually receiving notifies would be good. > 3. On the other hand, that doesn't help much for the isolation tester > because it doesn't go through psql. In fact, AFAICS it doesn't have > any provision for dealing with notify messages at all; probably, > in the async-notify.spec test, the listening session builds up a > queue of notifies that it never reads. So we could imagine addressing > the testing gap strictly inside the isolation-tester framework, if we > added the ability for it to detect and print notifications in a > test-friendly format (no explicit PIDs). > > I'm finding alternative #3 the most attractive, because we really > want isolation-style testing for LISTEN/NOTIFY, and this solution > doesn't require designing a psql feature that we'd need to get > consensus on. Yea. I think that's really what need. As you say, the type of test we really need is what isolationtester provides. We can reimplement it awkwardly in perl, but there seems to be little point in doing so. Especially as what we're talking about is an additional ~15 lines or so of code in isolationtester. It'd be kinda neat if we had other information in the notify message. E.g. having access to the sender's application name would be useful for isolationtester, to actually verify where the message came from. But it's probably not worth investing a lot in that. Perhaps we could just have isolationtester check to which isolationtester session the backend pid belongs? And then print the session name instead of the pid? That should be fairly easy, and would probably give us all we need? Greetings, Andres Freund
Andres Freund <andres@anarazel.de> writes:
> On 2019-07-27 12:46:51 -0400, Tom Lane wrote:
>> I'm finding alternative #3 the most attractive, because we really
>> want isolation-style testing for LISTEN/NOTIFY, and this solution
>> doesn't require designing a psql feature that we'd need to get
>> consensus on.
> Perhaps we could just have isolationtester check to which
> isolationtester session the backend pid belongs? And then print the
> session name instead of the pid? That should be fairly easy, and would
> probably give us all we need?
Oh, that's a good idea -- it's already tracking all the backend PIDs,
so probably not much extra work to do it like that.
regards, tom lane
While I'm looking at isolationtester ... my eye was immediately drawn
to this bit, because it claims to be dealing with NOTIFY messages ---
though that's wrong, it's really blocking NOTICE messages:
/*
* Suppress NOTIFY messages, which otherwise pop into results at odd
* places.
*/
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(1);
}
PQclear(res);
This seems to me to be a great example of terrible test design.
It's not isolationtester's job to impose a client_min_messages level
on the test scripts; if they want a non-default level, they can
perfectly well set it for themselves in their setup sections.
Furthermore, if I remove this bit, the only NOTICE messages I'm
actually seeing come from explicit RAISE NOTICE messages in the
test scripts themselves, which means this is overriding the express
intent of individual test authors. And my testing isn't detecting
any instability in when those come out, although of course the
buildfarm might have a different opinion.
So I think we should apply something like the attached, and if the
buildfarm shows any instability as a result, dealing with that by
taking out the RAISE NOTICE commands.
I'm a little inclined to remove the notice anyway in the
plpgsql-toast test, as the bulk-to-value ratio doesn't seem good.
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/expected/plpgsql-toast.out b/src/test/isolation/expected/plpgsql-toast.out
index 4341153..39a7bbe 100644
--- a/src/test/isolation/expected/plpgsql-toast.out
+++ b/src/test/isolation/expected/plpgsql-toast.out
@@ -35,6 +35,7 @@ step unlock:
pg_advisory_unlock
t
+s1: NOTICE: x =
foofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoo
step assign1: <... completed>
starting permutation: lock assign2 vacuum unlock
@@ -72,6 +73,7 @@ step unlock:
pg_advisory_unlock
t
+s1: NOTICE: x =
foofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoo
step assign2: <... completed>
starting permutation: lock assign3 vacuum unlock
@@ -110,6 +112,7 @@ step unlock:
pg_advisory_unlock
t
+s1: NOTICE: r =
(1,foofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoo)
step assign3: <... completed>
starting permutation: lock assign4 vacuum unlock
@@ -147,6 +150,7 @@ step unlock:
pg_advisory_unlock
t
+s1: NOTICE: r =
(1,foofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoo)
step assign4: <... completed>
starting permutation: lock assign5 vacuum unlock
@@ -186,4 +190,5 @@ step unlock:
pg_advisory_unlock
t
+s1: NOTICE: r =
(foofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoofoo)
step assign5: <... completed>
diff --git a/src/test/isolation/isolationtester.c b/src/test/isolation/isolationtester.c
index 2f039b8..9a89468 100644
--- a/src/test/isolation/isolationtester.c
+++ b/src/test/isolation/isolationtester.c
@@ -187,18 +187,6 @@ main(int argc, char **argv)
blackholeNoticeProcessor,
NULL);
- /*
- * Suppress NOTIFY messages, which otherwise pop into results at odd
- * places.
- */
- 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(1);
- }
- PQclear(res);
-
/* Get the backend pid for lock wait checking. */
res = PQexec(conns[i], "SELECT pg_catalog.pg_backend_pid()");
if (PQresultStatus(res) == PGRES_TUPLES_OK)
Hi,
On 2019-07-27 14:15:39 -0400, Tom Lane wrote:
> So I think we should apply something like the attached, and if the
> buildfarm shows any instability as a result, dealing with that by
> taking out the RAISE NOTICE commands.
+1
> 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
Hm, that actually makes the test - which is pretty complicated - easier
to understand.
> diff --git a/src/test/isolation/expected/plpgsql-toast.out b/src/test/isolation/expected/plpgsql-toast.out
> index 4341153..39a7bbe 100644
> --- a/src/test/isolation/expected/plpgsql-toast.out
> +++ b/src/test/isolation/expected/plpgsql-toast.out
> @@ -35,6 +35,7 @@ step unlock:
> pg_advisory_unlock
>
> t
> +s1: NOTICE: x = foofoofoofo
Yea, there indeed does not not much point in this.
Greetings,
Andres Freund
Andres Freund <andres@anarazel.de> writes:
> On 2019-07-27 14:15:39 -0400, Tom Lane wrote:
>> So I think we should apply something like the attached, and if the
>> buildfarm shows any instability as a result, dealing with that by
>> taking out the RAISE NOTICE commands.
> +1
>> 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
> Hm, that actually makes the test - which is pretty complicated - easier
> to understand.
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 --- Peter, any thoughts?
What I will do for the moment is remove the client_min_messages=WARNING
setting from isolationtester.c and instead put it into
insert-conflict-specconflict.spec, which seems like a saner
way to manage this. If we can get these messages to appear
stably, we can just fix that spec file.
>> +s1: NOTICE: x = foofoofoofo
> Yea, there indeed does not not much point in this.
Maybe we could just log the lengths of the strings... if there's
anything broken, we could expect that the decompressed output
would be a different length.
regards, tom lane
Hi,
On 2019-07-27 15:39:44 -0400, Tom Lane wrote:
> Andres Freund <andres@anarazel.de> writes:
> >> 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
>
> > Hm, that actually makes the test - which is pretty complicated - easier
> > to understand.
>
> 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.
> --- Peter, any thoughts?
Think that's my transgression :/
> What I will do for the moment is remove the client_min_messages=WARNING
> setting from isolationtester.c and instead put it into
> insert-conflict-specconflict.spec, which seems like a saner
> way to manage this. If we can get these messages to appear
> stably, we can just fix that spec file.
Makes sense.
Greetings,
Andres Freund
On Sat, Jul 27, 2019 at 12:39 PM Tom Lane <tgl@sss.pgh.pa.us> 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 --- Peter, any thoughts?
I don't know why this happens, but it's worth noting that the plpgsql
function that raises these notices ("blurt_and_lock()") is marked
IMMUTABLE (not sure if you noticed that already). This is a deliberate
misrepresentation which is needed to acquire advisory locks at just
the right points during execution.
If I had to guess, I'd guess that it had something to do with that. I
might be able to come up with a better explanation if I saw the diff.
--
Peter Geoghegan
I wrote:
> Andres Freund <andres@anarazel.de> writes:
>> Perhaps we could just have isolationtester check to which
>> isolationtester session the backend pid belongs? And then print the
>> session name instead of the pid? That should be fairly easy, and would
>> probably give us all we need?
> Oh, that's a good idea -- it's already tracking all the backend PIDs,
> so probably not much extra work to do it like that.
I found out that to avoid confusion, one really wants the message to
identify both the sending and receiving sessions. Here's a patch
that does it that way and extends the async-notify.spec test to
perform basic end-to-end checks on LISTEN/NOTIFY.
I intentionally made the test show the lack of NOTIFY de-deduplication
that currently happens with subtransactions. If we change this as I
proposed in <17822.1564186806@sss.pgh.pa.us>, this test output will
change.
regards, tom lane
diff --git a/src/test/isolation/expected/async-notify.out b/src/test/isolation/expected/async-notify.out
index 92d281a..3dc1227 100644
--- a/src/test/isolation/expected/async-notify.out
+++ b/src/test/isolation/expected/async-notify.out
@@ -1,17 +1,82 @@
Parsed test spec with 2 sessions
-starting permutation: listen begin check notify check
-step listen: LISTEN a;
-step begin: BEGIN;
-step check: SELECT pg_notification_queue_usage() > 0 AS nonzero;
+starting permutation: listenc notify1 notify2 notify3
+step listenc: LISTEN c1; LISTEN c2;
+step notify1: NOTIFY c1;
+notifier: NOTIFY "c1" with payload "" from notifier
+step notify2: NOTIFY c2, 'payload';
+notifier: NOTIFY "c2" with payload "payload" from notifier
+step notify3: NOTIFY c3, 'payload3';
+
+starting permutation: listenc notifyd notifys1
+step listenc: LISTEN c1; LISTEN c2;
+step notifyd: NOTIFY c2, 'payload'; NOTIFY c1; NOTIFY "c2", 'payload';
+notifier: NOTIFY "c2" with payload "payload" from notifier
+notifier: NOTIFY "c1" with payload "" from notifier
+step notifys1:
+ BEGIN;
+ NOTIFY c1, 'payload1'; NOTIFY "c2", 'payload2';
+ NOTIFY c1, 'payload1'; NOTIFY "c2", 'payload2';
+ SAVEPOINT s1;
+ NOTIFY c1, 'payload1'; NOTIFY "c2", 'payload2';
+ NOTIFY c1, 'payload1s'; NOTIFY "c2", 'payload2s';
+ NOTIFY c1, 'payload1'; NOTIFY "c2", 'payload2';
+ NOTIFY c1, 'payload1s'; NOTIFY "c2", 'payload2s';
+ RELEASE SAVEPOINT s1;
+ SAVEPOINT s2;
+ NOTIFY c1, 'rpayload1'; NOTIFY "c2", 'rpayload2';
+ NOTIFY c1, 'rpayload1s'; NOTIFY "c2", 'rpayload2s';
+ NOTIFY c1, 'rpayload1'; NOTIFY "c2", 'rpayload2';
+ NOTIFY c1, 'rpayload1s'; NOTIFY "c2", 'rpayload2s';
+ ROLLBACK TO SAVEPOINT s2;
+ COMMIT;
+
+notifier: NOTIFY "c1" with payload "payload1" from notifier
+notifier: NOTIFY "c2" with payload "payload2" from notifier
+notifier: NOTIFY "c1" with payload "payload1" from notifier
+notifier: NOTIFY "c2" with payload "payload2" from notifier
+notifier: NOTIFY "c1" with payload "payload1s" from notifier
+notifier: NOTIFY "c2" with payload "payload2s" from notifier
+
+starting permutation: llisten notify1 notify2 notify3 lcheck
+step llisten: LISTEN c1; LISTEN c2;
+step notify1: NOTIFY c1;
+step notify2: NOTIFY c2, 'payload';
+step notify3: NOTIFY c3, 'payload3';
+step lcheck: SELECT 1 AS x;
+x
+
+1
+listener: NOTIFY "c1" with payload "" from notifier
+listener: NOTIFY "c2" with payload "payload" from notifier
+
+starting permutation: listenc llisten notify1 notify2 notify3 lcheck
+step listenc: LISTEN c1; LISTEN c2;
+step llisten: LISTEN c1; LISTEN c2;
+step notify1: NOTIFY c1;
+notifier: NOTIFY "c1" with payload "" from notifier
+step notify2: NOTIFY c2, 'payload';
+notifier: NOTIFY "c2" with payload "payload" from notifier
+step notify3: NOTIFY c3, 'payload3';
+step lcheck: SELECT 1 AS x;
+x
+
+1
+listener: NOTIFY "c1" with payload "" from notifier
+listener: NOTIFY "c2" with payload "payload" from notifier
+
+starting permutation: llisten lbegin usage bignotify usage
+step llisten: LISTEN c1; LISTEN c2;
+step lbegin: BEGIN;
+step usage: SELECT pg_notification_queue_usage() > 0 AS nonzero;
nonzero
f
-step notify: SELECT count(pg_notify('a', s::text)) FROM generate_series(1, 1000) s;
+step bignotify: SELECT count(pg_notify('c1', s::text)) FROM generate_series(1, 1000) s;
count
1000
-step check: SELECT pg_notification_queue_usage() > 0 AS nonzero;
+step usage: SELECT pg_notification_queue_usage() > 0 AS nonzero;
nonzero
t
diff --git a/src/test/isolation/isolationtester.c b/src/test/isolation/isolationtester.c
index 6ab19b1..98e5bf2 100644
--- a/src/test/isolation/isolationtester.c
+++ b/src/test/isolation/isolationtester.c
@@ -23,10 +23,12 @@
/*
* conns[0] is the global setup, teardown, and watchdog connection. Additional
- * connections represent spec-defined sessions.
+ * connections represent spec-defined sessions. We also track the backend
+ * PID, in numeric and string formats, for each connection.
*/
static PGconn **conns = NULL;
-static const char **backend_pids = NULL;
+static int *backend_pids = NULL;
+static const char **backend_pid_strs = NULL;
static int nconns = 0;
/* In dry run only output permutations to be run by the tester. */
@@ -41,7 +43,7 @@ static void run_permutation(TestSpec *testspec, int nsteps, Step **steps);
#define STEP_NONBLOCK 0x1 /* return 0 as soon as cmd waits for a lock */
#define STEP_RETRY 0x2 /* this is a retry of a previously-waiting cmd */
-static bool try_complete_step(Step *step, int flags);
+static bool try_complete_step(TestSpec *testspec, Step *step, int flags);
static int step_qsort_cmp(const void *a, const void *b);
static int step_bsearch_cmp(const void *a, const void *b);
@@ -159,9 +161,11 @@ main(int argc, char **argv)
* extra for lock wait detection and global work.
*/
nconns = 1 + testspec->nsessions;
- conns = calloc(nconns, sizeof(PGconn *));
+ conns = (PGconn **) pg_malloc0(nconns * sizeof(PGconn *));
+ backend_pids = pg_malloc0(nconns * sizeof(*backend_pids));
+ backend_pid_strs = pg_malloc0(nconns * sizeof(*backend_pid_strs));
atexit(disconnect_atexit);
- backend_pids = calloc(nconns, sizeof(*backend_pids));
+
for (i = 0; i < nconns; i++)
{
conns[i] = PQconnectdb(conninfo);
@@ -187,26 +191,9 @@ main(int argc, char **argv)
blackholeNoticeProcessor,
NULL);
- /* Get the backend pid for lock wait checking. */
- res = PQexec(conns[i], "SELECT pg_catalog.pg_backend_pid()");
- if (PQresultStatus(res) == PGRES_TUPLES_OK)
- {
- if (PQntuples(res) == 1 && PQnfields(res) == 1)
- backend_pids[i] = pg_strdup(PQgetvalue(res, 0, 0));
- else
- {
- fprintf(stderr, "backend pid query returned %d rows and %d columns, expected 1 row and 1 column",
- PQntuples(res), PQnfields(res));
- exit(1);
- }
- }
- else
- {
- fprintf(stderr, "backend pid query failed: %s",
- PQerrorMessage(conns[i]));
- exit(1);
- }
- PQclear(res);
+ /* Save each connection's backend PID for subsequent use. */
+ backend_pids[i] = PQbackendPID(conns[i]);
+ backend_pid_strs[i] = psprintf("%d", backend_pids[i]);
}
/* Set the session index fields in steps. */
@@ -231,9 +218,9 @@ main(int argc, char **argv)
appendPQExpBufferStr(&wait_query,
"SELECT pg_catalog.pg_isolation_test_session_is_blocked($1, '{");
/* The spec syntax requires at least one session; assume that here. */
- appendPQExpBufferStr(&wait_query, backend_pids[1]);
+ appendPQExpBufferStr(&wait_query, backend_pid_strs[1]);
for (i = 2; i < nconns; i++)
- appendPQExpBuffer(&wait_query, ",%s", backend_pids[i]);
+ appendPQExpBuffer(&wait_query, ",%s", backend_pid_strs[i]);
appendPQExpBufferStr(&wait_query, "}')");
res = PQprepare(conns[0], PREP_WAITING, wait_query.data, 0, NULL);
@@ -549,7 +536,7 @@ run_permutation(TestSpec *testspec, int nsteps, Step **steps)
oldstep = waiting[w];
/* Wait for previous step on this connection. */
- try_complete_step(oldstep, STEP_RETRY);
+ try_complete_step(testspec, oldstep, STEP_RETRY);
/* Remove that step from the waiting[] array. */
if (w + 1 < nwaiting)
@@ -571,7 +558,8 @@ run_permutation(TestSpec *testspec, int nsteps, Step **steps)
nerrorstep = 0;
while (w < nwaiting)
{
- if (try_complete_step(waiting[w], STEP_NONBLOCK | STEP_RETRY))
+ if (try_complete_step(testspec, waiting[w],
+ STEP_NONBLOCK | STEP_RETRY))
{
/* Still blocked on a lock, leave it alone. */
w++;
@@ -600,14 +588,15 @@ run_permutation(TestSpec *testspec, int nsteps, Step **steps)
}
/* Try to complete this step without blocking. */
- mustwait = try_complete_step(step, STEP_NONBLOCK);
+ mustwait = try_complete_step(testspec, step, STEP_NONBLOCK);
/* Check for completion of any steps that were previously waiting. */
w = 0;
nerrorstep = 0;
while (w < nwaiting)
{
- if (try_complete_step(waiting[w], STEP_NONBLOCK | STEP_RETRY))
+ if (try_complete_step(testspec, waiting[w],
+ STEP_NONBLOCK | STEP_RETRY))
w++;
else
{
@@ -630,7 +619,7 @@ run_permutation(TestSpec *testspec, int nsteps, Step **steps)
/* Wait for any remaining queries. */
for (w = 0; w < nwaiting; ++w)
{
- try_complete_step(waiting[w], STEP_RETRY);
+ try_complete_step(testspec, waiting[w], STEP_RETRY);
report_error_message(waiting[w]);
}
@@ -693,7 +682,7 @@ run_permutation(TestSpec *testspec, int nsteps, Step **steps)
* a lock, returns true. Otherwise, returns false.
*/
static bool
-try_complete_step(Step *step, int flags)
+try_complete_step(TestSpec *testspec, Step *step, int flags)
{
PGconn *conn = conns[1 + step->session];
fd_set read_set;
@@ -702,6 +691,7 @@ try_complete_step(Step *step, int flags)
int sock = PQsocket(conn);
int ret;
PGresult *res;
+ PGnotify *notify;
bool canceled = false;
if (sock < 0)
@@ -738,7 +728,7 @@ try_complete_step(Step *step, int flags)
bool waiting;
res = PQexecPrepared(conns[0], PREP_WAITING, 1,
- &backend_pids[step->session + 1],
+ &backend_pid_strs[step->session + 1],
NULL, NULL, 0);
if (PQresultStatus(res) != PGRES_TUPLES_OK ||
PQntuples(res) != 1)
@@ -858,6 +848,35 @@ try_complete_step(Step *step, int flags)
PQclear(res);
}
+ /* Report any available NOTIFY messages, too */
+ PQconsumeInput(conn);
+ while ((notify = PQnotifies(conn)) != NULL)
+ {
+ /* Try to identify which session it came from */
+ const char *sendername = NULL;
+ char pidstring[32];
+
+ for (int i = 0; i < testspec->nsessions; i++)
+ {
+ if (notify->be_pid == backend_pids[i + 1])
+ {
+ sendername = testspec->sessions[i]->name;
+ break;
+ }
+ }
+ if (sendername == NULL)
+ {
+ /* Doesn't seem to be any test session, so show the hard way */
+ snprintf(pidstring, sizeof(pidstring), "PID %d", notify->be_pid);
+ sendername = pidstring;
+ }
+ printf("%s: NOTIFY \"%s\" with payload \"%s\" from %s\n",
+ testspec->sessions[step->session]->name,
+ notify->relname, notify->extra, sendername);
+ PQfreemem(notify);
+ PQconsumeInput(conn);
+ }
+
return false;
}
diff --git a/src/test/isolation/specs/async-notify.spec b/src/test/isolation/specs/async-notify.spec
index 8adad42..498e357 100644
--- a/src/test/isolation/specs/async-notify.spec
+++ b/src/test/isolation/specs/async-notify.spec
@@ -1,14 +1,68 @@
-# Verify that pg_notification_queue_usage correctly reports a non-zero result,
-# after submitting notifications while another connection is listening for
-# those notifications and waiting inside an active transaction.
+# Tests for LISTEN/NOTIFY
-session "listener"
-step "listen" { LISTEN a; }
-step "begin" { BEGIN; }
-teardown { ROLLBACK; UNLISTEN *; }
+# Most of these tests use only the "notifier" session and hence exercise only
+# self-notifies, which are convenient because they minimize timing concerns.
+# Note we assume that each step is delivered to the backend as a single Query
+# message so it will run as one transaction.
session "notifier"
-step "check" { SELECT pg_notification_queue_usage() > 0 AS nonzero; }
-step "notify" { SELECT count(pg_notify('a', s::text)) FROM generate_series(1, 1000) s; }
+step "listenc" { LISTEN c1; LISTEN c2; }
+step "notify1" { NOTIFY c1; }
+step "notify2" { NOTIFY c2, 'payload'; }
+step "notify3" { NOTIFY c3, 'payload3'; } # not listening to c3
+step "notifyd" { NOTIFY c2, 'payload'; NOTIFY c1; NOTIFY "c2", 'payload'; }
+step "notifys1" {
+ BEGIN;
+ NOTIFY c1, 'payload1'; NOTIFY "c2", 'payload2';
+ NOTIFY c1, 'payload1'; NOTIFY "c2", 'payload2';
+ SAVEPOINT s1;
+ NOTIFY c1, 'payload1'; NOTIFY "c2", 'payload2';
+ NOTIFY c1, 'payload1s'; NOTIFY "c2", 'payload2s';
+ NOTIFY c1, 'payload1'; NOTIFY "c2", 'payload2';
+ NOTIFY c1, 'payload1s'; NOTIFY "c2", 'payload2s';
+ RELEASE SAVEPOINT s1;
+ SAVEPOINT s2;
+ NOTIFY c1, 'rpayload1'; NOTIFY "c2", 'rpayload2';
+ NOTIFY c1, 'rpayload1s'; NOTIFY "c2", 'rpayload2s';
+ NOTIFY c1, 'rpayload1'; NOTIFY "c2", 'rpayload2';
+ NOTIFY c1, 'rpayload1s'; NOTIFY "c2", 'rpayload2s';
+ ROLLBACK TO SAVEPOINT s2;
+ COMMIT;
+}
+step "usage" { SELECT pg_notification_queue_usage() > 0 AS nonzero; }
+step "bignotify" { SELECT count(pg_notify('c1', s::text)) FROM generate_series(1, 1000) s; }
+teardown { UNLISTEN *; }
+
+# The listener session is used for cross-backend notify checks.
+
+session "listener"
+step "llisten" { LISTEN c1; LISTEN c2; }
+step "lcheck" { SELECT 1 AS x; }
+step "lbegin" { BEGIN; }
+teardown { UNLISTEN *; }
+
+
+# Trivial cases.
+permutation "listenc" "notify1" "notify2" "notify3"
+
+# Check simple and less-simple deduplication.
+permutation "listenc" "notifyd" "notifys1"
+
+# Cross-backend notification delivery. We use a "select 1" to force the
+# listener session to check for notifies. In principle we could just wait
+# for delivery, but that would require extra support in isolationtester
+# and might have portability-of-timing issues.
+permutation "llisten" "notify1" "notify2" "notify3" "lcheck"
+
+# Again, with local delivery too.
+permutation "listenc" "llisten" "notify1" "notify2" "notify3" "lcheck"
+
+# Verify that pg_notification_queue_usage correctly reports a non-zero result,
+# after submitting notifications while another connection is listening for
+# those notifications and waiting inside an active transaction. We have to
+# fill a page of the notify SLRU to make this happen, which is a good deal
+# of traffic. To not bloat the expected output, we intentionally don't
+# commit the listener's transaction, so that it never reports these events.
+# Hence, this should be the last test in this script.
-permutation "listen" "begin" "check" "notify" "check"
+permutation "llisten" "lbegin" "usage" "bignotify" "usage"
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
Hi,
On 2019-07-27 18:20:52 -0400, Tom Lane wrote:
> diff --git a/src/test/isolation/isolationtester.c b/src/test/isolation/isolationtester.c
> index 6ab19b1..98e5bf2 100644
> --- a/src/test/isolation/isolationtester.c
> +++ b/src/test/isolation/isolationtester.c
> @@ -23,10 +23,12 @@
>
> /*
> * conns[0] is the global setup, teardown, and watchdog connection. Additional
> - * connections represent spec-defined sessions.
> + * connections represent spec-defined sessions. We also track the backend
> + * PID, in numeric and string formats, for each connection.
> */
> static PGconn **conns = NULL;
> -static const char **backend_pids = NULL;
> +static int *backend_pids = NULL;
> +static const char **backend_pid_strs = NULL;
> static int nconns = 0;
Hm, a bit sad to have both of those around. Not worth getting bothered
about memory wise, but it does irk me somewhat.
> @@ -187,26 +191,9 @@ main(int argc, char **argv)
> blackholeNoticeProcessor,
> NULL);
>
> - /* Get the backend pid for lock wait checking. */
> - res = PQexec(conns[i], "SELECT pg_catalog.pg_backend_pid()");
> - if (PQresultStatus(res) == PGRES_TUPLES_OK)
> - {
> - if (PQntuples(res) == 1 && PQnfields(res) == 1)
> - backend_pids[i] = pg_strdup(PQgetvalue(res, 0, 0));
> - else
> - {
> - fprintf(stderr, "backend pid query returned %d rows and %d columns, expected 1 row and 1 column",
> - PQntuples(res), PQnfields(res));
> - exit(1);
> - }
> - }
> - else
> - {
> - fprintf(stderr, "backend pid query failed: %s",
> - PQerrorMessage(conns[i]));
> - exit(1);
> - }
> - PQclear(res);
> + /* Save each connection's backend PID for subsequent use. */
> + backend_pids[i] = PQbackendPID(conns[i]);
> + backend_pid_strs[i] = psprintf("%d", backend_pids[i]);
Heh.
> @@ -738,7 +728,7 @@ try_complete_step(Step *step, int flags)
> bool waiting;
>
> res = PQexecPrepared(conns[0], PREP_WAITING, 1,
> - &backend_pids[step->session + 1],
> + &backend_pid_strs[step->session + 1],
> NULL, NULL, 0);
> if (PQresultStatus(res) != PGRES_TUPLES_OK ||
> PQntuples(res) != 1)
We could of course just send the pids in binary ;). No, not worth it
just to avoid a small redundant array ;)
> + /* Report any available NOTIFY messages, too */
> + PQconsumeInput(conn);
> + while ((notify = PQnotifies(conn)) != NULL)
> + {
Hm. I wonder if all that's happening with prairedog is that the notice
is sent a bit later. I think that could e.g. conceivably happen because
it TCP_NODELAY isn't supported on prariedog? Or just because the machine
is very slow?
The diff you showed with the reordering afaict only reordered the NOTIFY
around statements that are marked as <waiting ...>. As the waiting
detection is done over a separate connection, there's afaict no
guarantee that we see all notices/notifies that occurred before the
query started blocking. It's possible we could make this practically
robust enough by checking for notice/notifies on the blocked connection
just before printing out the <waiting ...>? That still leaves the
potential issue that the different backend connection deliver data out
of order, but that seems not very likely?
Greetings,
Andres Freund
Andres Freund <andres@anarazel.de> writes:
> We could of course just send the pids in binary ;). No, not worth it
> just to avoid a small redundant array ;)
IIRC, we'd have to do htonl on them, so we'd still end up with
two representations ...
> Hm. I wonder if all that's happening with prairedog is that the notice
> is sent a bit later. I think that could e.g. conceivably happen because
> it TCP_NODELAY isn't supported on prariedog? Or just because the machine
> is very slow?
The notices (not notifies) are coming out in the opposite order from
expected. I haven't really thought hard about what's causing that;
it seems odd, because isolationtester isn't supposed to give up waiting
for a session until it's visibly blocked according to pg_locks. Maybe
it needs to recheck for incoming data once more after seeing that?
regards, tom lane
I wrote:
> Andres Freund <andres@anarazel.de> writes:
>> Hm. I wonder if all that's happening with prairedog is that the notice
>> is sent a bit later. I think that could e.g. conceivably happen because
>> it TCP_NODELAY isn't supported on prariedog? Or just because the machine
>> is very slow?
> The notices (not notifies) are coming out in the opposite order from
> expected. I haven't really thought hard about what's causing that;
> it seems odd, because isolationtester isn't supposed to give up waiting
> for a session until it's visibly blocked according to pg_locks. Maybe
> it needs to recheck for incoming data once more after seeing that?
Ah-hah, that seems to be the answer. With the attached patch I'm
getting reliable-seeming passes on prairiedog.
regards, tom lane
diff --git a/src/test/isolation/isolationtester.c b/src/test/isolation/isolationtester.c
index 6ab19b1..e97fef1 100644
*** a/src/test/isolation/isolationtester.c
--- b/src/test/isolation/isolationtester.c
*************** try_complete_step(Step *step, int flags)
*** 752,757 ****
--- 752,777 ----
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 should do PQconsumeInput
+ * to process any such messages, and we might as well then
+ * check PQisBusy, though it's unlikely to succeed.
+ */
+ 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 <waiting ...>\n",
step->name, step->sql);
Hi, On 2019-07-27 19:27:17 -0400, Tom Lane wrote: > Andres Freund <andres@anarazel.de> writes: > > We could of course just send the pids in binary ;). No, not worth it > > just to avoid a small redundant array ;) > > IIRC, we'd have to do htonl on them, so we'd still end up with > two representations ... Yea. Although that'd could just be done in a local variable. Anyway, it's obviously not important. > > Hm. I wonder if all that's happening with prairedog is that the notice > > is sent a bit later. I think that could e.g. conceivably happen because > > it TCP_NODELAY isn't supported on prariedog? Or just because the machine > > is very slow? > > The notices (not notifies) are coming out in the opposite order from > expected. I haven't really thought hard about what's causing that; > it seems odd, because isolationtester isn't supposed to give up waiting > for a session until it's visibly blocked according to pg_locks. Maybe > it needs to recheck for incoming data once more after seeing that? Yea, that's precisely what I was trying to refer to / suggesting. What I think is happening is that both queries get sent to the server, we PQisBusy();select() and figure out they're not done yet. On most machines the raise NOTICE will have been processed by that time, after it's a trivial query. But on prariedog (and I suspect even more likely on valgrind / clobber cache animals), they're not that far yet. So we send the blocking query, until we've seen that it blocks. But there's no interlock guaranteeing that we'll have seen the notices before the *other* connection has detected us blocking. As the blocking query is more complex to plan and execute, that window isn't that small. Polling for notices on the blocked connection before printing anything ought to practically be reliable. Theoretically I think it still allows for some reordering, e.g. because there was packet loss on one, but not the other connection. Greetings, Andres Freund
Andres Freund <andres@anarazel.de> writes:
> Polling for notices on the blocked connection before printing anything
> ought to practically be reliable. Theoretically I think it still allows
> for some reordering, e.g. because there was packet loss on one, but not
> the other connection.
As long as it's a local connection, packet loss shouldn't be a problem
;-). I'm slightly more worried about the case of more than one bufferful
of NOTICE messages: calling PQconsumeInput isn't entirely guaranteed to
absorb *all* available input. But for the cases we actually need to
deal with, I think probably the patch as I sent it is OK. We could
complicate matters by going around the loop extra time(s) to verify
that select() thinks no data is waiting, but I doubt it's worth the
complexity.
regards, tom lane
Hi, On 2019-07-27 20:02:13 -0400, Tom Lane wrote: > Andres Freund <andres@anarazel.de> writes: > I'm slightly more worried about the case of more than one bufferful > of NOTICE messages: calling PQconsumeInput isn't entirely guaranteed to > absorb *all* available input. But for the cases we actually need to > deal with, I think probably the patch as I sent it is OK. We could > complicate matters by going around the loop extra time(s) to verify > that select() thinks no data is waiting, but I doubt it's worth the > complexity. It'd just be one continue; right? Except that we don't know if PQconsumeInput() actually did anything... So we'd need to do something like executing a select and only call PQconsumeInput() if the select signals that there's data? And then always retry? Yea, that seems too complicated. Kinda annoying that we don't expose pqReadData()'s return value anywhere that I can see. Not so much for this, but in general. Travelling back into the past, ISTM, PQconsumeInput() should have returned a different return code if either pqReadData() or pqFlush() did anything. I wonder if there aren't similar dangers around the notify handling. In your patch we don't print them particularly eagerly. Doesn't that also open us up to timing concerns? In particular, for notifies sent out while idle, we might print them together with the *last* command executed - as far as I can tell, if they arrive before the PQconsumeInput(), we'll process them all in the PQisBusy() call at the top of try_complete_step()'s loop? Am I missing some interlock here? Greetings, Andres Freund
Andres Freund <andres@anarazel.de> writes:
> I wonder if there aren't similar dangers around the notify handling. In
> your patch we don't print them particularly eagerly. Doesn't that also
> open us up to timing concerns?
I think probably not, because of the backend-side restrictions on when
notify messages will be sent. The corresponding case for the NOTICE
bug we just fixed would be if a backend sent a NOTIFY before blocking;
but it can't do that internally to a transaction, and anyway the proposed
test script isn't doing anything that tricky.
I did spend some time thinking about how isolationtester might report
notifys that are sent spontaneously (without any "triggering" query)
but I didn't feel that that was worth messing with. We'd have to
have the program checking all the connections not just the one that's
running what it thinks is the currently active step.
We might be approaching a time where it's worth scrapping the
isolationtester logic and starting over. I'm not volunteering though.
regards, tom lane
Andres Freund <andres@anarazel.de> writes:
> On 2019-07-27 12:46:51 -0400, Tom Lane wrote:
>> 2. Change psql so that there's a way to get NOTIFY messages without
>> the sending PID. For testing purposes, it'd be sufficient to know
>> whether the sending PID is our own backend's PID or not. This idea
>> is not horrible, and it might even be useful for outside purposes
>> if we made it flexible enough; which leads to thoughts like allowing
>> the psql user to set a format-style string, similar to the PROMPT
>> strings but with escapes for channel name, payload, etc. I foresee
>> bikeshedding, but we could probably come to an agreement on a feature
>> like that.
> I was wondering about just tying it to VERBOSITY. But that'd not allow
> us to see whether our backend was the sender. I'm mildly inclined to
> think that that might still be a good idea, even if we mostly go with
> 3) - some basic plain regression test coverage of actually receiving
> notifies would be good.
BTW, as far as that goes, do you think we could get away with changing
psql to print "from self" instead of "from PID n" when it's a self-notify?
That would be enough to make the output stable for cases that we'd be
able to check in the core test infrastructure.
So far as the backend is concerned, doing anything there is redundant
with the isolation tests I just committed --- but it would allow psql's
own notify code to be covered, so maybe it's worth the trouble.
regards, tom lane