Обсуждение: [HACKERS] Statement timeout behavior in extended queries

Last year I have proposed an enhancement regarding behavior of the
statement timeout in extended queries.

https://www.postgresql.org/message-id/20160528.220442.1489791680347556026.t-ishii%40sraoss.co.jp

IMO the current behavior is counter intuitive and I would like to
change it toward PostgreSQL 10.0.

For example, suppose that the timeout is set to 4 seconds and the
first query takes 2 seconds and the second query takes 3 seconds. Then
the statement timeout is triggered if a sync message is sent to
backend after the second query.

Moreover, log_duration or log_min_duration_statement shows that each
query took 2 or 3 seconds of course, which is not very consistent with
the statement timeout IMO.

Attached patch tries to change the behavior, by checking statement
timeout against each phase of an extended query.

To test the patch, I have created a small tool called "pgproto", which
can issue arbitrary sequence of frontend/backend message, reading from a
text file.

https://github.com/tatsuo-ishii/pgproto
(to build the program, you need C compiler and libpq)

A test data is here:
----------------------------------------------------------
#
# Test case for statement timeout patch.
#
'Q'    "SET statement_timeout = '4s'"

# Receive response from backend
'Y'

# Execute statement which takes 3 seconds.
'P'    "S1"    "SELECT pg_sleep(3)"    0
'B'    ""    "S1"    0    0    0
'E'    ""    0
'C'    'S'    "S1"

# Execute statement which takes 2 seconds.
'P'    "S2"    "SELECT pg_sleep(2)"    0
'B'    ""    "S2"    0    0    0
'E'    ""    0
'C'    'S'    "S2"

# Issue Sync message
'S'

# Receive response from backend
'Y'

# Send terminate message
'X'
----------------------------------------------------------

In each row, the first column corresponds to the message type defined
in frontend/backend protocol (except 'Y', which asks pgproto to
collect responses from backend). Each column is separated with a tab
character.

To run the test:

pgproto -f data_file -p port_number -d database_name

With the attached patch, "SELECT pg_sleep(3)" and "SELECT pg_sleep(2)"
does not trigger the statement timeout as expected, while existing
code triggers the statement timeout after the sync message is sent.

Best regards,
--
Tatsuo Ishii
SRA OSS, Inc. Japan
English: http://www.sraoss.co.jp/index_en.php
Japanese:http://www.sraoss.co.jp
diff --git a/src/backend/tcop/postgres.c b/src/backend/tcop/postgres.c
index b07d6c6..e35a1dd 100644
--- a/src/backend/tcop/postgres.c
+++ b/src/backend/tcop/postgres.c
@@ -149,6 +149,11 @@ static bool doing_extended_query_message = false;static bool ignore_till_sync = false;/*
+ * Flag to keep track of whether we have started statement timeout timer.
+ */
+static bool st_timeout = false;
+
+/* * If an unnamed prepared statement exists, it's stored here. * We keep it separate from the hashtable kept by
commands/prepare.c* in order to reduce overhead for short-lived queries.
 
@@ -188,6 +193,8 @@ static bool IsTransactionStmtList(List *pstmts);static void drop_unnamed_stmt(void);static void
SigHupHandler(SIGNAL_ARGS);staticvoid log_disconnections(int code, Datum arg);
 
+static void enable_statement_timeout(void);
+static void disable_statement_timeout(void);/* ----------------------------------------------------------------
@@ -1234,6 +1241,11 @@ exec_parse_message(const char *query_string,    /* string to execute */    start_xact_command();
  /*
 
+     * Set statement timeout running, if any
+     */
+    enable_statement_timeout();
+
+    /*     * Switch to appropriate context for constructing parsetrees.     *     * We have two strategies depending
onwhether the prepared statement is
 
@@ -1521,6 +1533,11 @@ exec_bind_message(StringInfo input_message)     */    start_xact_command();
+    /*
+     * Set statement timeout running, if any
+     */
+    enable_statement_timeout();
+    /* Switch back to message context */    MemoryContextSwitchTo(MessageContext);
@@ -1937,6 +1954,11 @@ exec_execute_message(const char *portal_name, long max_rows)    start_xact_command();    /*
+     * Set statement timeout running, if any
+     */
+    enable_statement_timeout();
+
+    /*     * If we re-issue an Execute protocol request against an existing portal,     * then we are only fetching
morerows rather than completely re-executing     * the query from the start. atStart is never reset for a v3 portal, so
we
@@ -2008,6 +2030,11 @@ exec_execute_message(const char *portal_name, long max_rows)             * those that start or
enda transaction block.             */            CommandCounterIncrement();
 
