Re: BUG #16035: STATEMENT_TIMEOUT not working when we have single quote usage inside CTE which is used in inner sql

[ cc'ing Tatsuo and Andres, as authors of the relevant commit ]

PG Bug reporting form <noreply(at)postgresql(dot)org> writes:
> PostgreSQL version: 10.8

> Below sql should get killed after 1 second but looks like it is running for
> 5 seconds.

> SET STATEMENT_TIMEOUT = '1s';SELECT * FROM ( WITH test AS ( SELECT
> pg_sleep(5), 'Billy' as emp_name ) SELECT 1 FROM test ) AS sub;

I can reproduce this in v10, but only if I submit the two statements as
a single query string:

psql (10.10)
Type "help" for help.

regression=# \timing
Timing is on.
regression=# SET STATEMENT_TIMEOUT = '1s'\;SELECT * FROM ( WITH test AS ( SELECT
pg_sleep(5), 'Billy' as emp_name ) SELECT 1 FROM test ) AS sub;
?column?
----------
1
(1 row)

Time: 5007.648 ms (00:05.008)

If they're sent as separate statements then it works as expected:

psql (10.10)
Type "help" for help.

regression=# \timing
Timing is on.
regression=# SET STATEMENT_TIMEOUT = '1s';SELECT * FROM ( WITH test AS ( SELECT
pg_sleep(5), 'Billy' as emp_name ) SELECT 1 FROM test ) AS sub;
SET
Time: 0.635 ms
ERROR: canceling statement due to statement timeout
Time: 1000.707 ms (00:01.001)

In v11 and up it works the same either way:

psql (11.5)
Type "help" for help.

regression=# \timing
Timing is on.
regression=# SET STATEMENT_TIMEOUT = '1s'\;SELECT * FROM ( WITH test AS ( SELECT
pg_sleep(5), 'Billy' as emp_name ) SELECT 1 FROM test ) AS sub;
ERROR: canceling statement due to statement timeout
Time: 1001.187 ms (00:01.001)

... or does it?

regression=# SET STATEMENT_TIMEOUT = '10s';
SET
Time: 0.462 ms
regression=# SET STATEMENT_TIMEOUT = '1s'\;SELECT * FROM ( WITH test AS ( SELECT
pg_sleep(5), 'Billy' as emp_name ) SELECT 1 FROM test ) AS sub;
?column?
----------
1
(1 row)

Time: 5005.946 ms (00:05.006)

The v10-and-below behavior is consistent with the idea that the initial
value of statement_timeout is applied across the whole multi-statement
query string. Since you didn't set statement_timeout till after the query
string started, the new value doesn't apply until the next submitted
command.

The newer behavior is simply not very consistent. If you had a prevailing
statement_timeout then it continues to apply; but if you didn't, and you
set one, then it's armed immediately and applies to the rest of the query
string (as a whole, not per-statement).

The change in behavior seems to be a consequence of f8e5f156b,
which made start_xact_command do this unconditionally:

+ /*
+ * Start statement timeout if necessary. Note that this'll intentionally
+ * not reset the clock on an already started timeout, to avoid the timing
+ * overhead when start_xact_command() is invoked repeatedly, without an
+ * interceding finish_xact_command() (e.g. parse/bind/execute). If that's
+ * not desired, the timeout has to be disabled explicitly.
+ */
+ enable_statement_timeout();

The commit message claims that this only affected extended query
protocol, but that's obviously false, because start_xact_command
is also called by exec_simple_query.

Not sure what if anything we should do about this. The semantics
of SET within a multi-statement string have always been pretty
squishy: most variables will affect the remaining statements, but
a few won't. But I don't like the fact that simple query's timeout
behavior can no longer be categorized as either of those alternatives.
"It affects the later statements, except when it doesn't" seems
unsatisfactory.

tl;dr: I do not think this is buggy in v10. But arguably there's
a bug in later branches, and they need to go back to behaving
like v10.

regards, tom lane