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:13 +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]

20 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/psql/t/020_cancel.pl
src/bin/scripts/t/080_pg_isready.pl
src/test/perl/PostgreSQL/Test/Cluster.pm
src/test/perl/PostgreSQL/Test/Utils.pm
src/test/perl/README
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 d604def0d02d1eb145061958e7df3659742f7242..b8e4ac7cf41ba6dbeabf8009f6043ef90c0b0f66 100644 (file)
@@ -18,7 +18,8 @@ my ($node, $result);
 #
 $node = PostgreSQL::Test::Cluster->new('CIC_test');
 $node->init;
-$node->append_conf('postgresql.conf', 'lock_timeout = 180000');
+$node->append_conf('postgresql.conf',
+   'lock_timeout = ' . (1000 * $PostgreSQL::Test::Utils::timeout_default));
 $node->start;
 $node->safe_psql('postgres', q(CREATE EXTENSION amcheck));
 $node->safe_psql('postgres', q(CREATE TABLE tbl(i int)));
index f668ed3c40ad3a243ffdbe4d67887185497b8550..e66ccd93f18266a80179e192abfa4b0dd25c6d12 100644 (file)
@@ -22,7 +22,8 @@ my ($node, $result);
 $node = PostgreSQL::Test::Cluster->new('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 * $PostgreSQL::Test::Utils::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($PostgreSQL::Test::Utils::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($PostgreSQL::Test::Utils::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($PostgreSQL::Test::Utils::timeout_default);
 my $reindex_h =
   $node->background_psql('postgres', \$reindex_in, \$reindex_out,
    $reindex_timer, on_error_stop => 1);
index d29045210013421964c494a6651776e8a51c09b9..d73ce034cd7f792850c21965bd5201530b968cd5 100644 (file)
@@ -39,7 +39,7 @@ sub check_log_pattern
    my $node     = shift;
    my $lfname   = fetch_file_name($logfiles, $format);
 
-   my $max_attempts = 180 * 10;
+   my $max_attempts = 10 * $PostgreSQL::Test::Utils::timeout_default;
 
    my $logcontents;
    for (my $attempts = 0; $attempts < $max_attempts; $attempts++)
@@ -78,7 +78,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 * $PostgreSQL::Test::Utils::timeout_default;
 
 my $current_logfiles;
 for (my $attempts = 0; $attempts < $max_attempts; $attempts++)
index d9bc267f6da029abad6ab4777fceb9803af9e813..3e55ff26f82f9f2725f34b6aa4ecb9219cd8d46e 100644 (file)
@@ -295,7 +295,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 * $PostgreSQL::Test::Utils::timeout_default),
            'postgres',
        ],
    },
index 005961f34d4ceb56e14f59392b5d7d073f0cd347..a54910680e57565d3d90b64aaee0d34c00422093 100644 (file)
@@ -94,7 +94,7 @@ close $FH;
 my $in  = '';
 my $out = '';
 
-my $timer = timer(5);
+my $timer = timer($PostgreSQL::Test::Utils::timeout_default);
 
 my $h = $node->interactive_psql('postgres', \$in, \$out, $timer);
 
@@ -111,7 +111,7 @@ sub check_completion
    # reset output collector
    $out = "";
    # restart per-command timer
-   $timer->start(5);
+   $timer->start($PostgreSQL::Test::Utils::timeout_default);
    # send the data to be sent
    $in .= $send;
    # wait ...
@@ -442,7 +442,7 @@ check_completion("blarg \t\t", qr//, "check completion failure path");
 clear_query();
 
 # send psql an explicit \q to shut it down, else pty won't close properly
-$timer->start(5);
+$timer->start($PostgreSQL::Test::Utils::timeout_default);
 $in .= "\\q\n";
 finish $h or die "psql returned $?";
 $timer->reset;
index 3224f8e26af523a0d6d5a15d51182266c7ca0048..d57d342952172ced5f9c2d256c789bb338188bd7 100644 (file)
@@ -46,12 +46,13 @@ SKIP: {
    my $psql_pid;
    until (-s "$tempdir/psql.pid" and ($psql_pid = PostgreSQL::Test::Utils::slurp_file("$tempdir/psql.pid")) =~ /^\d+\n/s)
    {
-       ($count++ < 180 * 100) or die "pid file did not appear";
+       ($count++ < 100 * $PostgreSQL::Test::Utils::timeout_default)
+         or die "pid file did not appear";
        usleep(10_000)
    }
 
    # Send sleep command and wait until the server has registered it
-   $stdin = "select pg_sleep(180);\n";
+   $stdin = "select pg_sleep($PostgreSQL::Test::Utils::timeout_default);\n";
    pump $h while length $stdin;
    $node->poll_query_until('postgres', q{SELECT (SELECT count(*) FROM pg_stat_activity WHERE query ~ '^select pg_sleep') > 0;})
      or die "timed out";
index e8436dc7e8a2cffa2c0d6180b000e3b65feefc1d..c45ca6666f9fa70d8deac9f0334cc08acae6cd94 100644 (file)
@@ -18,8 +18,8 @@ my $node = PostgreSQL::Test::Cluster->new('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=$PostgreSQL::Test::Utils::timeout_default" ],
    'succeeds with server running');
 
 done_testing();
index be05845248ad2ef073e386fb7240d049ec6df0be..4db52bc9367486b18a20638d56088460ef22182c 100644 (file)
@@ -36,7 +36,8 @@ PostgreSQL::Test::Cluster - 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 => $PostgreSQL::Test::Utils::timeout_default,
+     timed_out => \$timed_out,
      extra_params => ['--single-transaction'],
      on_error_die => 1)
   print "Sleep timed out" if $timed_out;
@@ -1723,7 +1724,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 => $PostgreSQL::Test::Utils::timeout_default,
+       timed_out => \$timed_out,
        extra_params => ['--single-transaction'])
 
 will set $cmdret to undef and $timed_out to a true value.
