pg.ddx.io  pgsql-hackers@postgresql.org mailing list archive  

help / color / mirror / Atom feed
From: Alexander Lakhin <exclusion@gmail.com>
To: Jelte Fennema-Nio <postgres@jeltef.nl>
Cc: Noah Misch <noah@leadboat.com>
Cc: Alvaro Herrera <alvherre@alvh.no-ip.org>
Cc: Tom Lane <tgl@sss.pgh.pa.us>
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: Tue, 25 Jun 2024 08:00:00 +0300
Message-ID: <ecd2358c-2128-877b-c680-23b377394285@gmail.com> (raw)
In-Reply-To: <CAGECzQSBp=sCcMCy1txig7cV0VX9hDDb1UdZt3zpDpZe2X2K-Q@mail.gmail.com>
References: <202403281753.ku5k2jvaw5fo@alvherre.pgsql>
	<3643677.1711648979@sss.pgh.pa.us>
	<CAGECzQRqxwcaePLd3MmpZ380CRiCrzPAwmGXsUY9jR5EWf5DLg@mail.gmail.com>
	<20240329221724.03@rfd.leadboat.com>
	<4db099c8-4a52-3cc4-e970-14539a319466@gmail.com>
	<CAGECzQSBp=sCcMCy1txig7cV0VX9hDDb1UdZt3zpDpZe2X2K-Q@mail.gmail.com>

24.06.2024 01:59, Jelte Fennema-Nio wrote:
> On Sat, 22 Jun 2024 at 17:00, Alexander Lakhin <exclusion@gmail.com> wrote:
>> @@ -2775,6 +2775,7 @@
>>    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;
> As you describe it, this problem occurs when the cancel request is
> processed by the foreign server, before the query is actually
> received. And postgres then (rightly) ignores the cancel request. I'm
> not sure if the existing test is easily changeable to fix this. The
> only thing that I can imagine works in practice is increasing the
> statement_timeout, e.g. to 100ms.

I'd just like to add that that one original query assumes several "remote"
queries (see the attached excerpt from postmaster.log with verbose logging
enabled).

