Skip to content

Commit f60bb3e

Browse files
nmischnmisch
committed
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
1 parent a008c03 commit f60bb3e

18 files changed

+63
-55
lines changed

‎contrib/amcheck/t/002_cic.pl

Lines changed: 2 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -18,7 +18,8 @@
1818
#
1919
$node = get_new_node('CIC_test');
2020
$node->init;
21-
$node->append_conf('postgresql.conf', 'lock_timeout = 180000');
21+
$node->append_conf('postgresql.conf',
22+
'lock_timeout = ' . (1000 * $TestLib::timeout_default));
2223
$node->start;
2324
$node->safe_psql('postgres', q(CREATE EXTENSION amcheck));
2425
$node->safe_psql('postgres', q(CREATE TABLE tbl(i int)));

‎contrib/amcheck/t/003_cic_2pc.pl

Lines changed: 8 additions & 6 deletions
Original file line numberDiff line numberDiff line change
@@ -22,7 +22,8 @@
2222
$node = get_new_node('CIC_2PC_test');
2323
$node->init;
2424
$node->append_conf('postgresql.conf', 'max_prepared_transactions = 10');
25-
$node->append_conf('postgresql.conf', 'lock_timeout = 180000');
25+
$node->append_conf('postgresql.conf',
26+
'lock_timeout = ' . (1000 * $TestLib::timeout_default));
2627
$node->start;
2728
$node->safe_psql('postgres', q(CREATE EXTENSION amcheck));
2829
$node->safe_psql('postgres', q(CREATE TABLE tbl(i int)));
@@ -38,7 +39,7 @@
3839

3940
my $main_in = '';
4041
my $main_out = '';
41-
my $main_timer = IPC::Run::timeout(180);
42+
my $main_timer = IPC::Run::timeout($TestLib::timeout_default);
4243

4344
my $main_h =
4445
$node->background_psql('postgres', \$main_in, \$main_out,
@@ -52,7 +53,7 @@
5253

5354
my $cic_in = '';
5455
my $cic_out = '';
55-
my $cic_timer = IPC::Run::timeout(180);
56+
my $cic_timer = IPC::Run::timeout($TestLib::timeout_default);
5657
my $cic_h =
5758
$node->background_psql('postgres', \$cic_in, \$cic_out,
5859
$cic_timer, on_error_stop => 1);
@@ -113,9 +114,10 @@
113114
));
114115
$node->restart;
115116

116-
my $reindex_in = '';
117-
my $reindex_out = '';
118-
my $reindex_timer = IPC::Run::timeout(180);
117+
my $reindex_in = '';
118+
my $reindex_out = '';
119+
my $reindex_timer =
120+
IPC::Run::timeout($TestLib::timeout_default);
119121
my $reindex_h =
120122
$node->background_psql('postgres', \$reindex_in, \$reindex_out,
121123
$reindex_timer, on_error_stop => 1);

‎src/bin/pg_ctl/t/004_logrotate.pl

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -27,7 +27,7 @@
2727
$node->psql('postgres', 'SELECT 1/0');
2828

2929
# might need to retry if logging collector process is slow...
30-
my $max_attempts = 180 * 10;
30+
my $max_attempts = 10 * $TestLib::timeout_default;
3131

3232
my $current_logfiles;
3333
for (my $attempts = 0; $attempts < $max_attempts; $attempts++)

‎src/bin/pg_dump/t/002_pg_dump.pl

Lines changed: 2 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -281,7 +281,8 @@
281281
'--no-sync',
282282
"--file=$tempdir/only_dump_test_table.sql",
283283
'--table=dump_test.test_table',
284-
'--lock-wait-timeout=1000000',
284+
'--lock-wait-timeout='
285+
. (1000 * $TestLib::timeout_default),
285286
'postgres',
286287
],
287288
},

‎src/bin/psql/t/010_tab_completion.pl

Lines changed: 3 additions & 3 deletions
Original file line numberDiff line numberDiff line change
@@ -92,7 +92,7 @@
9292
my $in = '';
9393
my $out = '';
9494

95-
my $timer = timer(5);
95+
my $timer = timer($TestLib::timeout_default);
9696

9797
my $h = $node->interactive_psql('postgres', \$in, \$out, $timer);
9898

@@ -109,7 +109,7 @@ sub check_completion
109109
# reset output collector
110110
$out = "";
111111
# restart per-command timer
112-
$timer->start(5);
112+
$timer->start($TestLib::timeout_default);
113113
# send the data to be sent
114114
$in .= $send;
115115
# wait ...
@@ -235,7 +235,7 @@ sub clear_line
235235
clear_line();
236236