+
+            /*
+             * We need to reset statement timeout if already set.
+             */
+            disable_statement_timeout();        }        /* Send appropriate CommandComplete to client */
@@ -2437,14 +2464,10 @@ start_xact_command(void)    {        StartTransactionCommand();
-        /* Set statement timeout running, if any */
-        /* NB: this mustn't be enabled until we are within an xact */
-        if (StatementTimeout > 0)
-            enable_timeout_after(STATEMENT_TIMEOUT, StatementTimeout);
-        else
-            disable_timeout(STATEMENT_TIMEOUT, false);
-        xact_started = true;
+
+        /* Set statement timeout running, if any */
+        enable_statement_timeout();    }}
@@ -2454,7 +2477,7 @@ finish_xact_command(void)    if (xact_started)    {        /* Cancel any active statement timeout
beforecommitting */
 
-        disable_timeout(STATEMENT_TIMEOUT, false);
+        disable_statement_timeout();        CommitTransactionCommand();
@@ -4502,3 +4525,51 @@ log_disconnections(int code, Datum arg)                    port->user_name, port->database_name,
port->remote_host,                 port->remote_port[0] ? " port=" : "", port->remote_port)));}
 
+
+/*
+ * Set statement timeout if any.
+ */
+static void enable_statement_timeout(void)
+{
+    if (!st_timeout)
+    {
+        if (StatementTimeout > 0)
+        {
+
+            /*
+             * Sanity check
+             */
+            if (!xact_started)
+            {
+                ereport(ERROR,
+                        (errcode(ERRCODE_INVALID_PARAMETER_VALUE),
+                         errmsg("Transaction must have been already started to set statement timeout")));
+            }
+
+            ereport(DEBUG3,
+                    (errmsg_internal("Set statement timeout")));
+
+            enable_timeout_after(STATEMENT_TIMEOUT, StatementTimeout);
+            st_timeout = true;
+        }
+        else
+            disable_timeout(STATEMENT_TIMEOUT, false);
+    }
+}
+
+/*
+ * Reset statement timeout if any.
+ */
+static void disable_statement_timeout(void)
+{
+    if (st_timeout)
+    {
+        ereport(DEBUG3,
+                    (errmsg_internal("Disable statement timeout")));
+
+        /* Cancel any active statement timeout */
+        disable_timeout(STATEMENT_TIMEOUT, false);
+
+        st_timeout = false;
+    }
+}

On Wed, Feb 22, 2017 at 11:50:44AM +0900, Tatsuo Ishii wrote:
> Last year I have proposed an enhancement regarding behavior of the
> statement timeout in extended queries.
> 
> https://www.postgresql.org/message-id/20160528.220442.1489791680347556026.t-ishii%40sraoss.co.jp
> 
> IMO the current behavior is counter intuitive and I would like to
> change it toward PostgreSQL 10.0.
> 
> For example, suppose that the timeout is set to 4 seconds and the
> first query takes 2 seconds and the second query takes 3 seconds. Then
> the statement timeout is triggered if a sync message is sent to
> backend after the second query.
> 
> Moreover, log_duration or log_min_duration_statement shows that each
> query took 2 or 3 seconds of course, which is not very consistent with
> the statement timeout IMO.
> 
> Attached patch tries to change the behavior, by checking statement
> timeout against each phase of an extended query.
> 
> To test the patch, I have created a small tool called "pgproto", which
> can issue arbitrary sequence of frontend/backend message, reading from a
> text file.
> 
> https://github.com/tatsuo-ishii/pgproto
> (to build the program, you need C compiler and libpq)

Does it seem reasonable to start making this into a regression test
and/or fuzz test for the protocol itself?

Best,
David.
-- 
David Fetter <david(at)fetter(dot)org> http://fetter.org/
Phone: +1 415 235 3778  AIM: dfetter666  Yahoo!: dfetter
Skype: davidfetter      XMPP: david(dot)fetter(at)gmail(dot)com

Remember to vote!
Consider donating to Postgres: http://www.postgresql.org/about/donate

> On Wed, Feb 22, 2017 at 11:50:44AM +0900, Tatsuo Ishii wrote:
>> Last year I have proposed an enhancement regarding behavior of the
>> statement timeout in extended queries.
>> 
>> https://www.postgresql.org/message-id/20160528.220442.1489791680347556026.t-ishii%40sraoss.co.jp
>> 
>> IMO the current behavior is counter intuitive and I would like to
>> change it toward PostgreSQL 10.0.
>> 
>> For example, suppose that the timeout is set to 4 seconds and the
>> first query takes 2 seconds and the second query takes 3 seconds. Then
>> the statement timeout is triggered if a sync message is sent to
>> backend after the second query.
>> 
>> Moreover, log_duration or log_min_duration_statement shows that each
>> query took 2 or 3 seconds of course, which is not very consistent with
>> the statement timeout IMO.
>> 
>> Attached patch tries to change the behavior, by checking statement
>> timeout against each phase of an extended query.
>> 
>> To test the patch, I have created a small tool called "pgproto", which
>> can issue arbitrary sequence of frontend/backend message, reading from a
>> text file.
>> 
>> https://github.com/tatsuo-ishii/pgproto
>> (to build the program, you need C compiler and libpq)
> 
> Does it seem reasonable to start making this into a regression test
> and/or fuzz test for the protocol itself?

