Re: [EXTERNAL] Re: Add non-blocking version of PQcancel - Mailing list pgsql-hackers

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
statementtimeout 
2024-08-30 06:27:31.926 UTC client backend[3668381] pg_regress/query_cancel STATEMENT:  select count(*) from ft1 CROSS
JOINft2 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
requestdue 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
cancelrequest due to timeout 
 calliphoridae | HEAD          | 2024-04-11 01:54:17 | postgres_fdwInstallCheck-C | +WARNING:  could not get result of
cancelrequest due to timeout 
 kestrel       | REL_17_STABLE | 2024-07-13 04:15:25 | postgres_fdwInstallCheck-C | +WARNING:  could not get result of
cancelrequest 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
cancelrequest due to timeout 
 mylodon       | HEAD          | 2024-07-26 13:15:09 | postgres_fdwInstallCheck-C | +WARNING:  could not get result of
cancelrequest due to timeout 
 adder         | HEAD          | 2024-07-02 00:24:10 | postgres_fdwCheck          | +WARNING:  could not get result of
cancelrequest 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
cancelrequest due to timeout 
 mylodon       | HEAD          | 2024-08-09 05:25:24 | postgres_fdwCheck          | +WARNING:  could not get result of
cancelrequest 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
cancelrequest due to timeout 
 skink         | HEAD          | 2024-07-20 20:57:01 | postgres_fdwCheck          | +WARNING:  could not get result of
cancelrequest 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
cancelrequest 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
cancelrequest 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
cancelrequest 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
cancelrequest 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
cancelrequest 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
cancelrequest 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
cancelrequest due to timeout 
 olingo        | HEAD          | 2024-06-20 09:52:04 | postgres_fdwInstallCheck-C | +WARNING:  could not get result of
cancelrequest due to timeout 
 francolin     | HEAD          | 2024-07-09 19:02:27 | postgres_fdwCheck          | +WARNING:  could not get result of
cancelrequest 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
cancelrequest 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
cancelrequest 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)