237237
# send psql an explicit \q to shut it down, else pty won't close properly
238-
$timer->start(5);
238+
$timer->start($TestLib::timeout_default);
239239
$in .= "\\q\n";
240240
finish $h or die "psql returned $?";
241241
$timer->reset;

‎src/bin/scripts/t/080_pg_isready.pl

Lines changed: 2 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -18,6 +18,6 @@
1818
$node->init;
1919
$node->start;
2020

21-
# use a long timeout for the benefit of very slow buildfarm machines
22-
$node->command_ok([qw(pg_isready --timeout=60)],
21+
$node->command_ok(
22+
[ 'pg_isready', "--timeout=$TestLib::timeout_default" ],
2323
'succeeds with server running');

‎src/test/perl/PostgresNode.pm

Lines changed: 14 additions & 10 deletions
Original file line numberDiff line numberDiff line change
@@ -33,7 +33,8 @@ PostgresNode - class representing PostgreSQL server instance
3333
my ($stdout, $stderr, $timed_out);
3434
my $cmdret = $node->psql('postgres', 'SELECT pg_sleep(600)',
3535
stdout => \$stdout, stderr => \$stderr,
36-
timeout => 180, timed_out => \$timed_out,
36+
timeout => $TestLib::timeout_default,
37+
timed_out => \$timed_out,
3738
extra_params => ['--single-transaction'],
3839
on_error_die => 1)
3940
print "Sleep timed out" if $timed_out;
@@ -1650,7 +1651,8 @@ e.g.
16501651
my ($stdout, $stderr, $timed_out);
16511652
my $cmdret = $node->psql('postgres', 'SELECT pg_sleep(600)',
16521653
stdout => \$stdout, stderr => \$stderr,
1653-
timeout => 180, timed_out => \$timed_out,
1654+
timeout => $TestLib::timeout_default,
1655+
timed_out => \$timed_out,
16541656
extra_params => ['--single-transaction'])
16551657
16561658
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
18241826
while idling this backend.
18251827
18261828
The specified timer object is attached to the harness, as well. It's caller's
1827-
responsibility to select the timeout length, and to restart the timer after
1829+
responsibility to set the timeout length (usually
1830+
$TestLib::timeout_default), and to restart the timer after
18281831
each command if the timeout is per-command.
18291832
18301833
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,
19121915
and its stdout and stderr go to the $stdout scalar reference.
19131916
ptys are used so that psql thinks it's being called interactively.
19141917
1915-
The specified timer object is attached to the harness, as well.
1916-
It's caller's responsibility to select the timeout length, and to
1917-
restart the timer after each command if the timeout is per-command.
1918+
The specified timer object is attached to the harness, as well. It's caller's
1919+
responsibility to set the timeout length (usually
1920+
$TestLib::timeout_default), and to restart the timer after
1921+
each command if the timeout is per-command.
19181922
19191923
psql is invoked in tuples-only unaligned mode with reading of B<.psqlrc>
19201924
disabled. That may be overridden by passing extra psql parameters.
@@ -2227,7 +2231,7 @@ sub connect_fails
22272231
Run B<$query> repeatedly, until it returns the B<$expected> result
22282232
('t', or SQL boolean true, by default).
22292233
Continues polling if B<psql> returns an error result.
2230-
Times out after 180 seconds.
2234+
Times out after $TestLib::timeout_default seconds.
22312235
Returns 1 if successful, 0 if timed out.
22322236
22332237
=cut
@@ -2245,7 +2249,7 @@ sub poll_query_until
22452249
'-d', $self->connstr($dbname)
22462250
];
22472251
my ($stdout, $stderr);
2248-
my $max_attempts = 180 * 10;
2252+
my $max_attempts = 10 * $TestLib::timeout_default;
22492253
my $attempts = 0;
22502254

22512255
while ($attempts < $max_attempts)
@@ -2267,8 +2271,8 @@ sub poll_query_until
22672271
$attempts++;
22682272
}
22692273

