Introduce PG_TEST_TIMEOUT_DEFAULT for TAP suite non-elapsing timeouts.
authorNoah Misch
Sat, 5 Mar 2022 02:53:13 +0000 (18:53 -0800)
committerNoah Misch
Sat, 5 Mar 2022 02:53:17 +0000 (18:53 -0800)
Slow hosts may avoid load-induced, spurious failures by setting
environment variable PG_TEST_TIMEOUT_DEFAULT to some number of seconds
greater than 180.  Developers may see faster failures by setting that
environment variable to some lesser number of seconds.  In tests, write
$PostgreSQL::Test::Utils::timeout_default wherever the convention has
been to write 180.  This change raises the default for some briefer
timeouts.  Back-patch to v10 (all supported versions).

Discussion: https://postgr.es/m/20220218052842[email protected]

18 files changed:
contrib/amcheck/t/002_cic.pl
contrib/amcheck/t/003_cic_2pc.pl
src/bin/pg_ctl/t/004_logrotate.pl
src/bin/pg_dump/t/002_pg_dump.pl
src/bin/psql/t/010_tab_completion.pl
src/bin/scripts/t/080_pg_isready.pl
src/test/perl/PostgresNode.pm
src/test/perl/TestLib.pm
src/test/recovery/t/003_recovery_targets.pl
src/test/recovery/t/006_logical_decoding.pl
src/test/recovery/t/010_logical_decoding_timelines.pl
src/test/recovery/t/013_crash_restart.pl
src/test/recovery/t/017_shm.pl
src/test/recovery/t/019_replslot_limit.pl
src/test/recovery/t/021_row_visibility.pl
src/test/recovery/t/022_crash_temp_files.pl
src/test/recovery/t/024_archive_recovery.pl
src/test/subscription/t/015_stream.pl

index 832ae8f1cbdb2f52b91ee8bfa8a9213d13f661c6..3587807b9577152cd351ae61857e7efd2dc73225 100644 (file)
@@ -18,7 +18,8 @@ my ($node, $result);
 #
 $node = get_new_node('CIC_test');
 $node->init;
-$node->append_conf('postgresql.conf', 'lock_timeout = 180000');
+$node->append_conf('postgresql.conf',
+   'lock_timeout = ' . (1000 * $TestLib::timeout_default));
 $node->start;
 $node->safe_psql('postgres', q(CREATE EXTENSION amcheck));
 $node->safe_psql('postgres', q(CREATE TABLE tbl(i int)));
index 9b2c92d11a32b0b6b18a4007c8c1530344fec1b1..445aabaa5e9d5ee216deba94cd08d82dc411b66f 100644 (file)
@@ -22,7 +22,8 @@ my ($node, $result);
 $node = get_new_node('CIC_2PC_test');
 $node->init;
 $node->append_conf('postgresql.conf', 'max_prepared_transactions = 10');
-$node->append_conf('postgresql.conf', 'lock_timeout = 180000');
+$node->append_conf('postgresql.conf',
+   'lock_timeout = ' . (1000 * $TestLib::timeout_default));
 $node->start;
 $node->safe_psql('postgres', q(CREATE EXTENSION amcheck));
 $node->safe_psql('postgres', q(CREATE TABLE tbl(i int)));
@@ -38,7 +39,7 @@ $node->safe_psql('postgres', q(CREATE TABLE tbl(i int)));
 
 my $main_in    = '';
 my $main_out   = '';
-my $main_timer = IPC::Run::timeout(180);
+my $main_timer = IPC::Run::timeout($TestLib::timeout_default);
 
 my $main_h =
   $node->background_psql('postgres', \$main_in, \$main_out,
@@ -52,7 +53,7 @@ pump $main_h until $main_out =~ /syncpoint1/ || $main_timer->is_expired;
 
 my $cic_in    = '';
 my $cic_out   = '';
-my $cic_timer = IPC::Run::timeout(180);
+my $cic_timer = IPC::Run::timeout($TestLib::timeout_default);
 my $cic_h =
   $node->background_psql('postgres', \$cic_in, \$cic_out,
    $cic_timer, on_error_stop => 1);
@@ -113,9 +114,10 @@ PREPARE TRANSACTION 'persists_forever';
 ));
 $node->restart;
 
