Use annotations to reduce instability of isolation-test results.

We've long contended with isolation test results that aren't entirely
stable.  Some test scripts insert long delays to try to force stable
results, which is not terribly desirable; but other erratic failure
modes remain, causing unrepeatable buildfarm failures.  I've spent a
fair amount of time trying to solve this by improving the server-side
support code, without much success: that way is fundamentally unable
to cope with diffs that stem from chance ordering of arrival of
messages from different server processes.

We can improve matters on the client side, however, by annotating
the test scripts themselves to show the desired reporting order
of events that might occur in different orders.  This patch adds
three types of annotations to deal with (a) test steps that might or
might not complete their waits before the isolationtester can see them
waiting; (b) test steps in different sessions that can legitimately
complete in either order; and (c) NOTIFY messages that might arrive
before or after the completion of a step in another session.  We might
need more annotation types later, but this seems to be enough to deal
with the instabilities we've seen in the buildfarm.  It also lets us
get rid of all the long delays that were previously used, cutting more
than a minute off the runtime of the isolation tests.

Back-patch to all supported branches, because the buildfarm
instabilities affect all the branches, and because it seems desirable
to keep isolationtester's capabilities the same across all branches
to simplify possible future back-patching of tests.

Discussion: https://postgr.es/m/327948.1623725828@sss.pgh.pa.us

Author: tglsfdc

contrib/test_decoding/expected/concurrent_ddl_dml.out

@@ -257,7 +257,7 @@ step s1_insert_tbl2: INSERT INTO tbl2 (val1, val2) VALUES (1, 1);
 step s2_alter_tbl1_boolean: ALTER TABLE tbl1 ALTER COLUMN val2 TYPE boolean; <waiting ...>
 step s1_commit: COMMIT;
 step s2_alter_tbl1_boolean: <... completed>
-error in steps s1_commit s2_alter_tbl1_boolean: ERROR:  column "val2" cannot be cast automatically to type boolean
+ERROR:  column "val2" cannot be cast automatically to type boolean
 step s2_get_changes: SELECT data FROM pg_logical_slot_get_changes('isolation_slot', NULL, NULL, 'include-xids', '0', 'skip-empty-xacts', '1');
 data           
 

src/test/isolation/README

@@ -57,11 +57,16 @@ Test specification
 ==================
 
 Each isolation test is defined by a specification file, stored in the specs
-subdirectory. A test specification consists of four parts, in this order:
+subdirectory.  A test specification defines some SQL "steps", groups them
+into "sessions" (where all the steps of one session will be run in the
+same backend), and specifies the "permutations" or orderings of the steps
+that are to be run.
+
+A test specification consists of four parts, in this order:
 
 setup { <SQL> }
 
-  The given SQL block is executed once, in one session only, before running
+  The given SQL block is executed once (per permutation) before running
   the test.  Create any test tables or other required objects here.  This
   part is optional.  Multiple setup blocks are allowed if needed; each is
   run separately, in the given order.  (The reason for allowing multiple
@@ -81,8 +86,8 @@ session "<name>"
   session is executed in its own connection. A session part consists
   of three parts: setup, teardown and one or more "steps". The per-session
   setup and teardown parts have the same syntax as the per-test setup and
-  teardown described above, but they are executed in each session. The
-  setup part typically contains a "BEGIN" command to begin a transaction.
+  teardown described above, but they are executed in each session. The setup
+  part might, for example, contain a "BEGIN" command to begin a transaction.
 
   Each step has the syntax
 
@@ -101,7 +106,8 @@ permutation "<step name>" ...
   order).  Note that the list of steps in a manually specified
   "permutation" line doesn't actually have to be a permutation of the
   available steps; it could for instance repeat some steps more than once,
-  or leave others out.
+  or leave others out.  Also, each step name can be annotated with some
+  parenthesized markers, which are described below.
 
 Lines beginning with a # are considered comments.
 
@@ -110,7 +116,8 @@ specified in the spec file, or automatically generated), the isolation
 tester runs the main setup part, then per-session setup parts, then
 the selected session steps, then per-session teardown, then the main
 teardown script.  Each selected step is sent to the connection associated