2270-
# The query result didn't change in 180 seconds. Give up. Print the
2271-
# output from the last attempt, hopefully that's useful for debugging.
2274+
# Give up. Print the output from the last attempt, hopefully that's useful
2275+
# for debugging.
22722276
diag qq(poll_query_until timed out executing this query:
22732277
$query
22742278
expecting this output:

‎src/test/perl/TestLib.pm

Lines changed: 6 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -91,8 +91,8 @@ our @EXPORT = qw(
9191
$use_unix_sockets
9292
);
9393

94-
our ($windows_os, $is_msys2, $use_unix_sockets, $tmp_check, $log_path,
95-
$test_logfile);
94+
our ($windows_os, $is_msys2, $use_unix_sockets, $timeout_default,
95+
$tmp_check, $log_path, $test_logfile);
9696

9797
BEGIN
9898
{
@@ -157,6 +157,10 @@ BEGIN
157157
# supported, but it can be overridden if desired.
158158
$use_unix_sockets =
159159
(!$windows_os || defined $ENV{PG_TEST_USE_UNIX_SOCKETS});
160+
161+
$timeout_default = $ENV{PG_TEST_TIMEOUT_DEFAULT};
162+
$timeout_default = 180
163+
if not defined $timeout_default or $timeout_default eq '';
160164
}
161165

162166
=pod

‎src/test/recovery/t/003_recovery_targets.pl

Lines changed: 2 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -172,8 +172,8 @@ sub test_recovery_standby
172172
$node_standby->logfile, 'start'
173173
]);
174174

175-
# wait up to 180s for postgres to terminate
176-
foreach my $i (0 .. 1800)
175+
# wait for postgres to terminate
176+
foreach my $i (0 .. 10 * $TestLib::timeout_default)
177177
{
178178
last if !-f $node_standby->data_dir . '/postmaster.pid';
179179
usleep(100_000);

‎src/test/recovery/t/006_logical_decoding.pl

Lines changed: 4 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -98,7 +98,8 @@
9898
);
9999

100100
my $stdout_recv = $node_primary->pg_recvlogical_upto(
101-
'postgres', 'test_slot', $endpos, 180,
101+
'postgres', 'test_slot', $endpos,
102+
$TestLib::timeout_default,
102103
'include-xids' => '0',
103104
'skip-empty-xacts' => '1');
104105
chomp($stdout_recv);
@@ -110,7 +111,8 @@
110111
) or die "slot never became inactive";
111112

112113
$stdout_recv = $node_primary->pg_recvlogical_upto(
113-
'postgres', 'test_slot', $endpos, 180,
114+
'postgres', 'test_slot', $endpos,
115+
$TestLib::timeout_default,
114116
'include-xids' => '0',
115117
'skip-empty-xacts' => '1');
116118
chomp($stdout_recv);

‎src/test/recovery/t/010_logical_decoding_timelines.pl

Lines changed: 2 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -158,7 +158,7 @@
158158
($ret, $stdout, $stderr) = $node_replica->psql(
159159
'postgres',
160160
"SELECT data FROM pg_logical_slot_peek_changes('before_basebackup', NULL, NULL, 'include-xids', '0', 'skip-empty-xacts', '1');",
161-
timeout => 180);
161+
timeout => $TestLib::timeout_default);
162162
is($ret, 0, 'replay from slot before_basebackup succeeds');
163163

164164
my $final_expected_output_bb = q(BEGIN
@@ -187,7 +187,7 @@ BEGIN
187187

188188
$stdout = $node_replica->pg_recvlogical_upto(
189189
'postgres', 'before_basebackup',
190-
$endpos, 180,
190+
$endpos, $TestLib::timeout_default,
191191
'include-xids' => '0',
192192
'skip-empty-xacts' => '1');
193193

‎src/test/recovery/t/013_crash_restart.pl

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -25,7 +25,7 @@
2525
# instance being driven by us, add a timeout high enough that it
2626
# should never trigger even on very slow machines, unless something
2727
# is really wrong.
28-
my $psql_timeout = IPC::Run::timer(60);
28+
my $psql_timeout = IPC::Run::timer($TestLib::timeout_default);
2929

3030
my $node = get_new_node('primary');
3131
$node->init(allows_streaming => 1);

‎src/test/recovery/t/017_shm.pl

Lines changed: 7 additions & 6 deletions
Original file line numberDiff line numberDiff line change
@@ -136,7 +136,7 @@ sub log_ipcs
136136
\$stdout,
137137
'2>',
138138
\$stderr,
139-
IPC::Run::timeout(900)); # five times the poll_query_until timeout
139+
IPC::Run::timeout(5 * $TestLib::timeout_default));
140140
ok( $gnat->poll_query_until(
141141
'postgres',
142142
"SELECT 1 FROM pg_stat_activity WHERE query = '$slow_query'", '1'),
@@ -147,10 +147,11 @@ sub log_ipcs
147147
unlink($gnat->data_dir . '/postmaster.pid');
148148
$gnat->rotate_logfile; # on Windows, can't open old log for writing
149149
log_ipcs();
150-
# Reject ordinary startup. Retry for the same reasons poll_start() does.
150+
# Reject ordinary startup. Retry for the same reasons poll_start() does,
151+
# every 0.1s for at least $TestLib::timeout_default seconds.
151152
my $pre_existing_msg = qr/pre-existing shared memory block/;
152153
{
153-
my $max_attempts = 180 * 10; # Retry every 0.1s for at least 180s.
154+
my $max_attempts = 10 * $TestLib::timeout_default;
154155
my $attempts = 0;
155156
while ($attempts < $max_attempts)
156157
{
@@ -197,7 +198,7 @@ sub poll_start
197198
{
198199
my ($node) = @_;
199200

200-
my $max_attempts = 180 * 10;
201+
my $max_attempts = 10 * $TestLib::timeout_default;
201202
my $attempts = 0;
202203

203204
while ($attempts < $max_attempts)
@@ -213,8 +214,8 @@ sub poll_start
213214
$attempts++;
214215
}
215216

216-
# No success within 180 seconds. Try one last time without fail_ok, which
217-
# will BAIL_OUT unless it succeeds.
217+
# Try one last time without fail_ok, which will BAIL_OUT unless it
218+
# succeeds.
218219
$node->start && return 1;
219220
return 0;
220221
}

‎src/test/recovery/t/019_replslot_limit.pl

Lines changed: 3 additions & 3 deletions
Original file line numberDiff line numberDiff line change
@@ -296,7 +296,7 @@
296296
SELECT pg_switch_wal();
297297
CHECKPOINT;
298298
SELECT 'finished';",
299-
timeout => '60'));
299+
timeout => $TestLib::timeout_default));
300300
is($result[1], 'finished', 'check if checkpoint command is not blocked');
301301

