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@postgresql.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

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

PG Bug reporting form <noreply@postgresql.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.

I understand the original reporter's complain. Also I understand Tom's
complain to v11's behavior. I will look into the v11 (and above) code.

Best regards,
--
Tatsuo Ishii
SRA OSS, Inc. Japan
English: http://www.sraoss.co.jp/index_en.php
Japanese:http://www.sraoss.co.jp

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.

I understand the original reporter's complain. Also I understand Tom's
complain to v11's behavior. I will look into the v11 (and above) code.

I admit v11's current behavior is inconstant, but I am not sue going
to back V10's behavior is a good idea.

With attached patch (against master), SET STATEMENT_TIMEOUT
immediately affects to subsequent commands in the multi statement. I
think this is not only more intuitive than v10's behavior but it meets
the original reporter's expectation.

SET STATEMENT_TIMEOUT = '10s';
SET
Time: 0.418 ms
-- SELECT timeout in 1 second.
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.107 ms (00:01.001)

Here are results of test cases attached (statement_timeout.sql).

\timing
Timing is on.
-- SELECT timeout in 1 second.
SET STATEMENT_TIMEOUT = '1s'\;SELECT * FROM ( WITH test AS ( SELECT pg_sleep(5), 'Billy' as emp_name ) SELECT 1 FROM test ) AS sub;
psql:/home/t-ishii/tmp/statement_timeout.sql:3: ERROR: canceling statement due to statement timeout
Time: 1001.138 ms (00:01.001)
SET STATEMENT_TIMEOUT = '10s';
SET
Time: 0.434 ms
-- SELECT timeout in 1 second.
SET STATEMENT_TIMEOUT = '1s'\;SELECT * FROM ( WITH test AS ( SELECT pg_sleep(5), 'Billy' as emp_name ) SELECT 1 FROM test ) AS sub;
psql:/home/t-ishii/tmp/statement_timeout.sql:7: ERROR: canceling statement due to statement timeout
Time: 1000.978 ms (00:01.001)
-- This time SELECT succeeds and STATEMENT_TIMEOUT is set to 8 secinds.
SET STATEMENT_TIMEOUT = '8s'\;SELECT * FROM ( WITH test AS ( SELECT pg_sleep(5), 'Billy' as emp_name ) SELECT 1 FROM test ) AS sub;
?column?
----------
1
(1 row)

Time: 5004.886 ms (00:05.005)
SHOW STATEMENT_TIMEOUT;
statement_timeout
-------------------
8s
(1 row)

Time: 0.433 ms
-- Following SELECT succeeds because now statement_timeout value is 8 seconds..
SELECT * FROM ( WITH test AS ( SELECT pg_sleep(5), 'Billy' as emp_name ) SELECT 1 FROM test ) AS sub;
?column?
----------
1
(1 row)

Time: 5006.196 ms (00:05.006)

If there's no objection, I would like to commit/push the diff.

Tatsuo Ishii <ishii@sraoss.co.jp> writes:

If there's no objection, I would like to commit/push the diff.

I'd like to look at the patch, but I just got back from pgconf.eu
and haven't had time yet.

regards, tom lane

Tatsuo Ishii <ishii@sraoss.co.jp> writes:

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.

I understand the original reporter's complain. Also I understand Tom's
complain to v11's behavior. I will look into the v11 (and above) code.

I admit v11's current behavior is inconstant, but I am not sue going
to back V10's behavior is a good idea.
With attached patch (against master), SET STATEMENT_TIMEOUT
immediately affects to subsequent commands in the multi statement. I
think this is not only more intuitive than v10's behavior but it meets
the original reporter's expectation.

Hm. So, okay, that is a nicer API probably, but note that it also
has the effect that the timeout starts over again for each statement
in the string, while before it applied to the string as a whole.
Are we okay with that change? (I've not yet looked to see if it's
documented anywhere that it works that way...) It's kind of tossing
some of the optimization intended by f8e5f156b overboard, since when
a timeout is active we'll be doing timeout calculations for each
statement in the string.

Anyway, granting that we want the definitional change, I still
don't like anything about this patch. The proposed test

+        if (!doing_extended_query_message ||
+            (!stmt_timeout_active && doing_extended_query_message))

is unreadably complicated and repetitive, and it's undocumented,
and it makes timeout handling work quite differently in the simple
and extended query paths, and it will cause excess timeout calculations
(over and above the newly-necessary ones) because it will force a new
timeout calculation for each start_xact_command call in the simple query
path (yes, we do more than one of those per statement in common cases).
Plus it makes the semantics of stmt_timeout_active rather unclear.

I think if we want to do this, the way to do it is to add another
disable_statement_timeout call while finishing up a non-last query
in exec_simple_query, as per 0001 below. That adds no extra overhead
unless we have a multi-statement string, and it is much more parallel
to the way things are done for extended protocol.

However ... as I was looking at this, I realized that I didn't like
anything about commit f8e5f156b either. It introduces private state
in postgres.c that has to be kept in sync with state in timeout.c.
We already found one bug in that (cf be42015fc), and I have little
faith that there aren't others, and no faith at all that we won't
introduce more later. The right way to manage that, I think, is to
extend timeout.c to allow inquiring whether the timeout is active,
as per 0002 below, so that timeout.c's state is the single source of
truth about this. Maintaining the extra state needed to make this
cheap allows some other small simplifications/speedups, too, mainly
that we can skip useless searches of the active_timeouts[] array.

Not sure what I think about back-patching this. We probably can't
back-patch 0001; that's enough of a behavioral change that the cure
seems worse than the disease. I'm tempted though to argue that we
should back-patch 0002, on the grounds that it prevents possible
bugs and should save a few cycles too.

regards, tom lane

I wrote:

Tatsuo Ishii <ishii@sraoss.co.jp> writes:

With attached patch (against master), SET STATEMENT_TIMEOUT
immediately affects to subsequent commands in the multi statement. I
think this is not only more intuitive than v10's behavior but it meets
the original reporter's expectation.

Hm. So, okay, that is a nicer API probably, but note that it also
has the effect that the timeout starts over again for each statement
in the string, while before it applied to the string as a whole.
Are we okay with that change? (I've not yet looked to see if it's
documented anywhere that it works that way...) It's kind of tossing
some of the optimization intended by f8e5f156b overboard, since when
a timeout is active we'll be doing timeout calculations for each
statement in the string.

I looked around, and as far as I can tell, there is no detail at all
about this in our user-facing docs. I think we should apply a doc
patch more or less like the attached. This fails to provide a complete
spec of what the behavior used to be, but I don't much care to try to
document that 100% exactly.

Anyone have an objection to pushing ahead with this for HEAD only?

regards, tom lane