I personally think the regression tests ought to include tests for
extended query protocols and pgproto could be an useful tool to
implement that. Of course if we are going for that direction, pgproto
needs to be a contrib module first.

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

Hello,


I've reviewed the patch.  My understanding is as follows.  Please correct me if I'm wrong.

* The difference is that the Execute message stops the statement_timeout timer, so that the execution of one statement
doesn'tshorten the timeout period of subsequent statements when they are run in batch followed by a single Sync
message.

* This patch is also necessary (or desirable) for the feature "Pipelining/batch mode support for libpq," which is being
developedfor PG 10.  This patch enables correct timeout handling for each statement execution in a batch.  Without this
patch,the entire batch of statements is subject to statement_timeout.  That's different from what the manual describes
aboutstatement_timeout.  statement_timeout should measure execution of each statement.
 


Below are what I found in the patch.


(1)
+static bool st_timeout = false;

I think the variable name would better be stmt_timeout_enabled or stmt_timer_started, because other existing names use
stmtto abbreviate statement, and thhis variable represents a state (see xact_started for example.)
 


(2)
+static void enable_statement_timeout(void)
+{

+static void disable_statement_timeout(void)
+{

"static void" and the remaining line should be on different lines, as other functions do.



(3)
+            /*
+             * Sanity check
+             */
+            if (!xact_started)
+            {
+                ereport(ERROR,
+                        (errcode(ERRCODE_INVALID_PARAMETER_VALUE),
+                         errmsg("Transaction must have been already started to set statement timeout")));
+            }

I think this fragment can be deleted, because enable/disable_timeout() is used only at limited places in postgres.c, so
Idon't see the chance of misuse.
 


Regards
Takayuki Tsunakawa

Thank you for reviewing my patch!

> Hello,
> 
> 
> I've reviewed the patch.  My understanding is as follows.  Please correct me if I'm wrong.
> 
> * The difference is that the Execute message stops the statement_timeout timer, 

No. Parse, bind and Execute message indivually stops and starts the
statement_timeout timer with the patch. Unless there's a lock
conflict, parse and bind will take very short time. So actually users
could only observe the timeout in execute message though.

> so that the execution of one statement doesn't shorten the timeout
> period of subsequent statements when they are run in batch followed by
> a single Sync message.

This is true. Currently multiple set of parse/bind/execute will not
trigger statement timeout until sync message is sent to
backend. Suppose statement_timeout is set to 3 seconds, combo A
(parse/bind/execute) takes 2 seconds and combo B (parse/bind/execute)
takes 2 seconds then a sync message is followed. Currently statement
timeout is fired in the run of combo B (assuming that parse and bind
take almost 0 seconds). With my patch, no statement timeout will be
fired because both combo A and combo B runs within 3 seconds.

> * This patch is also necessary (or desirable) for the feature "Pipelining/batch mode support for libpq," which is
beingdeveloped for PG 10.  This patch enables correct timeout handling for each statement execution in a batch.
Withoutthis patch, the entire batch of statements is subject to statement_timeout.  That's different from what the
manualdescribes about statement_timeout.  statement_timeout should measure execution of each statement.
 

True.

> Below are what I found in the patch.
> 
> 
> (1)
> +static bool st_timeout = false;
> 
> I think the variable name would better be stmt_timeout_enabled or stmt_timer_started, because other existing names
usestmt to abbreviate statement, and thhis variable represents a state (see xact_started for example.)
 

Agreed. Chaged to stmt_timer_started.

> (2)
> +static void enable_statement_timeout(void)
> +{
> 
> +static void disable_statement_timeout(void)
> +{
> 
> "static void" and the remaining line should be on different lines, as other functions do.

Fixed.

> (3)
> +            /*
> +             * Sanity check
> +             */
> +            if (!xact_started)
> +            {
> +                ereport(ERROR,
> +                        (errcode(ERRCODE_INVALID_PARAMETER_VALUE),
> +                         errmsg("Transaction must have been already started to set statement timeout")));
> +            }
> 
> I think this fragment can be deleted, because enable/disable_timeout() is used only at limited places in postgres.c,
soI don't see the chance of misuse.
 

I'd suggest leave it as it is. Because it might be possible that the
function is used in different place in the future. Or at least we
should document the pre-condition as a comment.

revised patch attached.
--
Tatsuo Ishii
SRA OSS, Inc. Japan
English: http://www.sraoss.co.jp/index_en.php
Japanese:http://www.sraoss.co.jp
diff --git a/src/backend/tcop/postgres.c b/src/backend/tcop/postgres.c
index a2282058..68a739e 100644
--- a/src/backend/tcop/postgres.c
+++ b/src/backend/tcop/postgres.c
@@ -149,6 +149,11 @@ static bool doing_extended_query_message = false;static bool ignore_till_sync = false;/*
+ * Flag to keep track of whether we have started statement timeout timer.
+ */
+static bool stmt_timer_started = false;
+
+/* * If an unnamed prepared statement exists, it's stored here. * We keep it separate from the hashtable kept by
commands/prepare.c* in order to reduce overhead for short-lived queries.
 
@@ -188,6 +193,8 @@ static bool IsTransactionStmtList(List *pstmts);static void drop_unnamed_stmt(void);static void
SigHupHandler(SIGNAL_ARGS);staticvoid log_disconnections(int code, Datum arg);
 
+static void enable_statement_timeout(void);
+static void disable_statement_timeout(void);/* ----------------------------------------------------------------
@@ -1239,6 +1246,11 @@ exec_parse_message(const char *query_string,    /* string to execute */    start_xact_command();
  /*
 
+     * Set statement timeout running, if any
+     */
+    enable_statement_timeout();
+
+    /*     * Switch to appropriate context for constructing parsetrees.     *     * We have two strategies depending
onwhether the prepared statement is
 
@@ -1526,6 +1538,11 @@ exec_bind_message(StringInfo input_message)     */    start_xact_command();
+    /*
+     * Set statement timeout running, if any
+     */
+    enable_statement_timeout();
+    /* Switch back to message context */    MemoryContextSwitchTo(MessageContext);
@@ -1942,6 +1959,11 @@ exec_execute_message(const char *portal_name, long max_rows)    start_xact_command();    /*
+     * Set statement timeout running, if any
+     */
+    enable_statement_timeout();
+
+    /*     * If we re-issue an Execute protocol request against an existing portal,     * then we are only fetching
morerows rather than completely re-executing     * the query from the start. atStart is never reset for a v3 portal, so
we
@@ -2014,6 +2036,11 @@ exec_execute_message(const char *portal_name, long max_rows)             * those that start or
enda transaction block.             */            CommandCounterIncrement();
 
+
+            /*
+             * We need to reset statement timeout if already set.
+             */
+            disable_statement_timeout();        }        /* Send appropriate CommandComplete to client */
@@ -2443,14 +2470,10 @@ start_xact_command(void)    {        StartTransactionCommand();
-        /* Set statement timeout running, if any */
-        /* NB: this mustn't be enabled until we are within an xact */
-        if (StatementTimeout > 0)
-            enable_timeout_after(STATEMENT_TIMEOUT, StatementTimeout);
-        else
-            disable_timeout(STATEMENT_TIMEOUT, false);
-        xact_started = true;
+
+        /* Set statement timeout running, if any */
+        enable_statement_timeout();    }}
@@ -2460,7 +2483,7 @@ finish_xact_command(void)    if (xact_started)    {        /* Cancel any active statement timeout
beforecommitting */
 
-        disable_timeout(STATEMENT_TIMEOUT, false);
+        disable_statement_timeout();        CommitTransactionCommand();
@@ -4511,3 +4534,53 @@ log_disconnections(int code, Datum arg)                    port->user_name, port->database_name,
port->remote_host,                 port->remote_port[0] ? " port=" : "", port->remote_port)));}
 