Best regards,
Alexander
2024-06-24 07:25:33.539 UTC [47957:426] pg_regress/postgres_fdw LOG:  statement: SET LOCAL statement_timeout = '10ms';
2024-06-24 07:25:33.540 UTC [47957:427] pg_regress/postgres_fdw LOG:  statement: select count(*) from ft1 CROSS JOIN ft2 CROSS JOIN ft4 CROSS JOIN ft5;
2024-06-24 07:25:33.541 UTC [47957:428] pg_regress/postgres_fdw DEBUG:  starting remote transaction on connection 0x5190000f1480
2024-06-24 07:25:33.542 UTC [48390:203] pg_regress LOG:  statement: START TRANSACTION ISOLATION LEVEL REPEATABLE READ
2024-06-24 07:25:33.542 UTC [48390:204] pg_regress LOG:  statement: EXPLAIN SELECT NULL FROM "S 1"."T 1"
2024-06-24 07:25:33.543 UTC [48390:205] pg_regress LOG:  statement: EXPLAIN SELECT NULL FROM ("S 1"."T 1" r1 INNER JOIN "S 1"."T 1" r2 ON (TRUE))
2024-06-24 07:25:33.544 UTC [48390:206] pg_regress LOG:  statement: EXPLAIN SELECT NULL FROM ("S 1"."T 1" r2 INNER JOIN "S 1"."T 3" r4 ON (TRUE))
2024-06-24 07:25:33.545 UTC [48390:207] pg_regress LOG:  statement: EXPLAIN SELECT NULL FROM ("S 1"."T 1" r2 INNER JOIN "S 1"."T 4" r6 ON (TRUE))
2024-06-24 07:25:33.546 UTC [48390:208] pg_regress LOG:  statement: EXPLAIN SELECT NULL FROM (("S 1"."T 1" r1 INNER JOIN "S 1"."T 1" r2 ON (TRUE)) INNER JOIN "S 1"."T 3" r4 ON (TRUE))
2024-06-24 07:25:33.548 UTC [48390:209] pg_regress LOG:  statement: EXPLAIN SELECT NULL FROM (("S 1"."T 1" r1 INNER JOIN "S 1"."T 1" r2 ON (TRUE)) INNER JOIN "S 1"."T 4" r6 ON (TRUE))
2024-06-24 07:25:33.549 UTC [48390:210] pg_regress LOG:  statement: EXPLAIN SELECT NULL FROM (("S 1"."T 1" r2 INNER JOIN "S 1"."T 3" r4 ON (TRUE)) INNER JOIN "S 1"."T 4" r6 ON (TRUE))
2024-06-24 07:25:33.550 UTC [48390:211] pg_regress LOG:  statement: EXPLAIN SELECT NULL FROM ((("S 1"."T 1" r1 INNER JOIN "S 1"."T 1" r2 ON (TRUE)) INNER JOIN "S 1"."T 3" r4 ON (TRUE)) INNER JOIN "S 1"."T 4" r6 ON (TRUE))
2024-06-24 07:25:33.551 UTC [48390:212] pg_regress LOG:  statement: EXPLAIN SELECT count(*) FROM ((("S 1"."T 1" r1 INNER JOIN "S 1"."T 1" r2 ON (TRUE)) INNER JOIN "S 1"."T 3" r4 ON (TRUE)) INNER JOIN "S 1"."T 4" r6 ON (TRUE))
2024-06-24 07:25:33.553 UTC [48390:213] pg_regress DEBUG:  parse <unnamed>: DECLARE c1 CURSOR FOR
        SELECT count(*) FROM ((("S 1"."T 1" r1 INNER JOIN "S 1"."T 1" r2 ON (TRUE)) INNER JOIN "S 1"."T 3" r4 ON (TRUE)) INNER JOIN "S 1"."T 4" r6 ON (TRUE))
2024-06-24 07:25:33.553 UTC [48390:214] pg_regress DEBUG:  bind <unnamed> to <unnamed>
2024-06-24 07:25:33.553 UTC [48390:215] pg_regress LOG:  execute <unnamed>: DECLARE c1 CURSOR FOR
        SELECT count(*) FROM ((("S 1"."T 1" r1 INNER JOIN "S 1"."T 1" r2 ON (TRUE)) INNER JOIN "S 1"."T 3" r4 ON (TRUE)) INNER JOIN "S 1"."T 4" r6 ON (TRUE))
2024-06-24 07:25:33.555 UTC [47957:429] pg_regress/postgres_fdw ERROR:  canceling statement due to statement timeout
2024-06-24 07:25:33.555 UTC [47957:430] pg_regress/postgres_fdw DEBUG:  closing remote transaction on connection 0x5190000f1480
2024-06-24 07:25:33.561 UTC [48465:1] [unknown] LOG:  connection received: host=[local]
2024-06-24 07:25:33.561 UTC [48465:2] [unknown] DEBUG:  processing cancel request: sending SIGINT to process 48390
2024-06-24 07:25:33.561 UTC [48465:3] [unknown] DEBUG:  shmem_exit(0): 0 before_shmem_exit callbacks to make
2024-06-24 07:25:33.561 UTC [48465:4] [unknown] DEBUG:  shmem_exit(0): 0 on_shmem_exit callbacks to make
2024-06-24 07:25:33.561 UTC [48465:5] [unknown] DEBUG:  proc_exit(0): 1 callbacks to make
2024-06-24 07:25:33.561 UTC [48465:6] [unknown] DEBUG:  exit(0)
2024-06-24 07:25:33.561 UTC [48465:7] [unknown] DEBUG:  shmem_exit(-1): 0 before_shmem_exit callbacks to make
2024-06-24 07:25:33.561 UTC [48465:8] [unknown] DEBUG:  shmem_exit(-1): 0 on_shmem_exit callbacks to make
2024-06-24 07:25:33.561 UTC [48465:9] [unknown] DEBUG:  proc_exit(-1): 0 callbacks to make
2024-06-24 07:25:33.635 UTC [48390:216] pg_regress LOG:  statement: FETCH 100 FROM c1
...
2024-06-24 07:26:09.041 UTC [47957:431] pg_regress/postgres_fdw WARNING:  could not get result of cancel request due to timeout
2024-06-24 07:26:09.041 UTC [47957:432] pg_regress/postgres_fdw DEBUG:  discarding connection 0x5190000f1480