-my $reindex_in    = '';
-my $reindex_out   = '';
-my $reindex_timer = IPC::Run::timeout(180);
+my $reindex_in  = '';
+my $reindex_out = '';
+my $reindex_timer =
+  IPC::Run::timeout($TestLib::timeout_default);
 my $reindex_h =
   $node->background_psql('postgres', \$reindex_in, \$reindex_out,
    $reindex_timer, on_error_stop => 1);
index 9a0492ae631a0c164bcc0426f35294a810f6ec07..c4f130dd944b2a30759418052f455a4a7f38e92f 100644 (file)
@@ -27,7 +27,7 @@ $node->start();
 $node->psql('postgres', 'SELECT 1/0');
 
 # might need to retry if logging collector process is slow...
-my $max_attempts = 180 * 10;
+my $max_attempts = 10 * $TestLib::timeout_default;
 
 my $current_logfiles;
 for (my $attempts = 0; $attempts < $max_attempts; $attempts++)
index a065bd690856a4bd031e2357cfa96174a5066f26..b52cfe9f735d6e5d84509cc22d049c40e5bb77b6 100644 (file)
@@ -281,7 +281,8 @@ my %pgdump_runs = (
            '--no-sync',
            "--file=$tempdir/only_dump_test_table.sql",
            '--table=dump_test.test_table',
-           '--lock-wait-timeout=1000000',
+           '--lock-wait-timeout='
+             . (1000 * $TestLib::timeout_default),
            'postgres',
        ],
    },
index 002e44df995afde597612cba229ac7519b4dd9c3..a98fa26cc605d757cd999ecfa2cdb4073644b1d3 100644 (file)
@@ -92,7 +92,7 @@ close $FH;
 my $in  = '';
 my $out = '';
 
-my $timer = timer(5);
+my $timer = timer($TestLib::timeout_default);
 
 my $h = $node->interactive_psql('postgres', \$in, \$out, $timer);
 
@@ -109,7 +109,7 @@ sub check_completion
    # reset output collector
    $out = "";
    # restart per-command timer
-   $timer->start(5);
+   $timer->start($TestLib::timeout_default);
    # send the data to be sent
    $in .= $send;
    # wait ...
