On Fri, Jul 15, 2011 at 07:01:26PM -0400, Alvaro Herrera wrote:
> Excerpts from Noah Misch's message of mié jul 13 01:34:10 -0400 2011:
>
> > coypu failed during the run of the test due to a different session being
> > chosen
> > as the deadlock victim. We can now vary deadlock_timeout to prevent this;
> > see
> > attached fklocks-tests-deadlock_timeout.patch. This also makes the tests
> > much
> > faster on a default postgresql.conf.
>
> I applied your patch, thanks. I couldn't reproduce the failures without
> it, even running only the three new tests in a loop a few dozen times.
It's probably more likely to crop up on a loaded system. I did not actually
reproduce it myself. However, if you swap the timeouts, the opposite session
finds the deadlock. From there, I'm convinced that the right timing
perturbations could yield the symptom coypu exhibited.
> > crake failed when it reported waiting on the first step of an existing
> > isolation
> > test ("two-ids.spec"). I will need to look into that further.
>
> Actually, there are four failures in tests other than the two fixed by
> your patch. These are:
>
> http://buildfarm.postgresql.org/cgi-bin/show_log.pl?nm=crake&dt=2011-07-12%2022:32:02
> http://buildfarm.postgresql.org/cgi-bin/show_log.pl?nm=nightjar&dt=2011-07-14%2016:27:00
> http://buildfarm.postgresql.org/cgi-bin/show_log.pl?nm=pitta&dt=2011-07-15%2015:00:08
> http://buildfarm.postgresql.org/cgi-bin/show_log.pl?nm=crake&dt=2011-07-15%2018:32:02
Thanks for summarizing. These all boil down to lock waits not anticipated by
the test specs. Having pondered this, I've been able to come up with just one
explanation. If autovacuum runs VACUUM during the test and finds that it can
truncate dead space from the end of a relation, it will acquire an
AccessExclusiveLock. When I decrease autovacuum_naptime to 1s, I do see
plenty of pg_type and pg_attribute truncations during a test run.
When I sought to reproduce this, what I first saw instead was an indefinite
test suite hang. That turned out to arise from an unrelated thinko -- I
assumed that backend IDs were stable for the life of the backend, but they're
only stable for the life of a pgstat snapshot. This fell down when a backend
older than one of the test backends exited during the test:
4199 2011-07-16 03:33:28.733 EDT DEBUG: forked new backend, pid=23984 socket=8
23984 2011-07-16 03:33:28.737 EDT LOG: statement: SET client_min_messages =
warning;
23984 2011-07-16 03:33:28.739 EDT LOG: statement: SELECT i FROM
pg_stat_get_backend_idset() t(i) WHERE pg_stat_get_backend_pid(i) =
pg_backend_pid()
23985 2011-07-16 03:33:28.740 EDT DEBUG: autovacuum: processing database
"postgres"
4199 2011-07-16 03:33:28.754 EDT DEBUG: forked new backend, pid=23986 socket=8
23986 2011-07-16 03:33:28.754 EDT LOG: statement: SET client_min_messages =
warning;
4199 2011-07-16 03:33:28.755 EDT DEBUG: server process (PID 23985) exited with
exit code 0
23986 2011-07-16 03:33:28.755 EDT LOG: statement: SELECT i FROM
pg_stat_get_backend_idset() t(i) WHERE pg_stat_get_backend_pid(i) =
pg_backend_pid()
4199 2011-07-16 03:33:28.766 EDT DEBUG: forked new backend, pid=23987 socket=8
23987 2011-07-16 03:33:28.766 EDT LOG: statement: SET client_min_messages =
warning;
23987 2011-07-16 03:33:28.767 EDT LOG: statement: SELECT i FROM
pg_stat_get_backend_idset() t(i) WHERE pg_stat_get_backend_pid(i) =
pg_backend_pid()
This led isolationtester to initialize backend_ids = {1,2,2}, making us unable
to detect lock waits correctly. That's also consistent with the symptoms Rémi
Zara just reported. With that fixed, I was able to reproduce the failure due
to autovacuum-truncate-induced transient waiting using this recipe:
- autovacuum_naptime = 1s
- src/test/isolation/Makefile changed to pass --use-existing during installcheck
- Run 'make installcheck' in a loop
- A concurrent session running this in a loop:
CREATE TABLE churn (a int, b int, c int, d int, e int, f int, g int, h int);
DROP TABLE churn;
That yields a steady stream of vacuum truncations, and an associated lock wait
generally capsized the suite within 5-10 runs. Frankly, I have some
difficulty believing that this mechanic alone produced all four failures you
cite above; I suspect I'm still missing some more-frequent cause. Any other
theories on which system background activities can cause a transient lock
wait? It would have to produce a "pgstat_report_waiting(true)" call, so I
believe that excludes all LWLock and lighter contention.
In any event, I have attached a patch that fixes the problems I have described
here. To ignore autovacuum, it only recognizes a wait when one of the
backends under test holds a conflicting lock. (It occurs to me that perhaps
we should expose a pg_lock_conflicts(lockmode_held text, lockmode_req text)
function to simplify this query -- this is a fairly common monitoring need.)
With that change in place, my setup survived through about fifty suite runs at
a time. The streak would end when session 2 would unexpectedly detect a
deadlock that session 1 should have detected. The session 1 deadlock_timeout
I chose, 20ms, is too aggressive. When session 2 is to issue the command that
completes the deadlock, it must do so before session 1 runs the deadlock
detector. Since we burn 10ms just noticing that the previous statement has
blocked, that left only 10ms to issue the next statement. This patch bumps
the figure from 20s to 100ms; hopefully that will be enough for even a
decently-loaded virtual host. We should keep it as low as is reasonable,
because it contributes directly to the isolation suite runtime. Each addition
to deadlock_timeout slows the suite by 12x that amount.
With this patch in its final form, I have completed 180+ suite runs without a
failure. In the absence of better theories on the cause for the buildfarm
failures, we should give the buildfarm a whirl with this patch.
I apologize for the quantity of errata this change is entailing.
Thanks,
nm
--
Noah Misch http://www.2ndQuadrant.com/
PostgreSQL Development, 24x7 Support, Training & Services
diff --git a/src/test/isolation/isolationtester.c
b/src/test/isolation/isolationtester.c
index 126e185..96d7f17 100644
*** a/src/test/isolation/isolationtester.c
--- b/src/test/isolation/isolationtester.c
***************
*** 21,26 ****
--- 21,27 ----
#endif
#include "libpq-fe.h"
+ #include "pqexpbuffer.h"
#include "isolationtester.h"
***************
*** 31,37 ****
* connections represent spec-defined sessions.
*/
static PGconn **conns = NULL;
! static const char **backend_ids = NULL;
static int nconns = 0;
static void run_all_permutations(TestSpec * testspec);
--- 32,38 ----
* connections represent spec-defined sessions.
*/
static PGconn **conns = NULL;
! static const char **backend_pids = NULL;
static int nconns = 0;
static void run_all_permutations(TestSpec * testspec);
***************
*** 67,72 **** main(int argc, char **argv)
--- 68,74 ----
TestSpec *testspec;
int i;
PGresult *res;
+ PQExpBufferData wait_query;
/*
* If the user supplies a parameter on the command line, use it as the
***************
*** 89,95 **** main(int argc, char **argv)
*/
nconns = 1 + testspec->nsessions;
conns = calloc(nconns, sizeof(PGconn *));
! backend_ids = calloc(nconns, sizeof(*backend_ids));
for (i = 0; i < nconns; i++)
{
conns[i] = PQconnectdb(conninfo);
--- 91,97 ----
*/
nconns = 1 + testspec->nsessions;
conns = calloc(nconns, sizeof(PGconn *));
! backend_pids = calloc(nconns, sizeof(*backend_pids));
for (i = 0; i < nconns; i++)
{
conns[i] = PQconnectdb(conninfo);
***************
*** 112,134 **** main(int argc, char **argv)
}
PQclear(res);
! /* Get the backend ID for lock wait checking. */
! res = PQexec(conns[i], "SELECT i FROM
pg_stat_get_backend_idset() t(i) "
! "WHERE pg_stat_get_backend_pid(i) =
pg_backend_pid()");
if (PQresultStatus(res) == PGRES_TUPLES_OK)
{
if (PQntuples(res) == 1 && PQnfields(res) == 1)
! backend_ids[i] = strdup(PQgetvalue(res, 0, 0));
else
{
! fprintf(stderr, "backend id query returned %d
rows and %d columns, expected 1 row and 1 column",
PQntuples(res), PQnfields(res));
exit_nicely();
}
}
else
{
! fprintf(stderr, "backend id query failed: %s",
PQerrorMessage(conns[i]));
exit_nicely();
}
--- 114,135 ----
}
PQclear(res);
! /* Get the backend pid for lock wait checking. */
! res = PQexec(conns[i], "SELECT pg_backend_pid()");
if (PQresultStatus(res) == PGRES_TUPLES_OK)
{
if (PQntuples(res) == 1 && PQnfields(res) == 1)
! backend_pids[i] = 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_nicely();
}
}
else
{
! fprintf(stderr, "backend pid query failed: %s",
PQerrorMessage(conns[i]));
exit_nicely();
}
***************
*** 145,152 **** main(int argc, char **argv)
session->steps[stepindex]->session = i;
}
! res = PQprepare(conns[0], PREP_WAITING,
! "SELECT 1 WHERE
pg_stat_get_backend_waiting($1)", 0, NULL);
if (PQresultStatus(res) != PGRES_COMMAND_OK)
{
fprintf(stderr, "prepare of lock wait query failed: %s",
--- 146,232 ----
session->steps[stepindex]->session = i;
}
! /*
! * Build the query we'll use to detect lock contention among sessions in
! * the test specification. Most of the time, we could get away with
! * simply checking whether a session is waiting for *any* lock: we don't
! * exactly expect concurrent use of test tables. However, autovacuum
will
! * occasionally take AccessExclusiveLock to truncate a table, and we
must
! * ignore that transient wait.
! */
! initPQExpBuffer(&wait_query);
! appendPQExpBufferStr(&wait_query,
! "SELECT 1 FROM pg_locks
holder, pg_locks waiter "
! "WHERE NOT waiter.granted AND
waiter.pid = $1 "
! "AND holder.granted "
! "AND holder.pid <> $1 AND
holder.pid IN (");
! /* The spec syntax requires at least one session; assume that here. */
! appendPQExpBuffer(&wait_query, "%s", backend_pids[1]);
! for (i = 2; i < nconns; i++)
! appendPQExpBuffer(&wait_query, ", %s", backend_pids[i]);
! appendPQExpBufferStr(&wait_query,
! ") "
!
! "AND holder.mode = ANY (CASE
waiter.mode "
! "WHEN 'AccessShareLock' THEN
ARRAY["
! "'AccessExclusiveLock'] "
! "WHEN 'RowShareLock' THEN
ARRAY["
! "'ExclusiveLock',"
! "'AccessExclusiveLock'] "
! "WHEN 'RowExclusiveLock' THEN
ARRAY["
! "'ShareLock',"
! "'ShareRowExclusiveLock',"
! "'ExclusiveLock',"
! "'AccessExclusiveLock'] "
! "WHEN
'ShareUpdateExclusiveLock' THEN ARRAY["
! "'ShareUpdateExclusiveLock',"
! "'ShareLock',"
! "'ShareRowExclusiveLock',"
! "'ExclusiveLock',"
! "'AccessExclusiveLock'] "
! "WHEN 'ShareLock' THEN ARRAY["
! "'RowExclusiveLock',"
! "'ShareUpdateExclusiveLock',"
! "'ShareRowExclusiveLock',"
! "'ExclusiveLock',"
! "'AccessExclusiveLock'] "
! "WHEN 'ShareRowExclusiveLock'
THEN ARRAY["
! "'RowExclusiveLock',"
! "'ShareUpdateExclusiveLock',"
! "'ShareLock',"
! "'ShareRowExclusiveLock',"
! "'ExclusiveLock',"
! "'AccessExclusiveLock'] "
! "WHEN 'ExclusiveLock' THEN
ARRAY["
! "'RowShareLock',"
! "'RowExclusiveLock',"
! "'ShareUpdateExclusiveLock',"
! "'ShareLock',"
! "'ShareRowExclusiveLock',"
! "'ExclusiveLock',"
! "'AccessExclusiveLock'] "
! "WHEN 'AccessExclusiveLock'
THEN ARRAY["
! "'AccessShareLock',"
! "'RowShareLock',"
! "'RowExclusiveLock',"
! "'ShareUpdateExclusiveLock',"
! "'ShareLock',"
! "'ShareRowExclusiveLock',"
! "'ExclusiveLock',"
! "'AccessExclusiveLock'] END) "
!
! "AND holder.locktype IS NOT
DISTINCT FROM waiter.locktype "
! "AND holder.database IS NOT
DISTINCT FROM waiter.database "
! "AND holder.relation IS NOT
DISTINCT FROM waiter.relation "
! "AND holder.page IS NOT
DISTINCT FROM waiter.page "
! "AND holder.tuple IS NOT
DISTINCT FROM waiter.tuple "
! "AND holder.virtualxid IS NOT
DISTINCT FROM waiter.virtualxid "
! "AND holder.transactionid IS
NOT DISTINCT FROM waiter.transactionid "
! "AND holder.classid IS NOT
DISTINCT FROM waiter.classid "
! "AND holder.objid IS NOT
DISTINCT FROM waiter.objid "
! "AND holder.objsubid IS NOT
DISTINCT FROM waiter.objsubid ");
!
! res = PQprepare(conns[0], PREP_WAITING, wait_query.data, 0, NULL);
if (PQresultStatus(res) != PGRES_COMMAND_OK)
{
fprintf(stderr, "prepare of lock wait query failed: %s",
***************
*** 154,159 **** main(int argc, char **argv)
--- 234,240 ----
exit_nicely();
}
PQclear(res);
+ termPQExpBuffer(&wait_query);
/*
* Run the permutations specified in the spec, or all if none were
***************
*** 411,419 **** run_permutation(TestSpec * testspec, int nsteps, Step ** steps)
* Our caller already sent the query associated with this step. Wait for it
* to either complete or (if given the STEP_NONBLOCK flag) to block while
* waiting for a lock. We assume that any lock wait will persist until we
! * have executed additional steps in the permutation. This is not fully
! * robust -- a concurrent autovacuum could briefly take a lock with which we
! * conflict. The risk may be low enough to discount.
*
* When calling this function on behalf of a given step for a second or later
* time, pass the STEP_RETRY flag. This only affects the messages printed.
--- 492,498 ----
* Our caller already sent the query associated with this step. Wait for it
* to either complete or (if given the STEP_NONBLOCK flag) to block while
* waiting for a lock. We assume that any lock wait will persist until we
! * have executed additional steps in the permutation.
*
* When calling this function on behalf of a given step for a second or later
* time, pass the STEP_RETRY flag. This only affects the messages printed.
***************
*** 450,456 **** try_complete_step(Step *step, int flags)
int ntuples;
res = PQexecPrepared(conns[0], PREP_WAITING, 1,
!
&backend_ids[step->session + 1],
NULL, NULL, 0);
if (PQresultStatus(res) != PGRES_TUPLES_OK)
{
--- 529,535 ----
int ntuples;
res = PQexecPrepared(conns[0], PREP_WAITING, 1,
!
&backend_pids[step->session + 1],
NULL, NULL, 0);
if (PQresultStatus(res) != PGRES_TUPLES_OK)
{
diff --git a/src/test/isolation/specs/fk-deindex b533d77..9f46c6b 100644
*** a/src/test/isolation/specs/fk-deadlock.spec
--- b/src/test/isolation/specs/fk-deadlock.spec
***************
*** 19,25 **** teardown
}
session "s1"
! setup { BEGIN; SET deadlock_timeout = '20ms'; }
step "s1i" { INSERT INTO child VALUES (1, 1); }
step "s1u" { UPDATE parent SET aux = 'bar'; }
step "s1c" { COMMIT; }
--- 19,25 ----
}
session "s1"
! setup { BEGIN; SET deadlock_timeout = '100ms'; }
step "s1i" { INSERT INTO child VALUES (1, 1); }
step "s1u" { UPDATE parent SET aux = 'bar'; }
step "s1c" { COMMIT; }
diff --git a/src/test/isolation/specs/fk-deadlocindex 5653628..a8f1516 100644
*** a/src/test/isolation/specs/fk-deadlock2.spec
--- b/src/test/isolation/specs/fk-deadlock2.spec
***************
*** 24,30 **** teardown
}
session "s1"
! setup { BEGIN; SET deadlock_timeout = '20ms'; }
step "s1u1" { UPDATE A SET Col1 = 1 WHERE AID = 1; }
step "s1u2" { UPDATE B SET Col2 = 1 WHERE BID = 2; }
step "s1c" { COMMIT; }
--- 24,30 ----
}
session "s1"
! setup { BEGIN; SET deadlock_timeout = '100ms'; }
step "s1u1" { UPDATE A SET Col1 = 1 WHERE AID = 1; }
step "s1u2" { UPDATE B SET Col2 = 1 WHERE BID = 2; }
step "s1c" { COMMIT; }
--
Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-hackers