302302
$node_primary2->stop;
@@ -348,7 +348,7 @@
348348
kill 'STOP', $senderpid, $receiverpid;
349349
advance_wal($node_primary3, 2);
350350

351-
my $max_attempts = 180;
351+
my $max_attempts = $TestLib::timeout_default;
352352
while ($max_attempts-- >= 0)
353353
{
354354
if (find_in_log(
@@ -371,7 +371,7 @@
371371
"lost")
372372
or die "timed out waiting for slot to be lost";
373373

374-
$max_attempts = 180;
374+
$max_attempts = $TestLib::timeout_default;
375375
while ($max_attempts-- >= 0)
376376
{
377377
if (find_in_log(

‎src/test/recovery/t/021_row_visibility.pl

Lines changed: 2 additions & 5 deletions
Original file line numberDiff line numberDiff line change
@@ -32,11 +32,8 @@
3232
$node_standby->append_conf('postgresql.conf', 'max_prepared_transactions=10');
3333
$node_standby->start;
3434

35-
# To avoid hanging while expecting some specific input from a psql
36-
# instance being driven by us, add a timeout high enough that it
37-
# should never trigger even on very slow machines, unless something
38-
# is really wrong.
39-
my $psql_timeout = IPC::Run::timer(300);
35+
my $psql_timeout =
36+
IPC::Run::timer(2 * $TestLib::timeout_default);
4037

4138
# One psql to primary and standby each, for all queries. That allows
4239
# to check uncommitted changes being replicated and such.

‎src/test/recovery/t/022_crash_temp_files.pl

Lines changed: 1 addition & 5 deletions
Original file line numberDiff line numberDiff line change
@@ -20,11 +20,7 @@
2020
}
2121

2222

23-
# To avoid hanging while expecting some specific input from a psql
24-
# instance being driven by us, add a timeout high enough that it
25-
# should never trigger even on very slow machines, unless something
26-
# is really wrong.
27-
my $psql_timeout = IPC::Run::timer(60);
23+
my $psql_timeout = IPC::Run::timer($TestLib::timeout_default);
2824

2925
my $node = get_new_node('node_crash');
3026
$node->init();

‎src/test/recovery/t/024_archive_recovery.pl

Lines changed: 2 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -81,8 +81,8 @@ sub test_recovery_wal_level_minimal
8181
$recovery_node->logfile, 'start'
8282
]);
8383

84-
# Wait up to 180s for postgres to terminate
85-
foreach my $i (0 .. 1800)
84+
# wait for postgres to terminate
85+
foreach my $i (0 .. 10 * $TestLib::timeout_default)
8686
{
8787
last if !-f $recovery_node->data_dir . '/postmaster.pid';
8888
usleep(100_000);

‎src/test/subscription/t/015_stream.pl

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -58,7 +58,7 @@
5858
my $in = '';
5959
my $out = '';
6060

61-
my $timer = IPC::Run::timeout(180);
61+
my $timer = IPC::Run::timeout($TestLib::timeout_default);
6262

6363
my $h = $node_publisher->background_psql('postgres', \$in, \$out, $timer,
6464
on_error_stop => 0);

0 commit comments

Comments
 (0)