-with its session.
+with its session.  The main setup and teardown scripts are run in a
+separate "control" session.
 
 
 Support for blocking commands
@@ -129,3 +136,69 @@ 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
 blocks on heavyweight locks will be detected.
+
+
+Dealing with race conditions
+============================
+
+In some cases, the isolationtester's output for a test script may vary
+due to timing issues.  One way to deal with that is to create variant
+expected-files, which follow the usual PG convention that variants for
+foo.spec are named foo_1.out, foo_2.out, etc.  However, this method is
+discouraged since the extra files are a nuisance for maintenance.
+Instead, it's usually possible to stabilize the test output by applying
+special markers to some of the step names listed in a permutation line.
+
+The general form of a permutation entry is
+
+	<step name> [ ( <marker> [ , <marker> ... ] ) ]
+
+where each marker defines a "blocking condition".  The step will not be
+reported as completed before all the blocking conditions are satisfied.
+The possible markers are:
+
+	*
+	<other step name>
+	<other step name> notices <n>
+
+An asterisk marker, such as mystep(*), forces the isolationtester to
+report the step as "waiting" as soon as it's been launched, regardless of
+whether it would have been detected as waiting later.  This is useful for
+stabilizing cases that are sometimes reported as waiting and other times
+reported as immediately completing, depending on the relative speeds of
+the step and the isolationtester's status-monitoring queries.
+
+A marker consisting solely of a step name indicates that this step may
+not be reported as completing until that other step has completed.
+This allows stabilizing cases where two queries might be seen to complete
+in either order.  Note that this step can be *launched* before the other
+step has completed.  (If the other step is used more than once in the
+current permutation, this step cannot complete while any of those
+instances is active.)
+
+A marker of the form "<other step name> notices <n>" (where <n> is a
+positive integer) indicates that this step may not be reported as
+completing until the other step's session has returned at least <n>
+NOTICE messages, counting from when this step is launched.  This is useful
+for stabilizing cases where a step can return NOTICE messages before it
+actually completes, and those messages must be synchronized with the
+completions of other steps.
+
+Notice that these markers can only delay reporting of the completion
+of a step, not the launch of a step.  The isolationtester will launch
+the next step in a permutation as soon as (A) all prior steps of the
+same session are done, and (B) the immediately preceding step in the
+permutation is done or deemed blocked.  For this purpose, "deemed
+blocked" means that it has been seen to be waiting on a database lock,
+or that it is complete but the report of its completion is delayed by
+one of these markers.
+
+In some cases it is important not to launch a step until after the
+completion of a step in another session that could have been deemed
+blocked.  An example is that if step s1 in session A is issuing a
+cancel for step s2 in session B, we'd better not launch B's next step
+till we're sure s1 is done.  If s1 is blockable, trouble could ensue.
+The best way to prevent that is to create an empty step in session A
+and run it, without any markers, just before the next session B step.
+The empty step cannot be launched until s1 is done, and in turn the
+next session B step cannot be launched until the empty step finishes.

src/test/isolation/expected/alter-table-3.out

@@ -54,7 +54,7 @@ i
 step s2c: INSERT INTO a VALUES (0); <waiting ...>
 step s1d: COMMIT;
 step s2c: <... completed>
-error in steps s1d s2c: ERROR:  duplicate key value violates unique constraint "a_pkey"
+ERROR:  duplicate key value violates unique constraint "a_pkey"
 step s2d: COMMIT;
 
 starting permutation: s1a s1b s2a s1c s1d s2b s2c s2d
@@ -97,7 +97,7 @@ i
 step s2c: INSERT INTO a VALUES (0); <waiting ...>
 step s1d: COMMIT;
 step s2c: <... completed>
-error in steps s1d s2c: ERROR:  duplicate key value violates unique constraint "a_pkey"
+ERROR:  duplicate key value violates unique constraint "a_pkey"
 step s2d: COMMIT;
 
 starting permutation: s1a s1b s2a s2b s1c s1d s2c s2d
@@ -126,7 +126,7 @@ step s1c: ALTER TABLE a ENABLE TRIGGER t;
 step s2c: INSERT INTO a VALUES (0); <waiting ...>
 step s1d: COMMIT;
 step s2c: <... completed>