+
+/*
+ * Set statement timeout if any.
+ */
+static void
+enable_statement_timeout(void)
+{
+    if (!stmt_timer_started)
+    {
+        if (StatementTimeout > 0)
+        {
+
+            /*
+             * Sanity check
+             */
+            if (!xact_started)
+            {
+                ereport(ERROR,
+                        (errcode(ERRCODE_INVALID_PARAMETER_VALUE),
+                         errmsg("Transaction must have been already started to set statement timeout")));
+            }
+
+            ereport(DEBUG3,
+                    (errmsg_internal("Set statement timeout")));
+
+            enable_timeout_after(STATEMENT_TIMEOUT, StatementTimeout);
+            stmt_timer_started = true;
+        }
+        else
+            disable_timeout(STATEMENT_TIMEOUT, false);
+    }
+}
+
+/*
+ * Reset statement timeout if any.
+ */
+static void
+disable_statement_timeout(void)
+{
+    if (stmt_timer_started)
+    {
+        ereport(DEBUG3,
+                    (errmsg_internal("Disable statement timeout")));
+
+        /* Cancel any active statement timeout */
+        disable_timeout(STATEMENT_TIMEOUT, false);
+
+        stmt_timer_started = false;
+    }
+}

Tatsuo Ishii <ishii@sraoss.co.jp> writes:
>> * The difference is that the Execute message stops the statement_timeout timer,

> No. Parse, bind and Execute message indivually stops and starts the
> statement_timeout timer with the patch.

That seems like it could represent quite a lot of added overhead,
on machines where gettimeofday() is slow ... which is still a lot
of them, unfortunately.
        regards, tom lane

> That seems like it could represent quite a lot of added overhead,
> on machines where gettimeofday() is slow ... which is still a lot
> of them, unfortunately.

Maybe. I think we could eliminate restarting the timer for parse and
bind.

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

On 2017-04-03 23:31:59 +0900, Tatsuo Ishii wrote:
> > That seems like it could represent quite a lot of added overhead,
> > on machines where gettimeofday() is slow ... which is still a lot
> > of them, unfortunately.
> 
> Maybe. I think we could eliminate restarting the timer for parse and
> bind.

