Re: BUG #19692: Generic partition-pruning plan delays statement_timeout cancellation

PG Bug reporting form <noreply(at)postgresql(dot)org> wrote:
> Generating a fresh generic plan for a range-partitioned table with 18
> partition keys and two parameterized lower-bound clauses per key delays
> statement_timeout cancellation. With statement_timeout set to 50 ms,
> cancellation was not reported until 315-346 ms after the statement began.

Reproduced on master (e1d8f81d496), built with --enable-debug
--enable-cassert, so the absolute numbers here are larger than they would
be on a production build:

psql reports the error after 281-304 ms, five runs, statement_timeout 50ms.

> Inference: this predicate shape appears to generate a Cartesian expansion of
> partition-pruning clause prefixes without sufficiently frequent interrupt
> checks.

That is where the time goes, and there are no interrupt checks at all:
partprune.c has no CHECK_FOR_INTERRUPTS(). Instrumenting
gen_partprune_steps() to log elapsed time against the statement start on
the case above:

gen_partprune_steps entered at 0.383 ms
first recursive call at 0.402 ms
gen_partprune_steps returned at 130.026 ms, after 524250 recursive calls

get_steps_using_prefix_recurse() emits one pruning step per combination of
the clauses matched to each partition key, so with 18 keys and 2 clauses
per key the recursion runs ~2^19 times. None of those calls services a
pending cancellation.

The attached patch adds a CHECK_FOR_INTERRUPTS() to that recursion, for the
same reason commit 35313832248 added one to the planner in 2005 ("you can't
Query-Cancel a long planner run, because no part of the planner did
CHECK_FOR_INTERRUPTS()").

It is worth separating two things that the client-side number adds
together. Timing the server itself, with log_statement=all, and taking the
distance between the "statement:" log line and the timeout error:

server raises the error at
master 135 ms
master + patch 50 ms (statement_timeout = 50 ms)

So with the patch the backend honors the deadline. psql still reports
115 ms rather than 50 ms, but that remaining time elapses *after* the error
is raised, while the transaction aborts and the memory for the steps built
so far is released; it is not planner work that fails to check for
interrupts, and no additional CHECK_FOR_INTERRUPTS() will shorten it. I
have not looked into whether that part is worth doing anything about.

Adding a check to the loop in get_matching_partitions() as well made no
measurable difference on this case, because with the patch the statement is
already cancelled during step generation and never reaches it.

Tests: test_setup, create_index, partition_prune, partition_join and
inherit pass with the patch.

Regards,
Manu