-error in steps s1d s2c: ERROR:  duplicate key value violates unique constraint "a_pkey"
+ERROR:  duplicate key value violates unique constraint "a_pkey"
 step s2d: COMMIT;
 
 starting permutation: s1a s1b s2a s2b s2c s1c s1d s2d
@@ -141,7 +141,7 @@ step s2c: INSERT INTO a VALUES (0); <waiting ...>
 step s1c: ALTER TABLE a ENABLE TRIGGER t;
 step s1d: COMMIT;
 step s2c: <... completed>
-error in steps s1d s2c: ERROR:  duplicate key value violates unique constraint "a_pkey"
+ERROR:  duplicate key value violates unique constraint "a_pkey"
 step s2d: COMMIT;
 
 starting permutation: s1a s2a s1b s1c s1d s2b s2c s2d
@@ -184,7 +184,7 @@ i
 step s2c: INSERT INTO a VALUES (0); <waiting ...>
 step s1d: COMMIT;
 step s2c: <... completed>
-error in steps s1d s2c: ERROR:  duplicate key value violates unique constraint "a_pkey"
+ERROR:  duplicate key value violates unique constraint "a_pkey"
 step s2d: COMMIT;
 
 starting permutation: s1a s2a s1b s2b s1c s1d s2c s2d
@@ -213,7 +213,7 @@ step s1c: ALTER TABLE a ENABLE TRIGGER t;
 step s2c: INSERT INTO a VALUES (0); <waiting ...>
 step s1d: COMMIT;
 step s2c: <... completed>
-error in steps s1d s2c: ERROR:  duplicate key value violates unique constraint "a_pkey"
+ERROR:  duplicate key value violates unique constraint "a_pkey"
 step s2d: COMMIT;
 
 starting permutation: s1a s2a s1b s2b s2c s1c s1d s2d
@@ -228,7 +228,7 @@ step s2c: INSERT INTO a VALUES (0); <waiting ...>
 step s1c: ALTER TABLE a ENABLE TRIGGER t;
 step s1d: COMMIT;
 step s2c: <... completed>
-error in steps s1d s2c: ERROR:  duplicate key value violates unique constraint "a_pkey"
+ERROR:  duplicate key value violates unique constraint "a_pkey"
 step s2d: COMMIT;
 
 starting permutation: s1a s2a s2b s1b s1c s1d s2c s2d
@@ -257,7 +257,7 @@ step s1c: ALTER TABLE a ENABLE TRIGGER t;
 step s2c: INSERT INTO a VALUES (0); <waiting ...>
 step s1d: COMMIT;
 step s2c: <... completed>
-error in steps s1d s2c: ERROR:  duplicate key value violates unique constraint "a_pkey"
+ERROR:  duplicate key value violates unique constraint "a_pkey"
 step s2d: COMMIT;
 
 starting permutation: s1a s2a s2b s1b s2c s1c s1d s2d
@@ -272,7 +272,7 @@ step s2c: INSERT INTO a VALUES (0); <waiting ...>
 step s1c: ALTER TABLE a ENABLE TRIGGER t;
 step s1d: COMMIT;
 step s2c: <... completed>
-error in steps s1d s2c: ERROR:  duplicate key value violates unique constraint "a_pkey"
+ERROR:  duplicate key value violates unique constraint "a_pkey"
 step s2d: COMMIT;
 
 starting permutation: s1a s2a s2b s2c s1b s1c s1d s2d
@@ -371,7 +371,7 @@ i
 step s2c: INSERT INTO a VALUES (0); <waiting ...>
 step s1d: COMMIT;
 step s2c: <... completed>
-error in steps s1d s2c: ERROR:  duplicate key value violates unique constraint "a_pkey"
+ERROR:  duplicate key value violates unique constraint "a_pkey"
 step s2d: COMMIT;
 
 starting permutation: s2a s1a s1b s2b s1c s1d s2c s2d
@@ -400,7 +400,7 @@ step s1c: ALTER TABLE a ENABLE TRIGGER t;
 step s2c: INSERT INTO a VALUES (0); <waiting ...>
 step s1d: COMMIT;
 step s2c: <... completed>
