24.06.2024 01:59, Jelte Fennema-Nio wrote:
On Sat, 22 Jun 2024 at 17:00, Alexander Lakhin <exclus...@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