@@ -235,7 +235,7 @@ check_completion(
 clear_line();
 
 # send psql an explicit \q to shut it down, else pty won't close properly
-$timer->start(5);
+$timer->start($TestLib::timeout_default);
 $in .= "\\q\n";
 finish $h or die "psql returned $?";
 $timer->reset;
index e2e39ea2d4e5ef08bf31467f8a02258be5aaef0b..375f0feb2165495e018ceb53ff0e9bde86a22545 100644 (file)
@@ -18,6 +18,6 @@ my $node = get_new_node('main');
 $node->init;
 $node->start;
 
-# use a long timeout for the benefit of very slow buildfarm machines
-$node->command_ok([qw(pg_isready --timeout=60)],
+$node->command_ok(
+   [ 'pg_isready', "--timeout=$TestLib::timeout_default" ],
    'succeeds with server running');
index 50acc169024d35716110631a31b0f62419b8f31c..c9016db6f8ddf59ba69fd754d4cf25039545d17d 100644 (file)
@@ -33,7 +33,8 @@ PostgresNode - class representing PostgreSQL server instance
   my ($stdout, $stderr, $timed_out);
   my $cmdret = $node->psql('postgres', 'SELECT pg_sleep(600)',
      stdout => \$stdout, stderr => \$stderr,
-     timeout => 180, timed_out => \$timed_out,
+     timeout => $TestLib::timeout_default,
+     timed_out => \$timed_out,
      extra_params => ['--single-transaction'],
      on_error_die => 1)
   print "Sleep timed out" if $timed_out;
@@ -1650,7 +1651,8 @@ e.g.
    my ($stdout, $stderr, $timed_out);
    my $cmdret = $node->psql('postgres', 'SELECT pg_sleep(600)',
        stdout => \$stdout, stderr => \$stderr,
-       timeout => 180, timed_out => \$timed_out,
+       timeout => $TestLib::timeout_default,
+       timed_out => \$timed_out,
        extra_params => ['--single-transaction'])
 
 will set $cmdret to undef and $timed_out to a true value.
@@ -1824,7 +1826,8 @@ scalar reference.  This allows the caller to act on other parts of the system
 while idling this backend.
 
 The specified timer object is attached to the harness, as well.  It's caller's
-responsibility to select the timeout length, and to restart the timer after
+responsibility to set the timeout length (usually
+$TestLib::timeout_default), and to restart the timer after
 each command if the timeout is per-command.
 
 psql is invoked in tuples-only unaligned mode with reading of B<.psqlrc>
@@ -1912,9 +1915,10 @@ The process's stdin is sourced from the $stdin scalar reference,
 and its stdout and stderr go to the $stdout scalar reference.
 ptys are used so that psql thinks it's being called interactively.
 
-The specified timer object is attached to the harness, as well.
-It's caller's responsibility to select the timeout length, and to
-restart the timer after each command if the timeout is per-command.
+The specified timer object is attached to the harness, as well.  It's caller's
+responsibility to set the timeout length (usually
+$TestLib::timeout_default), and to restart the timer after
+each command if the timeout is per-command.
 
 psql is invoked in tuples-only unaligned mode with reading of B<.psqlrc>
 disabled.  That may be overridden by passing extra psql parameters.
@@ -2227,7 +2231,7 @@ sub connect_fails
 Run B<$query> repeatedly, until it returns the B<$expected> result
 ('t', or SQL boolean true, by default).
 Continues polling if B returns an error result.
-Times out after 180 seconds.
+Times out after $TestLib::timeout_default seconds.
 Returns 1 if successful, 0 if timed out.
 
 =cut
@@ -2245,7 +2249,7 @@ sub poll_query_until
        '-d',                             $self->connstr($dbname)
    ];
    my ($stdout, $stderr);
-   my $max_attempts = 180 * 10;
+   my $max_attempts = 10 * $TestLib::timeout_default;
    my $attempts     = 0;
 
    while ($attempts < $max_attempts)
@@ -2267,8 +2271,8 @@ sub poll_query_until
        $attempts++;
    }
 
-   # The query result didn't change in 180 seconds. Give up. Print the
-   # output from the last attempt, hopefully that's useful for debugging.
+   # Give up. Print the output from the last attempt, hopefully that's useful
+   # for debugging.
    diag qq(poll_query_until timed out executing this query:
 $query
 expecting this output:
index c0fcf7dc6640aec3073b26608f319fad5a91edcd..0dfc414b07259b51121b953f7be63718f56c0a5e 100644 (file)
@@ -91,8 +91,8 @@ our @EXPORT = qw(
   $use_unix_sockets
 );
 
-our ($windows_os, $is_msys2, $use_unix_sockets, $tmp_check, $log_path,
-   $test_logfile);
+our ($windows_os, $is_msys2, $use_unix_sockets, $timeout_default,
+   $tmp_check, $log_path, $test_logfile);
 
 BEGIN
 {
@@ -157,6 +157,10 @@ BEGIN
    # supported, but it can be overridden if desired.
    $use_unix_sockets =
      (!$windows_os || defined $ENV{PG_TEST_USE_UNIX_SOCKETS});
+
+   $timeout_default = $ENV{PG_TEST_TIMEOUT_DEFAULT};
+   $timeout_default = 180
+     if not defined $timeout_default or $timeout_default eq '';
 }
 
 =pod
index 6f8e321b970457db7600cf07e53d678415e4e588..0815e6ee4366e3d1415fbabfdbf29d76b0bc8ef5 100644 (file)
@@ -172,8 +172,8 @@ run_log(
        $node_standby->logfile, 'start'
    ]);
 