@@ -1897,7 +1899,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
+$PostgreSQL::Test::Utils::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>
@@ -1985,9 +1988,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
+$PostgreSQL::Test::Utils::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.
@@ -2303,7 +2307,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 $PostgreSQL::Test::Utils::timeout_default seconds.
 Returns 1 if successful, 0 if timed out.
 
 =cut
@@ -2321,7 +2325,7 @@ sub poll_query_until
        '-d',                             $self->connstr($dbname)
    ];
    my ($stdout, $stderr);
-   my $max_attempts = 180 * 10;
+   my $max_attempts = 10 * $PostgreSQL::Test::Utils::timeout_default;
    my $attempts     = 0;
 
    while ($attempts < $max_attempts)
@@ -2343,8 +2347,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:
@@ -2657,7 +2661,7 @@ sub wait_for_slot_catchup
 
 Waits for the contents of the server log file, starting at the given offset, to
 match the supplied regular expression.  Checks the entire log if no offset is
-given.  Times out after 180 seconds.
+given.  Times out after $PostgreSQL::Test::Utils::timeout_default seconds.
 
 If successful, returns the length of the entire log file, in bytes.
 
@@ -2668,7 +2672,7 @@ sub wait_for_log
    my ($self, $regexp, $offset) = @_;
    $offset = 0 unless defined $offset;
 
-   my $max_attempts = 180 * 10;
+   my $max_attempts = 10 * $PostgreSQL::Test::Utils::timeout_default;
    my $attempts     = 0;
 
    while ($attempts < $max_attempts)
@@ -2683,7 +2687,6 @@ sub wait_for_log
        $attempts++;
    }
 
-   # The logs didn't match within 180 seconds. Give up.
    croak "timed out waiting for match: $regexp";
 }
 
index 46cd74679635e960811ace59465ccdea69e4918d..15b314d1f8901588f05c3efff8a4cbafd51e10ac 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 0511c55e9aac0029607bf6506e0e95e29b47f1ce..4b160cce36ed3cb88d4e021b9a9893f0393f894b 100644 (file)
@@ -23,6 +23,12 @@ tmp_check/log/ to get more info.  Files named 'regress_log_XXX' are log
 output from the perl test scripts themselves, and should be examined first.
 Other files are postmaster logs, and may be helpful as additional data.
 
+The tests default to a timeout of 180 seconds for many individual operations.
+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.
+
 Data directories will also be left behind for analysis when a test fails;
 they are named according to the test filename.  But if the environment
 variable PG_TEST_NOCLEAN is set, data directories will be retained
index 25dd5ee7ec79b2a8d764a9f419bd433cda0c239b..e8e1a420bc11116d42b0a04e3641f46d1ad42084 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 * $PostgreSQL::Test::Utils::timeout_default)
 {
    last if !-f $node_standby->data_dir . '/postmaster.pid';
    usleep(100_000);
index fa6bd453324c60decc2ad1d21ea666e1696ac97e..9cec2792fc25604ec68bb32feba09967266c73f4 100644 (file)
@@ -107,7 +107,8 @@ $node_primary->safe_psql('postgres',
 );
 
 my $stdout_recv = $node_primary->pg_recvlogical_upto(
-   'postgres', 'test_slot', $endpos, 180,
+   'postgres', 'test_slot', $endpos,
+   $PostgreSQL::Test::Utils::timeout_default,
    'include-xids'     => '0',
    'skip-empty-xacts' => '1');
 chomp($stdout_recv);
@@ -119,7 +120,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,
+   $PostgreSQL::Test::Utils::timeout_default,
    'include-xids'     => '0',
    'skip-empty-xacts' => '1');
 chomp($stdout_recv);