I've moved this patch to the next CF - it's been submitted fairly late
in the v10 cycle and there's obviously design work ongoing.

- Andres

From: pgsql-hackers-owner@postgresql.org
> [mailto:pgsql-hackers-owner@postgresql.org] On Behalf Of Tatsuo Ishii
> No. Parse, bind and Execute message indivually stops and starts the
> statement_timeout timer with the patch. Unless there's a lock conflict,
> parse and bind will take very short time. So actually users could only
> observe the timeout in execute message though.

Where is the statement_timeout timer stopped when processing Parse and Bind messages?  Do you mean the following
sequenceof operations are performed in this patch?
 

Parse(statement1) start timer stop timer
Bind(statement1, portal1) start timer stop timer
Execute(portal1) start timer stop timer
Sync

It looks like the patch does the following.  I think this is desirable, because starting and stopping the timer for
eachmessage may be costly as Tom said.
 

Parse(statement1) start timer
Bind(statement1, portal1)
Execute(portal1) stop timer
Sync


> > (3)
> > +            /*
> > +             * Sanity check
> > +             */
> > +            if (!xact_started)
> > +            {
> > +                ereport(ERROR,
> > +
>     (errcode(ERRCODE_INVALID_PARAMETER_VALUE),
> > +                         errmsg("Transaction
> must have been already started to set statement timeout")));
> > +            }
> >
> > I think this fragment can be deleted, because enable/disable_timeout()
> is used only at limited places in postgres.c, so I don't see the chance
> of misuse.
> 
> I'd suggest leave it as it is. Because it might be possible that the function
> is used in different place in the future. Or at least we should document
> the pre-condition as a comment.

OK, I favor documenting to reduce code, but I don't have a strong opinion.  I'd like to leave this to the committer.
Onething to note is that you can remove { and } in the following code like other places.
 

+            if (!xact_started)
+            {
+                ereport(ERROR,
+                        (errcode(ERRCODE_INVALID_PARAMETER_VALUE),
+                         errmsg("Transaction must have been already started to set statement timeout")));
+            }

Regards
Takayuki Tsunakawa

> Where is the statement_timeout timer stopped when processing Parse and Bind messages?

Actually the statement timer is replaced with new statement timer
value in enable_statement_timeout().

> Do you mean the following sequence of operations are performed in this patch?
> 
> Parse(statement1)
>   start timer
>   stop timer
> Bind(statement1, portal1)
>   start timer
>   stop timer
> Execute(portal1)
>   start timer
>   stop timer
> Sync

Yes.

> It looks like the patch does the following.  I think this is desirable, because starting and stopping the timer for
eachmessage may be costly as Tom said.
 
> Parse(statement1)
>   start timer
> Bind(statement1, portal1)
> Execute(portal1)
>   stop timer
> Sync

This doesn't work in general use cases. Following pattern appears
frequently in applications.

Parse(statement1)
Bind(statement1, portal1)
Execute(portal1)
Bind(statement1, portal1)
Execute(portal1)
:
:
Sync

Also what would happen if client just send a parse message and does
nothing after that?

So I think following is better:

Parse(statement1)
Bind(statement1, portal1)
Execute(portal1) start timer stop timer
Bind(statement1, portal1)
Execute(portal1) start timer stop timer
:
:
Sync

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

From: pgsql-hackers-owner@postgresql.org
> [mailto:pgsql-hackers-owner@postgresql.org] On Behalf Of Tatsuo Ishii
> Actually the statement timer is replaced with new statement timer value
> in enable_statement_timeout().

The patch doesn't seem to behave like that.  The Parse message calls start_xact_command() -> enable_statement_timeout()
->enable_timeout(), and set stmt_timer_started to true.  Subsequent Bind and Execute messages call
enable_statement_timeout(),but enable_statement_timeout() doesn't call enable_timeout() because stmt_timer_started is
alreadytrue.
 


> > It looks like the patch does the following.  I think this is desirable,
> because starting and stopping the timer for each message may be costly as
> Tom said.
> > Parse(statement1)
> >   start timer
> > Bind(statement1, portal1)
> > Execute(portal1)
> >   stop timer
> > Sync

I ran one INSERT statement using JDBC with log_min_messages = DEBUG3, and the server log shows what I said.

DEBUG:  parse <unnamed>: insert into a values(2)
DEBUG:  Set statement timeout
LOG:  duration: 0.431 ms  parse <unnamed>: insert into a values(2)
DEBUG:  bind <unnamed> to <unnamed>
LOG:  duration: 0.127 ms  bind <unnamed>: insert into a values(2)
DEBUG:  Disable statement timeout
LOG:  duration: 0.184 ms  execute <unnamed>: insert into a values(2)
DEBUG:  snapshot of 1+0 running transaction ids (lsn 0/163BF28 oldest xid 561 latest complete 560 next xid 562)


> This doesn't work in general use cases. Following pattern appears frequently
> in applications.
> 
> Parse(statement1)
> Bind(statement1, portal1)
> Execute(portal1)
> Bind(statement1, portal1)
> Execute(portal1)
> :
> :
> Sync

It works.  The first Parse-Bind-Execute is measured as one unit, then subsequent Bind-Execute pairs are measured as
otherunits.  That's because each Execute ends the statement_timeout timer and the Bind message starts it again.  I
thinkthis is desirable, so the current patch looks good.  May I mark this as ready for committer?  FYI, make
check-worldpassed successfully.
 


> Also what would happen if client just send a parse message and does nothing
> after that?

It's correct to trigger the statement timeout in this case, because the first SQL statement started (with the Parse
message)and its execution is not finished (with Execute message.)
 


Regards
Takayuki Tsunakawa

> What do you think?  I've not really tested this with the extended
> protocol, so I'd appreciate if you could rerun your test from the
> older thread.

Attached is your patch just rebased against master branch.

Also I attached the test cases and results using pgproto on patched
master branch. All looks good to me.

Best regards,
--
Tatsuo Ishii
SRA OSS, Inc. Japan
English: http://www.sraoss.co.jp/index_en.php
Japanese:http://www.sraoss.co.jp
diff --git a/src/backend/tcop/postgres.c b/src/backend/tcop/postgres.c
index 8d3fecf..6c53b9c 100644
--- a/src/backend/tcop/postgres.c
+++ b/src/backend/tcop/postgres.c
@@ -144,6 +144,11 @@ static bool doing_extended_query_message = false;static bool ignore_till_sync = false;/*
+ * Flag to keep track of whether statement timeout timer is active.
+ */
+static bool stmt_timeout_active = false;
+
+/* * If an unnamed prepared statement exists, it's stored here. * We keep it separate from the hashtable kept by
commands/prepare.c* in order to reduce overhead for short-lived queries.
 
@@ -182,6 +187,8 @@ static bool IsTransactionExitStmtList(List *pstmts);static bool IsTransactionStmtList(List
*pstmts);staticvoid drop_unnamed_stmt(void);static void log_disconnections(int code, Datum arg);
 
+static void enable_statement_timeout(void);
+static void disable_statement_timeout(void);/* ----------------------------------------------------------------
@@ -1228,7 +1235,8 @@ exec_parse_message(const char *query_string,    /* string to execute */    /*     * Start up a
transactioncommand so we can run parse analysis etc. (Note     * that this will normally change current memory
context.)Nothing happens
 
-     * if we are already in one.
+     * if we are already in one.  This also arms the statement timeout if
+     * necessary.     */    start_xact_command();
@@ -1516,7 +1524,8 @@ exec_bind_message(StringInfo input_message)    /*     * Start up a transaction command so we can
callfunctions etc. (Note that     * this will normally change current memory context.) Nothing happens if
 
-     * we are already in one.
+     * we are already in one.  This also arms the statement timeout if
+     * necessary.     */    start_xact_command();
@@ -2008,6 +2017,9 @@ exec_execute_message(const char *portal_name, long max_rows)             * those that start or
enda transaction block.             */            CommandCounterIncrement();
 
+
+            /* full command has been executed, reset timeout */
+            disable_statement_timeout();        }        /* Send appropriate CommandComplete to client */
@@ -2437,25 +2449,27 @@ start_xact_command(void)    {        StartTransactionCommand();
-        /* Set statement timeout running, if any */
-        /* NB: this mustn't be enabled until we are within an xact */
-        if (StatementTimeout > 0)
-            enable_timeout_after(STATEMENT_TIMEOUT, StatementTimeout);
-        else
-            disable_timeout(STATEMENT_TIMEOUT, false);
-        xact_started = true;    }
+
+    /*
+     * 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();}static voidfinish_xact_command(void){
+    /* cancel active statement timeout after each command */
+    disable_statement_timeout();
+    if (xact_started)    {
-        /* Cancel any active statement timeout before committing */
-        disable_timeout(STATEMENT_TIMEOUT, false);
-        CommitTransactionCommand();#ifdef MEMORY_CONTEXT_CHECKING
@@ -4521,3 +4535,42 @@ log_disconnections(int code, Datum arg)                    port->user_name, port->database_name,
port->remote_host,                   port->remote_port[0] ? " port=" : "", port->remote_port)));}
 