-# wait up to 180s for postgres to terminate
-foreach my $i (0 .. 1800)
+# wait for postgres to terminate
+foreach my $i (0 .. 10 * $TestLib::timeout_default)
 {
    last if !-f $node_standby->data_dir . '/postmaster.pid';
    usleep(100_000);
index 827a7b488e2780a4bc42add6ec50d2b09a62bd4d..ae13c4fa4fd8fc90519db1b55912b46e5f21eec9 100644 (file)
@@ -98,7 +98,8 @@ $node_primary->safe_psql('postgres',
 );
 
 my $stdout_recv = $node_primary->pg_recvlogical_upto(
-   'postgres', 'test_slot', $endpos, 180,
+   'postgres', 'test_slot', $endpos,
+   $TestLib::timeout_default,
    'include-xids'     => '0',
    'skip-empty-xacts' => '1');
 chomp($stdout_recv);
@@ -110,7 +111,8 @@ $node_primary->poll_query_until('postgres',
 ) or die "slot never became inactive";
 
 $stdout_recv = $node_primary->pg_recvlogical_upto(
-   'postgres', 'test_slot', $endpos, 180,
+   'postgres', 'test_slot', $endpos,
+   $TestLib::timeout_default,
    'include-xids'     => '0',
    'skip-empty-xacts' => '1');
 chomp($stdout_recv);
index 12edbf760e13364892e3aab4807b2f10e75de376..973dcb59caf58d2da1cb14d63252be9f54adb0b3 100644 (file)
@@ -158,7 +158,7 @@ like(
 ($ret, $stdout, $stderr) = $node_replica->psql(
    'postgres',
    "SELECT data FROM pg_logical_slot_peek_changes('before_basebackup', NULL, NULL, 'include-xids', '0', 'skip-empty-xacts', '1');",
-   timeout => 180);
+   timeout => $TestLib::timeout_default);
 is($ret, 0, 'replay from slot before_basebackup succeeds');
 
 my $final_expected_output_bb = q(BEGIN
@@ -187,7 +187,7 @@ my $endpos = $node_replica->safe_psql('postgres',
 
 $stdout = $node_replica->pg_recvlogical_upto(
    'postgres', 'before_basebackup',
-   $endpos,    180,
+   $endpos,    $TestLib::timeout_default,
    'include-xids'     => '0',
    'skip-empty-xacts' => '1');
 
index 868a50b33d39f5836e244518acee968fb6ba43f2..b6540e418fa09072df7a65b1e54c6b3ee3482e1e 100644 (file)
@@ -25,7 +25,7 @@ plan tests => 18;
 # instance being driven by us, add a timeout high enough that it
 # should never trigger even on very slow machines, unless something
 # is really wrong.
-my $psql_timeout = IPC::Run::timer(60);
+my $psql_timeout = IPC::Run::timer($TestLib::timeout_default);
 
 my $node = get_new_node('primary');
 $node->init(allows_streaming => 1);
index 6c12292fe6e4d3b00e43c5f79c3f6849054eeb12..48eb4654f09e42cb8204ffea6fbe9dac2d78e1a8 100644 (file)
@@ -136,7 +136,7 @@ my $slow_client = IPC::Run::start(
    \$stdout,
    '2>',
    \$stderr,
-   IPC::Run::timeout(900));    # five times the poll_query_until timeout
+   IPC::Run::timeout(5 * $TestLib::timeout_default));
 ok( $gnat->poll_query_until(
        'postgres',
        "SELECT 1 FROM pg_stat_activity WHERE query = '$slow_query'", '1'),
@@ -147,10 +147,11 @@ $gnat->kill9;
 unlink($gnat->data_dir . '/postmaster.pid');
 $gnat->rotate_logfile;    # on Windows, can't open old log for writing
 log_ipcs();
-# Reject ordinary startup.  Retry for the same reasons poll_start() does.
+# Reject ordinary startup.  Retry for the same reasons poll_start() does,
+# every 0.1s for at least $TestLib::timeout_default seconds.
 my $pre_existing_msg = qr/pre-existing shared memory block/;
 {
-   my $max_attempts = 180 * 10;    # Retry every 0.1s for at least 180s.
+   my $max_attempts = 10 * $TestLib::timeout_default;
    my $attempts     = 0;
    while ($attempts < $max_attempts)
    {
@@ -197,7 +198,7 @@ sub poll_start
 {
    my ($node) = @_;
 
-   my $max_attempts = 180 * 10;
+   my $max_attempts = 10 * $TestLib::timeout_default;
    my $attempts     = 0;
 
    while ($attempts < $max_attempts)
@@ -213,8 +214,8 @@ sub poll_start
        $attempts++;
    }
 
-   # No success within 180 seconds.  Try one last time without fail_ok, which
-   # will BAIL_OUT unless it succeeds.
+   # Try one last time without fail_ok, which will BAIL_OUT unless it
+   # succeeds.
    $node->start && return 1;
    return 0;
 }
index f99fa16d47235c35df891c1e033ffbc6e72cf992..f6dcf0af1df6187f2da820088b1f2033e5bef7a0 100644 (file)
@@ -296,7 +296,7 @@ my @result =
         SELECT pg_switch_wal();
         CHECKPOINT;
         SELECT 'finished';",
-       timeout => '60'));
+       timeout => $TestLib::timeout_default));
 is($result[1], 'finished', 'check if checkpoint command is not blocked');
 
 $node_primary2->stop;
