From eadfafda049e3081f8078aa30ea33f538c45aecd Mon Sep 17 00:00:00 2001 From: Tom Lane Date: Mon, 9 Dec 2019 14:31:57 -0500 Subject: [PATCH] Improve isolationtester's timeout management. isolationtester.c had a hard-wired limit of 3 minutes per test step. It now emerges that this isn't quite enough for some of the slowest buildfarm animals. This isn't the first time we've had to raise this limit (cf. 1db439ad4), so let's make it configurable. This patch raises the default to 5 minutes, and introduces an environment variable PGISOLATIONTIMEOUT that can be set if more time is needed, following the precedent of PGCTLTIMEOUT. Also, modify isolationtester so that when the timeout is hit, it explicitly reports having sent a cancel. This makes the regression failure log considerably more intelligible. (In the worst case, a timed-out test might actually be reported as "passing" without this extra output, so arguably this is a bug fix in itself.) In passing, update the README file, which had apparently not gotten touched when we added "make check" support here. Back-patch to 9.6; older versions don't have comparable timeout logic. Discussion: https://postgr.es/m/22964.1575842935@sss.pgh.pa.us --- src/test/isolation/README | 29 +++++++++++++++++------- src/test/isolation/isolationtester.c | 33 +++++++++++++++++++++++----- 2 files changed, 48 insertions(+), 14 deletions(-) diff --git a/src/test/isolation/README b/src/test/isolation/README index 780b6dca1b..217953d183 100644 --- a/src/test/isolation/README +++ b/src/test/isolation/README @@ -11,18 +11,26 @@ comes from the fact that the original motivation was to test the serializable isolation level; but tests for other sorts of concurrent behaviors have been added as well. -To run the tests, you need to have a server running at the default port -expected by libpq. (You can set PGPORT and so forth in your environment -to control this.) Then run +You can run the tests against the current build tree by typing + make check +Alternatively, you can run against an existing installation by typing make installcheck -To run just specific test(s), you can do something like +(This will contact a server at the default port expected by libpq. +You can set PGPORT and so forth in your environment to control this.) + +To run just specific test(s) against an installed server, +you can do something like ./pg_isolation_regress fk-contention fk-deadlock (look into the specs/ subdirectory to see the available tests). The prepared-transactions test requires the server's max_prepared_transactions parameter to be set to at least 3; therefore it is not run by default. To include it in the test run, use + make check-prepared-txns +or make installcheck-prepared-txns +after making sure the server configuration is correct (see TEMP_CONFIG +to adjust this in the "check" case). To define tests with overlapping transactions, we use test specification files with a custom syntax, which is described in the next section. To add @@ -39,6 +47,11 @@ pg_isolation_regress is a tool similar to pg_regress, but instead of using psql to execute a test, it uses isolationtester. It accepts all the same command-line arguments as pg_regress. +By default, isolationtester will wait at most 300 seconds (5 minutes) +for any one test step to complete. If you need to adjust this, set +the environment variable PGISOLATIONTIMEOUT to the desired timeout +in seconds. + Test specification ================== @@ -108,10 +121,10 @@ Each step may contain commands that block until further action has been taken deadlock). A test that uses this ability must manually specify valid permutations, i.e. those that would not expect a blocked session to execute a command. If a test fails to follow that rule, isolationtester will cancel it -after 180 seconds. If the cancel doesn't work, isolationtester will exit -uncleanly after a total of 200 seconds of wait time. Testing invalid -permutations should be avoided because they can make the isolation tests take -a very long time to run, and they serve no useful testing purpose. +after PGISOLATIONTIMEOUT seconds. If the cancel doesn't work, isolationtester +will exit uncleanly after a total of twice PGISOLATIONTIMEOUT. Testing +invalid permutations should be avoided because they can make the isolation +tests take a very long time to run, and they serve no useful testing purpose. Note that isolationtester recognizes that a command has blocked by looking to see if it is shown as waiting in the pg_locks view; therefore, only diff --git a/src/test/isolation/isolationtester.c b/src/test/isolation/isolationtester.c index f98bb1cf64..a8353b93af 100644 --- a/src/test/isolation/isolationtester.c +++ b/src/test/isolation/isolationtester.c @@ -34,6 +34,10 @@ static int nconns = 0; /* In dry run only output permutations to be run by the tester. */ static int dry_run = false; +/* Maximum time to wait before giving up on a step (in usec) */ +static int64 max_step_wait = 300 * USECS_PER_SEC; + + static void run_testspec(TestSpec *testspec); static void run_all_permutations(TestSpec *testspec); static void run_all_permutations_recurse(TestSpec *testspec, int nsteps, @@ -66,6 +70,7 @@ int main(int argc, char **argv) { const char *conninfo; + const char *env_wait; TestSpec *testspec; int i, j; @@ -110,6 +115,14 @@ main(int argc, char **argv) else conninfo = "dbname = postgres"; + /* + * If PGISOLATIONTIMEOUT is set in the environment, adopt its value (given + * in seconds) as the max time to wait for any one step to complete. + */ + env_wait = getenv("PGISOLATIONTIMEOUT"); + if (env_wait != NULL) + max_step_wait = ((int64) atoi(env_wait)) * USECS_PER_SEC; + /* Read the test spec from stdin */ spec_yyparse(); testspec = &parseresult; @@ -779,7 +792,7 @@ try_complete_step(TestSpec *testspec, Step *step, int flags) td += (int64) current_time.tv_usec - (int64) start_time.tv_usec; /* - * After 180 seconds, try to cancel the query. + * After max_step_wait microseconds, try to cancel the query. * * If the user tries to test an invalid permutation, we don't want * to hang forever, especially when this is running in the @@ -787,7 +800,7 @@ try_complete_step(TestSpec *testspec, Step *step, int flags) * failing, but remaining permutations and tests should still be * OK. */ - if (td > 180 * USECS_PER_SEC && !canceled) + if (td > max_step_wait && !canceled) { PGcancel *cancel = PQgetCancel(conn); @@ -796,7 +809,15 @@ try_complete_step(TestSpec *testspec, Step *step, int flags) char buf[256]; if (PQcancel(cancel, buf, sizeof(buf))) + { + /* + * print to stdout not stderr, as this should appear + * in the test case's results + */ + printf("isolationtester: canceling step %s after %d seconds\n", + step->name, (int) (td / USECS_PER_SEC)); canceled = true; + } else fprintf(stderr, "PQcancel failed: %s\n", buf); PQfreeCancel(cancel); @@ -804,16 +825,16 @@ try_complete_step(TestSpec *testspec, Step *step, int flags) } /* - * After 200 seconds, just give up and die. + * After twice max_step_wait, just give up and die. * * Since cleanup steps won't be run in this case, this may cause * later tests to fail. That stinks, but it's better than waiting * forever for the server to respond to the cancel. */ - if (td > 200 * USECS_PER_SEC) + if (td > 2 * max_step_wait) { - fprintf(stderr, "step %s timed out after 200 seconds\n", - step->name); + fprintf(stderr, "step %s timed out after %d seconds\n", + step->name, (int) (td / USECS_PER_SEC)); exit(1); } }