Alexander Lakhin <exclus...@gmail.com> writes:
> Let me show you another related anomaly, which drongo kindly discovered
> recently: [1]. That test failed with:
> SELECT dblink_cancel_query('dtest1');
> - dblink_cancel_query
> ----------------------
> - OK
> + dblink_cancel_query
> +--------------------------
> + cancel request timed out
> (1 row)
While we're piling on, has anyone noticed that *non* Windows buildfarm
animals are also failing this test pretty frequently? The most recent
occurrence is at [1], and it looks like this:
diff -U3
/home/bf/bf-build/mylodon/HEAD/pgsql/contrib/postgres_fdw/expected/query_cancel.out
/home/bf/bf-build/mylodon/HEAD/pgsql.build/testrun/postgres_fdw/regress/results/query_cancel.out
---
/home/bf/bf-build/mylodon/HEAD/pgsql/contrib/postgres_fdw/expected/query_cancel.out
2024-07-22 11:09:50.638133878 +0000
+++
/home/bf/bf-build/mylodon/HEAD/pgsql.build/testrun/postgres_fdw/regress/results/query_cancel.out
2024-08-30 06:28:01.971083945 +0000
@@ -17,4 +17,5 @@
SET LOCAL statement_timeout = '10ms';
select count(*) from ft1 CROSS JOIN ft2 CROSS JOIN ft4 CROSS JOIN ft5; -- this
takes very long
ERROR: canceling statement due to statement timeout
+WARNING: could not get result of cancel request due to timeout
COMMIT;
I trawled the buildfarm database for other occurrences of "could not
get result of cancel request" since this test went in. I found 34
of them (see attachment), and none that weren't the timeout flavor.
Most of the failing machines are not especially slow, so even though
the hard-wired 30 second timeout that's being used here feels a little
under-engineered, I'm not sure that arranging to raise it would help.
My spidey sense feels that there's some actual bug here, but it's hard
to say where. mylodon's postmaster log confirms that the 30 seconds
did elapse, and that there wasn't anything much else going on:
2024-08-30 06:27:31.926 UTC client backend[3668381] pg_regress/query_cancel
ERROR: canceling statement due to statement timeout
2024-08-30 06:27:31.926 UTC client backend[3668381] pg_regress/query_cancel
STATEMENT: select count(*) from ft1 CROSS JOIN ft2 CROSS JOIN ft4 CROSS JOIN
ft5;
2024-08-30 06:28:01.946 UTC client backend[3668381] pg_regress/query_cancel
WARNING: could not get result of cancel request due to timeout
Any thoughts?
regards, tom lane
[1]
https://buildfarm.postgresql.org/cgi-bin/show_log.pl?nm=mylodon&dt=2024-08-30%2006%3A25%3A46
sysname | branch | snapshot | stage
| l
---------------+---------------+---------------------+----------------------------+---------------------------------------------------------------------------------------------------------------------------------------------
flaviventris | HEAD | 2024-04-02 23:58:01 |
postgres_fdwInstallCheck-C | +WARNING: could not get result of cancel request
due to timeout
calliphoridae | HEAD | 2024-04-11 01:54:17 |
postgres_fdwInstallCheck-C | +WARNING: could not get result of cancel request
due to timeout
kestrel | REL_17_STABLE | 2024-07-13 04:15:25 |
postgres_fdwInstallCheck-C | +WARNING: could not get result of cancel request
due to timeout
sarus | REL_17_STABLE | 2024-07-20 15:02:23 | ContribCheck-C
| 2024-07-20 15:10:15.547 UTC [613791:141] pg_regress/postgres_fdw WARNING:
could not get result of cancel request due to timeout
sarus | REL_17_STABLE | 2024-07-20 15:02:23 | ContribCheck-C
| +WARNING: could not get result of cancel request due to timeout
mylodon | HEAD | 2024-07-26 13:15:09 |
postgres_fdwInstallCheck-C | +WARNING: could not get result of cancel request
due to timeout
adder | HEAD | 2024-07-02 00:24:10 | postgres_fdwCheck
| +WARNING: could not get result of cancel request due to timeout
adder | HEAD | 2024-07-02 00:24:10 | postgres_fdwCheck
| 2024-07-02 00:33:45.770 UTC client backend[1036068] pg_regress/postgres_fdw
WARNING: could not get result of cancel request due to timeout
calliphoridae | REL_17_STABLE | 2024-07-16 22:45:08 |
postgres_fdwInstallCheck-C | +WARNING: could not get result of cancel request
due to timeout
mylodon | HEAD | 2024-08-09 05:25:24 | postgres_fdwCheck
| +WARNING: could not get result of cancel request due to timeout
mylodon | HEAD | 2024-08-09 05:25:24 | postgres_fdwCheck
| 2024-08-09 05:28:21.990 UTC client backend[1775253] pg_regress/query_cancel
WARNING: could not get result of cancel request due to timeout
mylodon | HEAD | 2024-04-24 07:12:22 |
postgres_fdwInstallCheck-C | +WARNING: could not get result of cancel request
due to timeout
skink | HEAD | 2024-07-20 20:57:01 | postgres_fdwCheck
| +WARNING: could not get result of cancel request due to timeout
skink | HEAD | 2024-07-20 20:57:01 | postgres_fdwCheck
| 2024-07-20 21:06:58.166 UTC client backend[2223425] pg_regress/postgres_fdw
WARNING: could not get result of cancel request due to timeout
grassquit | HEAD | 2024-08-20 19:29:20 | postgres_fdwCheck
| +WARNING: could not get result of cancel request due to timeout
grassquit | HEAD | 2024-08-20 19:29:20 | postgres_fdwCheck
| 2024-08-20 19:36:26.162 UTC client backend[2332294] pg_regress/query_cancel
WARNING: could not get result of cancel request due to timeout
adder | REL_17_STABLE | 2024-08-29 12:52:00 | postgres_fdwCheck
| +WARNING: could not get result of cancel request due to timeout
adder | REL_17_STABLE | 2024-08-29 12:52:00 | postgres_fdwCheck
| 2024-08-29 12:58:57.965 UTC client backend[2022100] pg_regress/query_cancel
WARNING: could not get result of cancel request due to timeout
mylodon | HEAD | 2024-08-30 06:25:46 | postgres_fdwCheck
| +WARNING: could not get result of cancel request due to timeout
mylodon | HEAD | 2024-08-30 06:25:46 | postgres_fdwCheck
| 2024-08-30 06:28:01.946 UTC client backend[3668381] pg_regress/query_cancel
WARNING: could not get result of cancel request due to timeout
mylodon | HEAD | 2024-04-16 18:31:28 | postgres_fdwCheck
| +WARNING: could not get result of cancel request due to timeout
mylodon | HEAD | 2024-04-16 18:31:28 | postgres_fdwCheck
| 2024-04-16 18:37:25.510 UTC client backend[1915743] pg_regress/postgres_fdw
WARNING: could not get result of cancel request due to timeout
francolin | HEAD | 2024-07-09 00:17:16 | postgres_fdwCheck
| +WARNING: could not get result of cancel request due to timeout
francolin | HEAD | 2024-07-09 00:17:16 | postgres_fdwCheck
| 2024-07-09 00:22:05.554 UTC client backend[3576551] pg_regress/postgres_fdw
WARNING: could not get result of cancel request due to timeout
mylodon | HEAD | 2024-07-09 03:46:50 | postgres_fdwCheck
| +WARNING: could not get result of cancel request due to timeout
mylodon | HEAD | 2024-07-09 03:46:50 | postgres_fdwCheck
| 2024-07-09 03:50:26.354 UTC client backend[3424317] pg_regress/postgres_fdw
WARNING: could not get result of cancel request due to timeout
adder | HEAD | 2024-08-29 10:42:09 |
postgres_fdwInstallCheck-C | +WARNING: could not get result of cancel request
due to timeout
olingo | HEAD | 2024-06-20 09:52:04 |
postgres_fdwInstallCheck-C | +WARNING: could not get result of cancel request
due to timeout
francolin | HEAD | 2024-07-09 19:02:27 | postgres_fdwCheck
| +WARNING: could not get result of cancel request due to timeout
francolin | HEAD | 2024-07-09 19:02:27 | postgres_fdwCheck
| 2024-07-09 19:05:09.198 UTC client backend[377098] pg_regress/postgres_fdw
WARNING: could not get result of cancel request due to timeout
skink | HEAD | 2024-08-10 19:52:56 | postgres_fdwCheck
| +WARNING: could not get result of cancel request due to timeout
skink | HEAD | 2024-08-10 19:52:56 | postgres_fdwCheck
| 2024-08-10 19:56:41.222 UTC client backend[1138302] pg_regress/query_cancel
WARNING: could not get result of cancel request due to timeout
snakefly | REL_17_STABLE | 2024-08-19 11:30:04 | ContribCheck-C
| +WARNING: could not get result of cancel request due to timeout
snakefly | REL_17_STABLE | 2024-08-19 11:30:04 | ContribCheck-C
| 2024-08-19 12:21:06.879 UTC [1312:11] pg_regress/query_cancel WARNING:
could not get result of cancel request due to timeout
(34 rows)
