[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;
+    }
+}