Thread: Cutting test runtime for src/test/modules/snapshot_too_old

I've complained before that the snapshot_too_old TAP tests seem
ridiculously slow --- close to a minute of runtime even on very fast
machines.  Today I happened to look closer and realized that there's
an absolutely trivial way to cut that.  The core of the slow runtime
is that there's a "pg_sleep(6)" in the test case; which perhaps could
be trimmed, but I'm not on about that right now.  What I'm on about
is that two of the three isolation tests allow the isolationtester to
default to running every possible permutation of steps, one of which
doesn't even generate the "snapshot too old" failure.  IMV it's
sufficient to run just one permutation.  That opinion was shared by
whoever wrote sto_using_hash_index.spec, but they didn't propagate
the idea into the other two tests.

The attached cuts the test runtime (exclusive of setup) from
approximately 30+24+6 seconds to 6+6+6 seconds, and I don't see
that it loses us one iota of coverage.

I cleaned up some unused tables and bad comment grammar, too.

            regards, tom lane

diff --git a/src/test/modules/snapshot_too_old/expected/sto_using_cursor.out
b/src/test/modules/snapshot_too_old/expected/sto_using_cursor.out
index 4359bf2ed9..06fe4d0669 100644
--- a/src/test/modules/snapshot_too_old/expected/sto_using_cursor.out
+++ b/src/test/modules/snapshot_too_old/expected/sto_using_cursor.out
@@ -1,27 +1,5 @@
 Parsed test spec with 2 sessions

-starting permutation: s1decl s1f1 s1sleep s1f2 s2u
-step s1decl: DECLARE cursor1 CURSOR FOR SELECT c FROM sto1;
-step s1f1: FETCH FIRST FROM cursor1;
-c
--
-1
-(1 row)
-
-step s1sleep: SELECT setting, pg_sleep(6) FROM pg_settings WHERE name = 'old_snapshot_threshold';
-setting|pg_sleep
--------+--------
-      0|
-(1 row)
-
-step s1f2: FETCH FIRST FROM cursor1;
-c
--
-1
-(1 row)
-
-step s2u: UPDATE sto1 SET c = 1001 WHERE c = 1;
-
 starting permutation: s1decl s1f1 s1sleep s2u s1f2
 step s1decl: DECLARE cursor1 CURSOR FOR SELECT c FROM sto1;
 step s1f1: FETCH FIRST FROM cursor1;
@@ -39,57 +17,3 @@ setting|pg_sleep
 step s2u: UPDATE sto1 SET c = 1001 WHERE c = 1;
 step s1f2: FETCH FIRST FROM cursor1;
 ERROR:  snapshot too old
-
-starting permutation: s1decl s1f1 s2u s1sleep s1f2
-step s1decl: DECLARE cursor1 CURSOR FOR SELECT c FROM sto1;
-step s1f1: FETCH FIRST FROM cursor1;
-c
--
-1
-(1 row)
-
-step s2u: UPDATE sto1 SET c = 1001 WHERE c = 1;
-step s1sleep: SELECT setting, pg_sleep(6) FROM pg_settings WHERE name = 'old_snapshot_threshold';
-setting|pg_sleep
--------+--------
-      0|
-(1 row)
-
-step s1f2: FETCH FIRST FROM cursor1;
-ERROR:  snapshot too old
-
-starting permutation: s1decl s2u s1f1 s1sleep s1f2
-step s1decl: DECLARE cursor1 CURSOR FOR SELECT c FROM sto1;
-step s2u: UPDATE sto1 SET c = 1001 WHERE c = 1;
-step s1f1: FETCH FIRST FROM cursor1;
-c
--
-1
-(1 row)
-
-step s1sleep: SELECT setting, pg_sleep(6) FROM pg_settings WHERE name = 'old_snapshot_threshold';
-setting|pg_sleep
--------+--------
-      0|
-(1 row)
-
-step s1f2: FETCH FIRST FROM cursor1;
-ERROR:  snapshot too old
-
-starting permutation: s2u s1decl s1f1 s1sleep s1f2
-step s2u: UPDATE sto1 SET c = 1001 WHERE c = 1;
-step s1decl: DECLARE cursor1 CURSOR FOR SELECT c FROM sto1;
-step s1f1: FETCH FIRST FROM cursor1;
-c
--
-2
-(1 row)
-
-step s1sleep: SELECT setting, pg_sleep(6) FROM pg_settings WHERE name = 'old_snapshot_threshold';
-setting|pg_sleep
--------+--------
-      0|
-(1 row)
-
-step s1f2: FETCH FIRST FROM cursor1;
-ERROR:  snapshot too old
diff --git a/src/test/modules/snapshot_too_old/expected/sto_using_select.out
b/src/test/modules/snapshot_too_old/expected/sto_using_select.out
index 3067e05454..e910e5c71e 100644
--- a/src/test/modules/snapshot_too_old/expected/sto_using_select.out
+++ b/src/test/modules/snapshot_too_old/expected/sto_using_select.out
@@ -1,26 +1,5 @@
 Parsed test spec with 2 sessions