+
+/*
+ * Start statement timeout timer, if enabled.
+ *
+ * If there's already a timeout running, don't restart the timer.  That
+ * enables compromises between accuracy of timeouts and cost of starting a
+ * timeout.
+ */
+static void
+enable_statement_timeout(void)
+{
+    /* must be within an xact */
+    Assert(xact_started);
+
+    if (StatementTimeout > 0)
+    {
+        if (!stmt_timeout_active)
+        {
+            enable_timeout_after(STATEMENT_TIMEOUT, StatementTimeout);
+            stmt_timeout_active = true;
+        }
+    }
+    else
+        disable_timeout(STATEMENT_TIMEOUT, false);
+}
+
+/*
+ * Disable statement timeout, if active.
+ */
+static void
+disable_statement_timeout(void)
+{
+    if (stmt_timeout_active)
+    {
+        disable_timeout(STATEMENT_TIMEOUT, false);
+
+        stmt_timeout_active = false;
+    }
+}
====== 001-without-trans =======
FE=> Query(query="SET statement_timeout = '4s'")
<= BE CommandComplete(SET)
<= BE ReadyForQuery(I)
FE=> Parse(stmt="", query="SELECT pg_sleep(3)")
FE=> Bind(stmt="", portal="")
FE=> Execute(portal="")
FE=> Parse(stmt="", query="SELECT pg_sleep(2)")
FE=> Bind(stmt="", portal="")
FE=> Execute(portal="")
FE=> Sync
<= BE ParseComplete
<= BE BindComplete
<= BE DataRow
<= BE CommandComplete(SELECT 1)
<= BE ParseComplete
<= BE BindComplete
<= BE DataRow
<= BE CommandComplete(SELECT 1)
<= BE ReadyForQuery(I)
FE=> Terminate
====== 002-with-trans =======
FE=> Query(query="SET statement_timeout = '4s'")
<= BE CommandComplete(SET)
<= BE ReadyForQuery(I)
FE=> Parse(stmt="", query="BEGIN")
FE=> Bind(stmt="", portal="")
FE=> Execute(portal="")
FE=> Parse(stmt="", query="SELECT pg_sleep(3)")
FE=> Bind(stmt="", portal="")
FE=> Execute(portal="")
FE=> Parse(stmt="", query="SELECT pg_sleep(2)")
FE=> Bind(stmt="", portal="")
FE=> Execute(portal="")
FE=> Parse(stmt="", query="COMMIT")
FE=> Bind(stmt="", portal="")
FE=> Execute(portal="")
FE=> Sync
<= BE ParseComplete
<= BE BindComplete
<= BE CommandComplete(BEGIN)
<= BE ParseComplete
<= BE BindComplete
<= BE DataRow
<= BE CommandComplete(SELECT 1)
<= BE ParseComplete
<= BE BindComplete
<= BE DataRow
<= BE CommandComplete(SELECT 1)
<= BE ParseComplete
<= BE BindComplete
<= BE CommandComplete(COMMIT)
<= BE ReadyForQuery(I)
FE=> Terminate
====== 003-without-trans-timeout =======
FE=> Query(query="SET statement_timeout = '2s'")
<= BE CommandComplete(SET)
<= BE ReadyForQuery(I)
FE=> Parse(stmt="", query="SELECT pg_sleep(1)")
FE=> Bind(stmt="", portal="")
FE=> Execute(portal="")
FE=> Parse(stmt="", query="SELECT pg_sleep(2)")
FE=> Bind(stmt="", portal="")
FE=> Execute(portal="")
FE=> Sync
2017-09-05 11:17:26.619 JST [5911] ERROR:  canceling statement due to statement timeout
2017-09-05 11:17:26.619 JST [5911] STATEMENT:  SELECT pg_sleep(2)
<= BE ParseComplete
<= BE BindComplete
<= BE DataRow
<= BE CommandComplete(SELECT 1)
<= BE ParseComplete
<= BE BindComplete
<= BE ErrorResponse(S ERROR V ERROR C 57014 M canceling statement due to statement timeout F postgres.c L 2983 R
ProcessInterrupts)
 