-error in steps s1d s2c: ERROR:  duplicate key value violates unique constraint "a_pkey"
+ERROR:  duplicate key value violates unique constraint "a_pkey"
 step s2d: COMMIT;
 
 starting permutation: s2a s1a s1b s2b s2c s1c s1d s2d
@@ -415,7 +415,7 @@ step s2c: INSERT INTO a VALUES (0); <waiting ...>
 step s1c: ALTER TABLE a ENABLE TRIGGER t;
 step s1d: COMMIT;
 step s2c: <... completed>
-error in steps s1d s2c: ERROR:  duplicate key value violates unique constraint "a_pkey"
+ERROR:  duplicate key value violates unique constraint "a_pkey"
 step s2d: COMMIT;
 
 starting permutation: s2a s1a s2b s1b s1c s1d s2c s2d
@@ -444,7 +444,7 @@ step s1c: ALTER TABLE a ENABLE TRIGGER t;
 step s2c: INSERT INTO a VALUES (0); <waiting ...>
 step s1d: COMMIT;
 step s2c: <... completed>
-error in steps s1d s2c: ERROR:  duplicate key value violates unique constraint "a_pkey"
+ERROR:  duplicate key value violates unique constraint "a_pkey"
 step s2d: COMMIT;
 
 starting permutation: s2a s1a s2b s1b s2c s1c s1d s2d
@@ -459,7 +459,7 @@ step s2c: INSERT INTO a VALUES (0); <waiting ...>
 step s1c: ALTER TABLE a ENABLE TRIGGER t;
 step s1d: COMMIT;
 step s2c: <... completed>
-error in steps s1d s2c: ERROR:  duplicate key value violates unique constraint "a_pkey"
+ERROR:  duplicate key value violates unique constraint "a_pkey"
 step s2d: COMMIT;
 
 starting permutation: s2a s1a s2b s2c s1b s1c s1d s2d
@@ -544,7 +544,7 @@ step s1c: ALTER TABLE a ENABLE TRIGGER t;
 step s2c: INSERT INTO a VALUES (0); <waiting ...>
 step s1d: COMMIT;
 step s2c: <... completed>
-error in steps s1d s2c: ERROR:  duplicate key value violates unique constraint "a_pkey"
+ERROR:  duplicate key value violates unique constraint "a_pkey"
 step s2d: COMMIT;
 
 starting permutation: s2a s2b s1a s1b s2c s1c s1d s2d
@@ -559,7 +559,7 @@ step s2c: INSERT INTO a VALUES (0); <waiting ...>
 step s1c: ALTER TABLE a ENABLE TRIGGER t;
 step s1d: COMMIT;
 step s2c: <... completed>
-error in steps s1d s2c: ERROR:  duplicate key value violates unique constraint "a_pkey"
+ERROR:  duplicate key value violates unique constraint "a_pkey"
 step s2d: COMMIT;
 
 starting permutation: s2a s2b s1a s2c s1b s1c s1d s2d

src/test/isolation/expected/alter-table-4.out

@@ -50,7 +50,7 @@ step s1modc1a: ALTER TABLE c1 ALTER COLUMN a TYPE float;
 step s2sel: SELECT SUM(a) FROM p; <waiting ...>
 step s1c: COMMIT;
 step s2sel: <... completed>
-error in steps s1c s2sel: ERROR:  attribute "a" of relation "c1" does not match parent's type
+ERROR:  attribute "a" of relation "c1" does not match parent's type
 step s2sel: SELECT SUM(a) FROM p;
 sum            
 

src/test/isolation/expected/deadlock-hard.out

@@ -18,8 +18,8 @@ step s6a7: LOCK TABLE a7; <waiting ...>
 step s7a8: LOCK TABLE a8; <waiting ...>
 step s8a1: LOCK TABLE a1; <waiting ...>
 step s8a1: <... completed>
+ERROR:  deadlock detected
 step s7a8: <... completed>
-error in steps s8a1 s7a8: ERROR:  deadlock detected
 step s8c: COMMIT;
 step s7c: COMMIT;
 step s6a7: <... completed>

src/test/isolation/expected/deadlock-simple.out

