Re: [HACKERS] Statement timeout behavior in extended queries

> 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