<= BE ReadyForQuery(I)
FE=> Terminate
====== 004-with-trans-timeout =======
FE=> Query(query="SET statement_timeout = '2s'")
<= BE CommandComplete(SET)
<= BE ReadyForQuery(I)
FE=> Parse(stmt="", query="BEGIN")
FE=> Bind(stmt="", portal="")
FE=> Execute(portal="")
FE=> Parse(stmt="", query="SELECT pg_sleep(1)")
FE=> Bind(stmt="", portal="")
FE=> Execute(portal="")
FE=> Parse(stmt="", query="SELECT pg_sleep(2)")
FE=> Bind(stmt="", portal="")
FE=> Execute(portal="")
FE=> Parse(stmt="", query="COMMIT")
FE=> Bind(stmt="", portal="")
FE=> Execute(portal="")
FE=> Sync
2017-09-05 11:17:29.630 JST [5914] ERROR:  canceling statement due to statement timeout
2017-09-05 11:17:29.630 JST [5914] STATEMENT:  SELECT pg_sleep(2)
<= BE ParseComplete
<= BE BindComplete
<= BE CommandComplete(BEGIN)
<= BE ParseComplete
<= BE BindComplete
<= BE DataRow
<= BE CommandComplete(SELECT 1)
<= BE ParseComplete
<= BE BindComplete
<= BE ErrorResponse(S ERROR V ERROR C 57014 M canceling statement due to statement timeout F postgres.c L 2983 R
ProcessInterrupts)
 