@@ -5,7 +5,7 @@ step s1as: LOCK TABLE a1 IN ACCESS SHARE MODE;
 step s2as: LOCK TABLE a1 IN ACCESS SHARE MODE;
 step s1ae: LOCK TABLE a1 IN ACCESS EXCLUSIVE MODE; <waiting ...>
 step s2ae: LOCK TABLE a1 IN ACCESS EXCLUSIVE MODE;
+ERROR:  deadlock detected
 step s1ae: <... completed>
-error in steps s2ae s1ae: ERROR:  deadlock detected
 step s1c: COMMIT;
 step s2c: COMMIT;

src/test/isolation/expected/eval-plan-qual-trigger.out

@@ -609,7 +609,7 @@ s2: NOTICE:  trigger: name rep_b_i; when: BEFORE; lev: ROWs; op: INSERT; old: <N
 step s2_ins_a: INSERT INTO trigtest VALUES ('key-a', 'val-a-s2') RETURNING *; <waiting ...>
 step s1_c: COMMIT;
 step s2_ins_a: <... completed>
-error in steps s1_c s2_ins_a: ERROR:  duplicate key value violates unique constraint "trigtest_pkey"
+ERROR:  duplicate key value violates unique constraint "trigtest_pkey"
 step s2_c: COMMIT;
 step s0_rep: SELECT * FROM trigtest ORDER BY key, data
 key            data           
@@ -2023,7 +2023,7 @@ step s2_upd_a_data:
  <waiting ...>
 step s1_c: COMMIT;
 step s2_upd_a_data: <... completed>
-error in steps s1_c s2_upd_a_data: ERROR:  could not serialize access due to concurrent update
+ERROR:  could not serialize access due to concurrent update
 step s2_c: COMMIT;
 step s0_rep: SELECT * FROM trigtest ORDER BY key, data
 key            data           
@@ -2136,7 +2136,7 @@ step s2_upd_a_data:
  <waiting ...>
 step s1_c: COMMIT;
 step s2_upd_a_data: <... completed>
-error in steps s1_c s2_upd_a_data: ERROR:  could not serialize access due to concurrent delete
+ERROR:  could not serialize access due to concurrent delete
 step s2_c: COMMIT;
 step s0_rep: SELECT * FROM trigtest ORDER BY key, data
 key            data           

src/test/isolation/expected/eval-plan-qual.out

@@ -551,7 +551,7 @@ balance
 step updwctefail: WITH doup AS (UPDATE accounts SET balance = balance + 1100 WHERE accountid = 'checking' RETURNING *, update_checking(999)) UPDATE accounts a SET balance = doup.balance + 100 FROM doup RETURNING *; <waiting ...>
 step c1: COMMIT;
 step updwctefail: <... completed>
-error in steps c1 updwctefail: ERROR:  tuple to be updated was already modified by an operation triggered by the current command
+ERROR:  tuple to be updated was already modified by an operation triggered by the current command
 step c2: COMMIT;
 step read: SELECT * FROM accounts ORDER BY accountid;
 accountid      balance        
@@ -584,7 +584,7 @@ balance
 step delwctefail: WITH doup AS (UPDATE accounts SET balance = balance + 1100 WHERE accountid = 'checking' RETURNING *, update_checking(999)) DELETE FROM accounts a USING doup RETURNING *; <waiting ...>
 step c1: COMMIT;
 step delwctefail: <... completed>
-error in steps c1 delwctefail: ERROR:  tuple to be deleted was already modified by an operation triggered by the current command
+ERROR:  tuple to be deleted was already modified by an operation triggered by the current command
 step c2: COMMIT;
 step read: SELECT * FROM accounts ORDER BY accountid;
 accountid      balance        
@@ -931,7 +931,7 @@ step complexpartupdate_route_err1:
  <waiting ...>
 step c1: COMMIT;
 step complexpartupdate_route_err1: <... completed>
-error in steps c1 complexpartupdate_route_err1: ERROR:  tuple to be locked was already moved to another partition due to concurrent update
+ERROR:  tuple to be locked was already moved to another partition due to concurrent update
 step c2: COMMIT;
 
 starting permutation: simplepartupdate_noroute complexpartupdate_route c1 c2