From: Tom Lane <tgl@sss.pgh.pa.us>
To: Alexander Lakhin <exclusion@gmail.com>
Cc: Alvaro Herrera <alvherre@alvh.no-ip.org>
Cc: Jelte Fennema-Nio <postgres@jeltef.nl>
Cc: Noah Misch <noah@leadboat.com>
Cc: Jacob Champion <jacob.champion@enterprisedb.com>
Cc: Denis Laxalde <denis.laxalde@dalibo.com>
Cc: vignesh C <vignesh21@gmail.com>
Cc: Thomas Munro <thomas.munro@gmail.com>
Cc: Greg Stark <stark@mit.edu>
Cc: Gregory Stark (as CFM) <stark.cfm@gmail.com>
Cc: Jelte Fennema <Jelte.Fennema@microsoft.com>
Cc: Daniel Gustafsson <daniel@yesql.se>
Cc: Peter Eisentraut <peter@eisentraut.org>
Cc: Andres Freund <andres@anarazel.de>
Cc: Justin Pryzby <pryzby@telsasoft.com>
Cc: Robert Haas <robertmhaas@gmail.com>
Cc: pgsql-hackers@lists.postgresql.org, Etsuro Fujita <etsuro.fujita@gmail.com>
Subject: Re: [EXTERNAL] Re: Add non-blocking version of PQcancel
Date: Fri, 30 Aug 2024 15:21:25 -0400
Message-ID: <578934.1725045685@sss.pgh.pa.us> (raw)
In-Reply-To: <5ea25e4d-1ee2-b9bf-7806-119ffa658826@gmail.com>
References: <202407221126.vyw5q3h4nyoh@alvherre.pgsql>
<5ea25e4d-1ee2-b9bf-7806-119ffa658826@gmail.com>
Alexander Lakhin <exclusion@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)
Attachments:
[text/plain] cancel-request-failures.txt (6.3K, ../578934.1725045685@sss.pgh.pa.us/2-cancel-request-failures.txt)
download | inline:
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)
Reply instructions:
You may reply publicly to this message via plain-text email
using any one of the following methods:
* Reply to all the recipients using the --to and --cc options:
reply via email
To: pgsql-hackers@postgresql.org
Cc: tgl@sss.pgh.pa.us, exclusion@gmail.com, alvherre@alvh.no-ip.org, postgres@jeltef.nl, noah@leadboat.com, jacob.champion@enterprisedb.com, denis.laxalde@dalibo.com, vignesh21@gmail.com, thomas.munro@gmail.com, stark@mit.edu, stark.cfm@gmail.com, Jelte.Fennema@microsoft.com, daniel@yesql.se, peter@eisentraut.org, andres@anarazel.de, pryzby@telsasoft.com, robertmhaas@gmail.com, etsuro.fujita@gmail.com
Subject: Re: [EXTERNAL] Re: Add non-blocking version of PQcancel
In-Reply-To: <578934.1725045685@sss.pgh.pa.us>
* Save the following mbox file, import it into your mail client,
and reply-to-all from there: mbox
This inbox is served by DDX for PostgreSQL; see mirroring instructions
for how to clone and mirror all data and code used for this inbox