From: Tom Lane <tgl@sss.pgh.pa.us>
To: rmohite@xento.com
cc: pgsql-bugs@lists.postgresql.org, Tatsuo Ishii <ishii@sraoss.co.jp>,
        Andres Freund <andres@anarazel.de>
Subject: Re: BUG #16035: STATEMENT_TIMEOUT not working when we have single
 quote usage inside CTE which is used in inner sql
In-reply-to: <16035-456e6e69ebfd4374@postgresql.org>
References: <16035-456e6e69ebfd4374@postgresql.org>
Comments: In-reply-to PG Bug reporting form <noreply@postgresql.org>
	message dated "Thu, 03 Oct 2019 06:38:33 -0000"
MIME-Version: 1.0
Content-Type: text/plain; charset="us-ascii"
Content-ID: <32453.1570114306.1@sss.pgh.pa.us>
Content-Transfer-Encoding: quoted-printable
Date: Thu, 03 Oct 2019 10:51:46 -0400
Message-ID: <32454.1570114306@sss.pgh.pa.us>
Precedence: bulk

[ 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 =3D '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=3D# \timing
Timing is on.
regression=3D# SET STATEMENT_TIMEOUT =3D '1s'\;SELECT * FROM ( WITH test A=
S ( 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=3D# \timing
Timing is on.
regression=3D# SET STATEMENT_TIMEOUT =3D '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=3D# \timing
Timing is on.
regression=3D# SET STATEMENT_TIMEOUT =3D '1s'\;SELECT * FROM ( WITH test A=
S ( 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=3D# SET STATEMENT_TIMEOUT =3D '10s';
SET
Time: 0.462 ms
regression=3D# SET STATEMENT_TIMEOUT =3D '1s'\;SELECT * FROM ( WITH test A=
S ( 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 intentiona=
lly
+    * not reset the clock on an already started timeout, to avoid the tim=
ing
+    * overhead when start_xact_command() is invoked repeatedly, without a=
n
+    * interceding finish_xact_command() (e.g. parse/bind/execute).  If th=
at'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