Received: from malur.postgresql.org ([217.196.149.56]) by arkaria.postgresql.org with esmtps (TLS1.3) tls TLS_ECDHE_RSA_WITH_AES_256_GCM_SHA384 (Exim 4.94.2) (envelope-from ) id 1sk7By-007o1u-38 for pgsql-hackers@arkaria.postgresql.org; Fri, 30 Aug 2024 19:21:54 +0000 Received: from localhost ([127.0.0.1] helo=malur.postgresql.org) by malur.postgresql.org with esmtp (Exim 4.94.2) (envelope-from ) id 1sk7Bu-009KsO-IS for pgsql-hackers@arkaria.postgresql.org; Fri, 30 Aug 2024 19:21:51 +0000 Received: from magus.postgresql.org ([2a02:c0:301:0:ffff::29]) by malur.postgresql.org with esmtps (TLS1.3) tls TLS_ECDHE_RSA_WITH_AES_256_GCM_SHA384 (Exim 4.94.2) (envelope-from ) id 1sk7Bu-009KsG-7N for pgsql-hackers@lists.postgresql.org; Fri, 30 Aug 2024 19:21:50 +0000 Received: from sss.pgh.pa.us ([68.162.161.243]) by magus.postgresql.org with esmtps (TLS1.3) tls TLS_ECDHE_RSA_WITH_AES_256_GCM_SHA384 (Exim 4.94.2) (envelope-from ) id 1sk7Bm-002IFZ-7c for pgsql-hackers@lists.postgresql.org; Fri, 30 Aug 2024 19:21:49 +0000 Received: from sss1.sss.pgh.pa.us (localhost [127.0.0.1]) by sss.pgh.pa.us (8.15.2/8.15.2) with ESMTP id 47UJLPYh578935; Fri, 30 Aug 2024 15:21:25 -0400 From: Tom Lane To: Alexander Lakhin cc: Alvaro Herrera , Jelte Fennema-Nio , Noah Misch , Jacob Champion , Denis Laxalde , vignesh C , Thomas Munro , Greg Stark , "Gregory Stark (as CFM)" , Jelte Fennema , Daniel Gustafsson , Peter Eisentraut , Andres Freund , Justin Pryzby , Robert Haas , pgsql-hackers@lists.postgresql.org, Etsuro Fujita Subject: Re: [EXTERNAL] Re: Add non-blocking version of PQcancel In-reply-to: <5ea25e4d-1ee2-b9bf-7806-119ffa658826@gmail.com> References: <202407221126.vyw5q3h4nyoh@alvherre.pgsql> <5ea25e4d-1ee2-b9bf-7806-119ffa658826@gmail.com> Comments: In-reply-to Alexander Lakhin message dated "Wed, 28 Aug 2024 21:00:00 +0300" MIME-Version: 1.0 Content-Type: multipart/mixed; boundary="----- =_aaaaaaaaaa0" Content-ID: <578653.1725045514.0@sss.pgh.pa.us> Date: Fri, 30 Aug 2024 15:21:25 -0400 Message-ID: <578934.1725045685@sss.pgh.pa.us> List-Id: List-Help: List-Subscribe: List-Post: List-Owner: List-Archive: Archived-At: Precedence: bulk ------- =_aaaaaaaaaa0 Content-Type: text/plain; charset="UTF-8" Content-ID: <578653.1725045514.1@sss.pgh.pa.us> Content-Transfer-Encoding: quoted-printable Alexander Lakhin 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/expecte= d/query_cancel.out /home/bf/bf-build/mylodon/HEAD/pgsql.build/testrun/post= gres_fdw/regress/results/query_cancel.out --- /home/bf/bf-build/mylodon/HEAD/pgsql/contrib/postgres_fdw/expected/que= ry_cancel.out 2024-07-22 11:09:50.638133878 +0000 +++ /home/bf/bf-build/mylodon/HEAD/pgsql.build/testrun/postgres_fdw/regres= s/results/query_cancel.out 2024-08-30 06:28:01.971083945 +0000 @@ -17,4 +17,5 @@ SET LOCAL statement_timeout =3D '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_cance= l ERROR: canceling statement due to statement timeout 2024-08-30 06:27:31.926 UTC client backend[3668381] pg_regress/query_cance= l 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_cance= l 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=3Dmylodon&dt=3D= 2024-08-30%2006%3A25%3A46 ------- =_aaaaaaaaaa0 Content-Type: text/plain; name="cancel-request-failures.txt"; charset="us-ascii" Content-ID: <578653.1725045514.2@sss.pgh.pa.us> Content-Description: cancel-request-failures.txt Content-Transfer-Encoding: quoted-printable sysname | branch | snapshot | stage = | = l = = ---------------+---------------+---------------------+--------------------= --------+-----------------------------------------------------------------= --------------------------------------------------------------------------= -- flaviventris | HEAD | 2024-04-02 23:58:01 | postgres_fdwInstall= Check-C | +WARNING: could not get result of cancel request due to timeout calliphoridae | HEAD | 2024-04-11 01:54:17 | postgres_fdwInstall= Check-C | +WARNING: could not get result of cancel request due to timeout kestrel | REL_17_STABLE | 2024-07-13 04:15:25 | postgres_fdwInstall= Check-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_fdwInstall= Check-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/p= ostgres_fdw WARNING: could not get result of cancel request due to timeou= t calliphoridae | REL_17_STABLE | 2024-07-16 22:45:08 | postgres_fdwInstall= Check-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/q= uery_cancel WARNING: could not get result of cancel request due to timeou= t mylodon | HEAD | 2024-04-24 07:12:22 | postgres_fdwInstall= Check-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/p= ostgres_fdw WARNING: could not get result of cancel request due to timeou= t 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/q= uery_cancel WARNING: could not get result of cancel request due to timeou= t 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/q= uery_cancel WARNING: could not get result of cancel request due to timeou= t 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/q= uery_cancel WARNING: could not get result of cancel request due to timeou= t 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/p= ostgres_fdw WARNING: could not get result of cancel request due to timeou= t 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/p= ostgres_fdw WARNING: could not get result of cancel request due to timeou= t 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/p= ostgres_fdw WARNING: could not get result of cancel request due to timeou= t adder | HEAD | 2024-08-29 10:42:09 | postgres_fdwInstall= Check-C | +WARNING: could not get result of cancel request due to timeout olingo | HEAD | 2024-06-20 09:52:04 | postgres_fdwInstall= Check-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/po= stgres_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/q= uery_cancel WARNING: could not get result of cancel request due to timeou= t 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 WA= RNING: could not get result of cancel request due to timeout (34 rows) ------- =_aaaaaaaaaa0--