From 7f2e1befc039029ce5be36088f6872ad393d007c Mon Sep 17 00:00:00 2001 From: Noah Misch Date: Fri, 4 Mar 2022 18:53:13 -0800 Subject: [PATCH] Introduce PG_TEST_TIMEOUT_DEFAULT for TAP suite non-elapsing timeouts. 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.GA3627003@rfd.leadboat.com --- src/bin/pg_dump/t/002_pg_dump.pl | 3 ++- src/bin/pgbench/t/022_cic.pl | 5 +++-- src/bin/pgbench/t/023_cic_2pc.pl | 16 +++++++++------- src/bin/scripts/t/080_pg_isready.pl | 5 +++-- src/test/perl/PostgresNode.pm | 17 ++++++++++------- src/test/perl/TestLib.pm | 6 +++++- src/test/recovery/t/006_logical_decoding.pl | 4 ++-- .../t/010_logical_decoding_timelines.pl | 4 ++-- src/test/recovery/t/017_shm.pl | 13 +++++++------ 9 files changed, 43 insertions(+), 30 deletions(-) diff --git a/src/bin/pg_dump/t/002_pg_dump.pl b/src/bin/pg_dump/t/002_pg_dump.pl index f59fcb6491a..8819999461a 100644 --- a/src/bin/pg_dump/t/002_pg_dump.pl +++ b/src/bin/pg_dump/t/002_pg_dump.pl @@ -209,7 +209,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', ], }, role => { dump_cmd => [ diff --git a/src/bin/pgbench/t/022_cic.pl b/src/bin/pgbench/t/022_cic.pl index a1cda5b47ae..2a874bdf26e 100644 --- a/src/bin/pgbench/t/022_cic.pl +++ b/src/bin/pgbench/t/022_cic.pl @@ -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 TABLE tbl(i int))); $node->safe_psql('postgres', q(CREATE INDEX idx ON tbl(i))); @@ -48,7 +49,7 @@ $node->safe_psql( # Run background pgbench with CIC. We cannot mix-in this script into single # pgbench: CIC will deadlock with itself occasionally. my $pgbench_out = ''; -my $pgbench_timer = IPC::Run::timeout(180); +my $pgbench_timer = IPC::Run::timeout($TestLib::timeout_default); my $pgbench_h = $node->background_pgbench( '--no-vacuum --client=1 --transactions=200', { diff --git a/src/bin/pgbench/t/023_cic_2pc.pl b/src/bin/pgbench/t/023_cic_2pc.pl index 5d695819a34..b1355a24601 100644 --- a/src/bin/pgbench/t/023_cic_2pc.pl +++ b/src/bin/pgbench/t/023_cic_2pc.pl @@ -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 TABLE tbl(i int))); $node->safe_psql( @@ -55,7 +56,7 @@ $node->safe_psql( 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, @@ -69,7 +70,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); @@ -131,9 +132,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); @@ -161,7 +163,7 @@ $node->safe_psql('postgres', q(REINDEX TABLE tbl;)); # Run background pgbench with CIC. We cannot mix-in this script into single # pgbench: CIC will deadlock with itself occasionally. my $pgbench_out = ''; -my $pgbench_timer = IPC::Run::timeout(180); +my $pgbench_timer = IPC::Run::timeout($TestLib::timeout_default); my $pgbench_h = $node->background_pgbench( '--no-vacuum --client=1 --transactions=100', { diff --git a/src/bin/scripts/t/080_pg_isready.pl b/src/bin/scripts/t/080_pg_isready.pl index d01804da371..fc2f54f061c 100644 --- a/src/bin/scripts/t/080_pg_isready.pl +++ b/src/bin/scripts/t/080_pg_isready.pl @@ -15,5 +15,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)], 'succeeds with server running'); +$node->command_ok( + [ 'pg_isready', "--timeout=$TestLib::timeout_default" ], + 'succeeds with server running'); diff --git a/src/test/perl/PostgresNode.pm b/src/test/perl/PostgresNode.pm index 099d4981e5e..d673494e889 100644 --- a/src/test/perl/PostgresNode.pm +++ b/src/test/perl/PostgresNode.pm @@ -31,7 +31,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; @@ -1246,7 +1247,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. @@ -1403,7 +1405,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> @@ -1624,7 +1627,7 @@ sub background_pgbench 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 @@ -1637,7 +1640,7 @@ sub poll_query_until my $cmd = [ 'psql', '-XAt', '-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) @@ -1659,8 +1662,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: diff --git a/src/test/perl/TestLib.pm b/src/test/perl/TestLib.pm index 6a738ba8b95..73db8f43406 100644 --- a/src/test/perl/TestLib.pm +++ b/src/test/perl/TestLib.pm @@ -45,7 +45,7 @@ our @EXPORT = qw( $windows_os ); -our ($windows_os, $tmp_check, $log_path, $test_logfile); +our ($windows_os, $timeout_default, $tmp_check, $log_path, $test_logfile); BEGIN { @@ -92,6 +92,10 @@ BEGIN require Win32API::File; Win32API::File->import(qw(createFile OsFHandleOpen CloseHandle)); } + + $timeout_default = $ENV{PG_TEST_TIMEOUT_DEFAULT}; + $timeout_default = 180 + if not defined $timeout_default or $timeout_default eq ''; } INIT diff --git a/src/test/recovery/t/006_logical_decoding.pl b/src/test/recovery/t/006_logical_decoding.pl index 5b6731f7df0..7e297c6c2c0 100644 --- a/src/test/recovery/t/006_logical_decoding.pl +++ b/src/test/recovery/t/006_logical_decoding.pl @@ -76,7 +76,7 @@ $node_master->safe_psql('postgres', ); my $stdout_recv = $node_master->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); @@ -89,7 +89,7 @@ $node_master->poll_query_until('postgres', or die "slot never became inactive"; $stdout_recv = $node_master->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); diff --git a/src/test/recovery/t/010_logical_decoding_timelines.pl b/src/test/recovery/t/010_logical_decoding_timelines.pl index b9d2638815a..ee5b31d975b 100644 --- a/src/test/recovery/t/010_logical_decoding_timelines.pl +++ b/src/test/recovery/t/010_logical_decoding_timelines.pl @@ -155,7 +155,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 @@ -184,7 +184,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'); diff --git a/src/test/recovery/t/017_shm.pl b/src/test/recovery/t/017_shm.pl index 94bc43ed073..a2e2c2659ee 100644 --- a/src/test/recovery/t/017_shm.pl +++ b/src/test/recovery/t/017_shm.pl @@ -120,7 +120,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'), @@ -131,10 +131,11 @@ $gnat->kill9; unlink($gnat->data_dir . '/postmaster.pid'); $gnat->rotate_logfile; 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) { @@ -184,7 +185,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) @@ -200,8 +201,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; } -- 2.39.5