@@ -348,7 +348,7 @@ $logstart = get_log_size($node_primary3);
 kill 'STOP', $senderpid, $receiverpid;
 advance_wal($node_primary3, 2);
 
-my $max_attempts = 180;
+my $max_attempts = $TestLib::timeout_default;
 while ($max_attempts-- >= 0)
 {
    if (find_in_log(
@@ -371,7 +371,7 @@ $node_primary3->poll_query_until('postgres',
    "lost")
   or die "timed out waiting for slot to be lost";
 
-$max_attempts = 180;
+$max_attempts = $TestLib::timeout_default;
 while ($max_attempts-- >= 0)
 {
    if (find_in_log(
index fd2c0a305312abf3b9ecd1c97d6c5ceb243d1958..8a554c5aae6b1e555e3b873ed2e928f7f4411a03 100644 (file)
@@ -32,11 +32,8 @@ $node_standby->init_from_backup($node_primary, $backup_name,
 $node_standby->append_conf('postgresql.conf', 'max_prepared_transactions=10');
 $node_standby->start;
 
-# To avoid hanging while expecting some specific input from a psql
-# instance being driven by us, add a timeout high enough that it
-# should never trigger even on very slow machines, unless something
-# is really wrong.
-my $psql_timeout = IPC::Run::timer(300);
+my $psql_timeout =
+  IPC::Run::timer(2 * $TestLib::timeout_default);
 
 # One psql to primary and standby each, for all queries. That allows
 # to check uncommitted changes being replicated and such.
index 157ddba8cfa3cc63646490ded7bc40b0fe180719..74965348791079a1438ad3c307de9032d1d226cb 100644 (file)
@@ -20,11 +20,7 @@ else
 }
 
 
-# To avoid hanging while expecting some specific input from a psql
-# instance being driven by us, add a timeout high enough that it
-# should never trigger even on very slow machines, unless something
-# is really wrong.
-my $psql_timeout = IPC::Run::timer(60);
+my $psql_timeout = IPC::Run::timer($TestLib::timeout_default);
 
 my $node = get_new_node('node_crash');
 $node->init();
index f06ed8c8a13a61f5c50cd975d380bec6e92c5375..1befa826239587b1ced2068808e1e93d9549a0ba 100644 (file)
@@ -81,8 +81,8 @@ sub test_recovery_wal_level_minimal
            $recovery_node->logfile,  'start'
        ]);
 
-   # Wait up to 180s for postgres to terminate
-   foreach my $i (0 .. 1800)
+   # wait for postgres to terminate
+   foreach my $i (0 .. 10 * $TestLib::timeout_default)
    {
        last if !-f $recovery_node->data_dir . '/postmaster.pid';
        usleep(100_000);
index 6cc8b4a8d262d5ff8fab32523e74b0d310486479..998650ac86a043ce5ad30977ca17a6e0f14c5a0a 100644 (file)
@@ -58,7 +58,7 @@ is($result, qq(2|2|2), 'check initial data was copied to subscriber');
 my $in  = '';
 my $out = '';
 
-my $timer = IPC::Run::timeout(180);
+my $timer = IPC::Run::timeout($TestLib::timeout_default);
 
 my $h = $node_publisher->background_psql('postgres', \$in, \$out, $timer,
    on_error_stop => 0);