<= BE ReadyForQuery(E)
FE=> Terminate
====== 005-without-trans-simple-timeout =======
FE=> Query(query="SET statement_timeout = '2s'")
<= BE CommandComplete(SET)
<= BE ReadyForQuery(I)
FE=> Query(query="SELECT pg_sleep(1)")
<= BE RowDescription
<= BE DataRow
<= BE CommandComplete(SELECT 1)
<= BE ReadyForQuery(I)
FE=> Query(query="SELECT pg_sleep(2)")
2017-09-05 11:17:32.637 JST [5916] ERROR:  canceling statement due to statement timeout
2017-09-05 11:17:32.637 JST [5916] STATEMENT:  SELECT pg_sleep(2)
<= BE RowDescription
<= BE ErrorResponse(S ERROR V ERROR C 57014 M canceling statement due to statement timeout F postgres.c L 2983 R
ProcessInterrupts)
 
<= BE ReadyForQuery(I)
FE=> Terminate
====== 006-with-trans-simple-timeout =======
FE=> Query(query="SET statement_timeout = '2s'")
<= BE CommandComplete(SET)
<= BE ReadyForQuery(I)
FE=> Query(query="BEGIN")
<= BE CommandComplete(BEGIN)
<= BE ReadyForQuery(T)
FE=> Query(query="SELECT pg_sleep(1)")
<= BE RowDescription
<= BE DataRow
<= BE CommandComplete(SELECT 1)
<= BE ReadyForQuery(T)
FE=> Query(query="SELECT pg_sleep(2)")
2017-09-05 11:17:35.648 JST [5920] ERROR:  canceling statement due to statement timeout
2017-09-05 11:17:35.648 JST [5920] STATEMENT:  SELECT pg_sleep(2)
<= BE RowDescription
<= BE ErrorResponse(S ERROR V ERROR C 57014 M canceling statement due to statement timeout F postgres.c L 2983 R
ProcessInterrupts)
 
<= BE ReadyForQuery(E)
FE=> Query(query="COMMIT")
<= BE CommandComplete(ROLLBACK)
<= BE ReadyForQuery(I)
FE=> Terminate
====== 007-timeout-twice =======
FE=> Query(query="SET statement_timeout = '3s'")
<= BE CommandComplete(SET)
<= BE ReadyForQuery(I)
FE=> Parse(stmt="S1", query="SELECT pg_sleep(2)")
FE=> Bind(stmt="S1", portal="S2")
FE=> Parse(stmt="", query="SET statement_timeout = '1s'")
FE=> Bind(stmt="", portal="")
FE=> Execute(portal="")
FE=> Execute(portal="S2")
FE=> Sync
2017-09-05 11:17:36.653 JST [5923] ERROR:  canceling statement due to statement timeout
2017-09-05 11:17:36.653 JST [5923] STATEMENT:  SELECT pg_sleep(2)
<= BE ParseComplete
<= BE BindComplete
<= BE ParseComplete
<= BE BindComplete
<= BE CommandComplete(SET)
<= BE ErrorResponse(S ERROR V ERROR C 57014 M canceling statement due to statement timeout F postgres.c L 2983 R
ProcessInterrupts)
 
<= BE ReadyForQuery(I)
FE=> Parse(stmt="S3", query="SELECT pg_sleep(2)")
FE=> Bind(stmt="S3", portal="S2")
FE=> Execute(portal="S2")
FE=> Sync
<= BE ParseComplete
<= BE BindComplete
<= BE DataRow
<= BE CommandComplete(SELECT 1)
<= BE ReadyForQuery(I)
FE=> Terminate

Andres,

If you don't mind, can you please commit/push the patch?

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

>> What do you think?  I've not really tested this with the extended
>> protocol, so I'd appreciate if you could rerun your test from the
>> older thread.
> 
> Attached is your patch just rebased against master branch.
> 
> Also I attached the test cases and results using pgproto on patched
> master branch. All looks good to me.
> 
> Best regards,
> --
> Tatsuo Ishii
> SRA OSS, Inc. Japan
> English: http://www.sraoss.co.jp/index_en.php
> Japanese:http://www.sraoss.co.jp


-- 
Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-hackers

Hi,

On 2017-09-11 09:10:49 +0900, Tatsuo Ishii wrote:
> If you don't mind, can you please commit/push the patch?

Ok, will do so.

Greetings,

Andres Freund


-- 
Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-hackers

On 2017-09-10 17:12:19 -0700, Andres Freund wrote:
> On 2017-09-11 09:10:49 +0900, Tatsuo Ishii wrote:
> > If you don't mind, can you please commit/push the patch?
> 
> Ok, will do so.

And, done.  Thanks for patch and reminder!

- Andres


-- 
Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-hackers

> On 2017-09-10 17:12:19 -0700, Andres Freund wrote:
>> On 2017-09-11 09:10:49 +0900, Tatsuo Ishii wrote:
>> > If you don't mind, can you please commit/push the patch?
>> 
>> Ok, will do so.
> 
> And, done.  Thanks for patch and reminder!

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


-- 
Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-hackers