-starting permutation: s1f1 s1sleep s1f2 s2u
-step s1f1: SELECT c FROM sto1 ORDER BY c LIMIT 1;
-c
--
-1
-(1 row)
-
-step s1sleep: SELECT setting, pg_sleep(6) FROM pg_settings WHERE name = 'old_snapshot_threshold';
-setting|pg_sleep
--------+--------
-      0|
-(1 row)
-
-step s1f2: SELECT c FROM sto1 ORDER BY c LIMIT 1;
-c
--
-1
-(1 row)
-
-step s2u: UPDATE sto1 SET c = 1001 WHERE c = 1;
-
 starting permutation: s1f1 s1sleep s2u s1f2
 step s1f1: SELECT c FROM sto1 ORDER BY c LIMIT 1;
 c
@@ -37,37 +16,3 @@ setting|pg_sleep
 step s2u: UPDATE sto1 SET c = 1001 WHERE c = 1;
 step s1f2: SELECT c FROM sto1 ORDER BY c LIMIT 1;
 ERROR:  snapshot too old
-
-starting permutation: s1f1 s2u s1sleep s1f2
-step s1f1: SELECT c FROM sto1 ORDER BY c LIMIT 1;
-c
--
-1
-(1 row)
-
-step s2u: UPDATE sto1 SET c = 1001 WHERE c = 1;
-step s1sleep: SELECT setting, pg_sleep(6) FROM pg_settings WHERE name = 'old_snapshot_threshold';
-setting|pg_sleep
--------+--------
-      0|
-(1 row)
-
-step s1f2: SELECT c FROM sto1 ORDER BY c LIMIT 1;
-ERROR:  snapshot too old
-
-starting permutation: s2u s1f1 s1sleep s1f2
-step s2u: UPDATE sto1 SET c = 1001 WHERE c = 1;
-step s1f1: SELECT c FROM sto1 ORDER BY c LIMIT 1;
-c
--
-2
-(1 row)
-
-step s1sleep: SELECT setting, pg_sleep(6) FROM pg_settings WHERE name = 'old_snapshot_threshold';
-setting|pg_sleep
--------+--------
-      0|
-(1 row)
-
-step s1f2: SELECT c FROM sto1 ORDER BY c LIMIT 1;
-ERROR:  snapshot too old
diff --git a/src/test/modules/snapshot_too_old/specs/sto_using_cursor.spec
b/src/test/modules/snapshot_too_old/specs/sto_using_cursor.spec
index eac18ca5b9..f3677a8fa9 100644
--- a/src/test/modules/snapshot_too_old/specs/sto_using_cursor.spec
+++ b/src/test/modules/snapshot_too_old/specs/sto_using_cursor.spec
@@ -6,14 +6,13 @@
 # granularity is in minutes.
 #
 # Since results depend on the value of old_snapshot_threshold, sneak that into