index 6e8b0b1b968fd6db44275539a0d1392663c19cd4..01ff31e61f5a68de78076a29178b7adcf98a48c2 100644 (file)
@@ -157,7 +157,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 => $PostgreSQL::Test::Utils::timeout_default);
 is($ret, 0, 'replay from slot before_basebackup succeeds');
 
 my $final_expected_output_bb = q(BEGIN
@@ -186,7 +186,7 @@ my $endpos = $node_replica->safe_psql('postgres',
 
 $stdout = $node_replica->pg_recvlogical_upto(
    'postgres', 'before_basebackup',
-   $endpos,    180,
+   $endpos,    $PostgreSQL::Test::Utils::timeout_default,
    'include-xids'     => '0',
    'skip-empty-xacts' => '1');
 
index 3976e339c0655f322ba8b22a238f90687c13cac3..44c4c62cb75df5c4731161a2d8123204dbffffaf 100644 (file)
@@ -18,11 +18,7 @@ use PostgreSQL::Test::Utils;
 use Test::More;
 use Config;
 
-# 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($PostgreSQL::Test::Utils::timeout_default);
 
 my $node = PostgreSQL::Test::Cluster->new('primary');
 $node->init(allows_streaming => 1);
index 88f9e2b9cd769f14ea5d7fe5943125eeb3bcf0eb..713e6f068d7695cb8f056a6f1ec620e56bff63f4 100644 (file)
@@ -132,7 +132,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 * $PostgreSQL::Test::Utils::timeout_default));
 ok( $gnat->poll_query_until(
        'postgres',
        "SELECT 1 FROM pg_stat_activity WHERE query = '$slow_query'", '1'),
@@ -143,10 +143,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 $PostgreSQL::Test::Utils::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 * $PostgreSQL::Test::Utils::timeout_default;
    my $attempts     = 0;
    while ($attempts < $max_attempts)
    {
@@ -193,7 +194,7 @@ sub poll_start
 {
    my ($node) = @_;
 
-   my $max_attempts = 180 * 10;
+   my $max_attempts = 10 * $PostgreSQL::Test::Utils::timeout_default;
    my $attempts     = 0;
 
    while ($attempts < $max_attempts)
@@ -209,8 +210,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 9bb71b62c06c9644bd75dbdedca831f7d64fe459..f62b7b32f6672883f0645aee5d11948f46ea63f1 100644 (file)
@@ -291,7 +291,7 @@ my @result =
         SELECT pg_switch_wal();
         CHECKPOINT;
         SELECT 'finished';",
-       timeout => '60'));
+       timeout => $PostgreSQL::Test::Utils::timeout_default));
 is($result[1], 'finished', 'check if checkpoint command is not blocked');
 
 $node_primary2->stop;
@@ -362,7 +362,7 @@ $logstart = get_log_size($node_primary3);
 kill 'STOP', $senderpid, $receiverpid;
 advance_wal($node_primary3, 2);
 
-my $max_attempts = 180;
+my $max_attempts = $PostgreSQL::Test::Utils::timeout_default;
 while ($max_attempts-- >= 0)
 {
    if (find_in_log(
@@ -385,7 +385,7 @@ $node_primary3->poll_query_until('postgres',
    "lost")
   or die "timed out waiting for slot to be lost";
 
-$max_attempts = 180;
+$max_attempts = $PostgreSQL::Test::Utils::timeout_default;
 while ($max_attempts-- >= 0)
 {
    if (find_in_log(
index 75cd487451484f4b27c96a43b9482e10d2693539..55d8c31b56f9b3f6d054f4c0556b6eb0de335426 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 * $PostgreSQL::Test::Utils::timeout_default);
 
 # One psql to primary and standby each, for all queries. That allows
 # to check uncommitted changes being replicated and such.
index 49dd86e848aed21800baab113f4ce9aa7c143fa9..36906b4aca6c8d536a5fd5b13627e29f438d355c 100644 (file)
@@ -15,11 +15,7 @@ if ($Config{osname} eq 'MSWin32')
    exit;
 }
 
-# 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($PostgreSQL::Test::Utils::timeout_default);
 
 my $node = PostgreSQL::Test::Cluster->new('node_crash');
 $node->init();
index c10bb5bf70f042796511d3025f48a6b54a459b7c..ce347e0cd1ad229daf6c5b378e71246f6015b155 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 * $PostgreSQL::Test::Utils::timeout_default)
    {
        last if !-f $recovery_node->data_dir . '/postmaster.pid';
        usleep(100_000);
index 9f221fc78c0c56f660659555a18c26ed93c76e85..6561b189de8ba552ce1d81cae9fd6e2ef014d643 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($PostgreSQL::Test::Utils::timeout_default);
 
 my $h = $node_publisher->background_psql('postgres', \$in, \$out, $timer,
    on_error_stop => 0);