Attachments:

  [text/plain] postmaster.log.txt (4.0K, ../ecd2358c-2128-877b-c680-23b377394285@gmail.com/2-postmaster.log.txt)
  download | inline:
2024-06-24 07:25:33.539 UTC [47957:426] pg_regress/postgres_fdw LOG:  statement: SET LOCAL statement_timeout = '10ms';
2024-06-24 07:25:33.540 UTC [47957:427] pg_regress/postgres_fdw LOG:  statement: select count(*) from ft1 CROSS JOIN ft2 CROSS JOIN ft4 CROSS JOIN ft5;
2024-06-24 07:25:33.541 UTC [47957:428] pg_regress/postgres_fdw DEBUG:  starting remote transaction on connection 0x5190000f1480
2024-06-24 07:25:33.542 UTC [48390:203] pg_regress LOG:  statement: START TRANSACTION ISOLATION LEVEL REPEATABLE READ
2024-06-24 07:25:33.542 UTC [48390:204] pg_regress LOG:  statement: EXPLAIN SELECT NULL FROM "S 1"."T 1"
2024-06-24 07:25:33.543 UTC [48390:205] pg_regress LOG:  statement: EXPLAIN SELECT NULL FROM ("S 1"."T 1" r1 INNER JOIN "S 1"."T 1" r2 ON (TRUE))
2024-06-24 07:25:33.544 UTC [48390:206] pg_regress LOG:  statement: EXPLAIN SELECT NULL FROM ("S 1"."T 1" r2 INNER JOIN "S 1"."T 3" r4 ON (TRUE))
2024-06-24 07:25:33.545 UTC [48390:207] pg_regress LOG:  statement: EXPLAIN SELECT NULL FROM ("S 1"."T 1" r2 INNER JOIN "S 1"."T 4" r6 ON (TRUE))
2024-06-24 07:25:33.546 UTC [48390:208] pg_regress LOG:  statement: EXPLAIN SELECT NULL FROM (("S 1"."T 1" r1 INNER JOIN "S 1"."T 1" r2 ON (TRUE)) INNER JOIN "S 1"."T 3" r4 ON (TRUE))
2024-06-24 07:25:33.548 UTC [48390:209] pg_regress LOG:  statement: EXPLAIN SELECT NULL FROM (("S 1"."T 1" r1 INNER JOIN "S 1"."T 1" r2 ON (TRUE)) INNER JOIN "S 1"."T 4" r6 ON (TRUE))
2024-06-24 07:25:33.549 UTC [48390:210] pg_regress LOG:  statement: EXPLAIN SELECT NULL FROM (("S 1"."T 1" r2 INNER JOIN "S 1"."T 3" r4 ON (TRUE)) INNER JOIN "S 1"."T 4" r6 ON (TRUE))
2024-06-24 07:25:33.550 UTC [48390:211] pg_regress LOG:  statement: EXPLAIN SELECT NULL FROM ((("S 1"."T 1" r1 INNER JOIN "S 1"."T 1" r2 ON (TRUE)) INNER JOIN "S 1"."T 3" r4 ON (TRUE)) INNER JOIN "S 1"."T 4" r6 ON (TRUE))
2024-06-24 07:25:33.551 UTC [48390:212] pg_regress LOG:  statement: EXPLAIN SELECT count(*) FROM ((("S 1"."T 1" r1 INNER JOIN "S 1"."T 1" r2 ON (TRUE)) INNER JOIN "S 1"."T 3" r4 ON (TRUE)) INNER JOIN "S 1"."T 4" r6 ON (TRUE))
2024-06-24 07:25:33.553 UTC [48390:213] pg_regress DEBUG:  parse <unnamed>: DECLARE c1 CURSOR FOR
        SELECT count(*) FROM ((("S 1"."T 1" r1 INNER JOIN "S 1"."T 1" r2 ON (TRUE)) INNER JOIN "S 1"."T 3" r4 ON (TRUE)) INNER JOIN "S 1"."T 4" r6 ON (TRUE))