-# the line generated by the sleep, so that a surprising values isn't so hard
+# the line generated by the sleep, so that a surprising value isn't so hard
 # to identify.

 setup
 {
     CREATE TABLE sto1 (c int NOT NULL);
     INSERT INTO sto1 SELECT generate_series(1, 1000);
-    CREATE TABLE sto2 (c int NOT NULL);
 }
 setup
 {
@@ -22,7 +21,7 @@ setup

 teardown
 {
-    DROP TABLE sto1, sto2;
+    DROP TABLE sto1;
 }

 session "s1"
@@ -35,3 +34,5 @@ teardown        { COMMIT; }

 session "s2"
 step "s2u"        { UPDATE sto1 SET c = 1001 WHERE c = 1; }
+
+permutation "s1decl" "s1f1" "s1sleep" "s2u" "s1f2"
diff --git a/src/test/modules/snapshot_too_old/specs/sto_using_select.spec
b/src/test/modules/snapshot_too_old/specs/sto_using_select.spec
index d7c34f3d89..80a31763ad 100644
--- a/src/test/modules/snapshot_too_old/specs/sto_using_select.spec
+++ b/src/test/modules/snapshot_too_old/specs/sto_using_select.spec
@@ -6,14 +6,13 @@
 # granularity is in minutes.
 #
 # Since results depend on the value of old_snapshot_threshold, sneak that into
-# the line generated by the sleep, so that a surprising values isn't so hard
+# the line generated by the sleep, so that a surprising value isn't so hard
 # to identify.

 setup
 {
     CREATE TABLE sto1 (c int NOT NULL);
     INSERT INTO sto1 SELECT generate_series(1, 1000);
-    CREATE TABLE sto2 (c int NOT NULL);
 }
 setup
 {
@@ -22,7 +21,7 @@ setup

 teardown
 {
-    DROP TABLE sto1, sto2;
+    DROP TABLE sto1;
 }

 session "s1"
@@ -34,3 +33,5 @@ teardown        { COMMIT; }

 session "s2"
 step "s2u"        { UPDATE sto1 SET c = 1001 WHERE c = 1; }
+
+permutation "s1f1" "s1sleep" "s2u" "s1f2"

On Tue, Aug 2, 2022 at 11:38 AM Tom Lane <tgl@sss.pgh.pa.us> wrote:
> I've complained before that the snapshot_too_old TAP tests seem
> ridiculously slow --- close to a minute of runtime even on very fast
> machines.  Today I happened to look closer and realized that there's
> an absolutely trivial way to cut that.  The core of the slow runtime
> is that there's a "pg_sleep(6)" in the test case; which perhaps could
> be trimmed, but I'm not on about that right now.  What I'm on about
> is that two of the three isolation tests allow the isolationtester to
> default to running every possible permutation of steps, one of which
> doesn't even generate the "snapshot too old" failure.  IMV it's
> sufficient to run just one permutation.  That opinion was shared by
> whoever wrote sto_using_hash_index.spec, but they didn't propagate
> the idea into the other two tests.
>
> The attached cuts the test runtime (exclusive of setup) from
> approximately 30+24+6 seconds to 6+6+6 seconds, and I don't see
> that it loses us one iota of coverage.
>
> I cleaned up some unused tables and bad comment grammar, too.

Yeah, I feel like it was a mistake to allow the list of permutations
to be unspecified. It encourages people to just run them all, which is
almost never a thoughtful decision. Maybe there's something to be said
for running these tests in one successful permutation and one failing
permutation -- or maybe even that is overkill -- but running them all
seems like a poor idea.

-- 
Robert Haas
EDB: http://www.enterprisedb.com

Robert Haas <robertmhaas@gmail.com> writes:
> Yeah, I feel like it was a mistake to allow the list of permutations
> to be unspecified. It encourages people to just run them all, which is
> almost never a thoughtful decision. Maybe there's something to be said
> for running these tests in one successful permutation and one failing
> permutation -- or maybe even that is overkill -- but running them all
> seems like a poor idea.

Yeah, I considered letting the no-error permutation survive.  But
I didn't really see what coverage it was adding at all, let alone
coverage that'd justify doubling the test runtime.

Also ... while doing further research I was reminded that a couple
years ago we were seriously discussing nuking old_snapshot_threshold
altogether, on the grounds that it was so buggy as to be unsafe
to use, and nobody was stepping up to fix it [1][2].  It doesn't
appear to me that the situation has got any better, so I wonder if
we're prepared to pull that trigger yet.

            regards, tom lane

[1] https://www.postgresql.org/message-id/flat/20200401064008.qob7bfnnbu4w5cw4%40alap3.anarazel.de
[2]
https://www.postgresql.org/message-id/flat/CA%2BTgmoY%3Daqf0zjTD%2B3dUWYkgMiNDegDLFjo%2B6ze%3DWtpik%2B3XqA%40mail.gmail.com