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

Previous Topic Next Topic
 
classic Classic list List threaded Threaded
4 messages Options
Reply | Threaded
Open this post in threaded view
|

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

PG Bug reporting form
The following bug has been logged on the website:

Bug reference:      16035
Logged by:          Raj Mohite
Email address:      [hidden email]
PostgreSQL version: 10.8
Operating system:   Windows 10
Description:        

I have created a simple sql where I have added STATEMENT_TIMEOUT = 1 seconds
and added explicit delay(pg_sleep(5) ) of 5 seconds inside CTE. 

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;

Note: If we remove the quoted string 'Billy' AS emp_name  from above sql
then proper timeout is getting applied. If we keep quoted string -- 'Billy'
AS emp_name in the comment then also it doesn't work.

Solution: We are still finding the root cause for the above behavior but I
found that if we will put the SET STATEMENT_TIMEOUT before and after the sql
then it working fine.

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

Above example will timeout after 3 seconds i.e. it will consider the 1st
timeout value.

Can you please help us to know why STATEMENT_TIMEOUT is not working in first
example?

Reply | Threaded
Open this post in threaded view
|

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

Tom Lane-2
[ cc'ing Tatsuo and Andres, as authors of the relevant commit ]

PG Bug reporting form <[hidden email]> 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


Reply | Threaded
Open this post in threaded view
|

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

Tatsuo Ishii-3
> [ cc'ing Tatsuo and Andres, as authors of the relevant commit ]
>
> PG Bug reporting form <[hidden email]> 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


Reply | Threaded
Open this post in threaded view
|

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

Tatsuo Ishii-3
>> 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)

diff --git a/src/backend/tcop/postgres.c b/src/backend/tcop/postgres.c
index e8d8e6f828..0ba6fa9d5e 100644
--- a/src/backend/tcop/postgres.c
+++ b/src/backend/tcop/postgres.c
@@ -4701,7 +4701,8 @@ enable_statement_timeout(void)
 
  if (StatementTimeout > 0)
  {
- if (!stmt_timeout_active)
+ if (!doing_extended_query_message ||
+ (!stmt_timeout_active && doing_extended_query_message))
  {
  enable_timeout_after(STATEMENT_TIMEOUT, StatementTimeout);
  stmt_timeout_active = true;

\timing
-- 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;

SET STATEMENT_TIMEOUT = '10s';
-- 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;

-- 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;
SHOW STATEMENT_TIMEOUT;

-- 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;