2024-06-24 07:25:33.553 UTC [48390:214] pg_regress DEBUG:  bind <unnamed> to <unnamed>
2024-06-24 07:25:33.553 UTC [48390:215] pg_regress LOG:  execute <unnamed>: DECLARE c1 CURSOR FOR
        SELECT count(*) FROM ((("S 1"."T 1" r1 INNER JOIN "S 1"."T 1" r2 ON (TRUE)) INNER JOIN "S 1"."T 3" r4 ON (TRUE)) INNER JOIN "S 1"."T 4" r6 ON (TRUE))
2024-06-24 07:25:33.555 UTC [47957:429] pg_regress/postgres_fdw ERROR:  canceling statement due to statement timeout
2024-06-24 07:25:33.555 UTC [47957:430] pg_regress/postgres_fdw DEBUG:  closing remote transaction on connection 0x5190000f1480
2024-06-24 07:25:33.561 UTC [48465:1] [unknown] LOG:  connection received: host=[local]
2024-06-24 07:25:33.561 UTC [48465:2] [unknown] DEBUG:  processing cancel request: sending SIGINT to process 48390
2024-06-24 07:25:33.561 UTC [48465:3] [unknown] DEBUG:  shmem_exit(0): 0 before_shmem_exit callbacks to make
2024-06-24 07:25:33.561 UTC [48465:4] [unknown] DEBUG:  shmem_exit(0): 0 on_shmem_exit callbacks to make
2024-06-24 07:25:33.561 UTC [48465:5] [unknown] DEBUG:  proc_exit(0): 1 callbacks to make
2024-06-24 07:25:33.561 UTC [48465:6] [unknown] DEBUG:  exit(0)
2024-06-24 07:25:33.561 UTC [48465:7] [unknown] DEBUG:  shmem_exit(-1): 0 before_shmem_exit callbacks to make
2024-06-24 07:25:33.561 UTC [48465:8] [unknown] DEBUG:  shmem_exit(-1): 0 on_shmem_exit callbacks to make
2024-06-24 07:25:33.561 UTC [48465:9] [unknown] DEBUG:  proc_exit(-1): 0 callbacks to make
2024-06-24 07:25:33.635 UTC [48390:216] pg_regress LOG:  statement: FETCH 100 FROM c1
...
2024-06-24 07:26:09.041 UTC [47957:431] pg_regress/postgres_fdw WARNING:  could not get result of cancel request due to timeout
2024-06-24 07:26:09.041 UTC [47957:432] pg_regress/postgres_fdw DEBUG:  discarding connection 0x5190000f1480

view thread (146+ messages)  latest in thread

Message-ID: <ecd2358c-2128-877b-c680-23b377394285@gmail.com>
Permalink:  ../ecd2358c-2128-877b-c680-23b377394285@gmail.com/
Also on:    postgresql.org/message-id/ecd2358c-2128-877b-c680-23b377394285@gmail.com

 · 

reply
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: exclusion@gmail.com, postgres@jeltef.nl, noah@leadboat.com, alvherre@alvh.no-ip.org, tgl@sss.pgh.pa.us, 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: <ecd2358c-2128-877b-c680-23b377394285@gmail.com>

* 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