Thread: Statement timeout

When extended query protocol message is used, statement timeout is not
checked until a sync message is received (more precisely, statement
timeout timer is canceled while processing the sync message, and
actual checking timeout is done in CHECK_FOR_INTERRUPTS). Example:

parse(statement1)
bind(statement1, portal1)
execute(portal1)
parse(statement2)
bind(statement2, portal2)
execute(portal2)
sync

Suppose statement_timeout = 2s. If execute(portal1) takes 3 seconds,
and execute(portal2) takes 1 second, the statement timeout is reported
at the time when the sync message is processed which is right after
execute(portal2). This may lead to certain confusions to users:

1) If log_min_error_statement is ERROR or below, the cause of statement  timeout is reported as statement2, rather than
statement1.

2) If log_duration is set, the execution time for execute(portal1) is  3 seconds, and execute(portal2) is 1 second
whichlooks  inconsistent with #1.
 

3) If the sync message arrives long time after execute(portal2) (say,  3 seconds), statement timeout will raised even
ifexecute(portal1)  and execute(portal2) take less than 2 seconds.
 

Is there any room to enhance this? For example calling
disable_timeout(STATEMENT_TIMEOUT, false) in exec_execute_message.

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

Tatsuo Ishii <ishii@postgresql.org> writes:
> When extended query protocol message is used, statement timeout is not
> checked until a sync message is received (more precisely, statement
> timeout timer is canceled while processing the sync message, and
> actual checking timeout is done in CHECK_FOR_INTERRUPTS). Example:

> parse(statement1)
> bind(statement1, portal1)
> execute(portal1)
> parse(statement2)
> bind(statement2, portal2)
> execute(portal2)
> sync

> Suppose statement_timeout = 2s. If execute(portal1) takes 3 seconds,
> and execute(portal2) takes 1 second, the statement timeout is reported
> at the time when the sync message is processed which is right after
> execute(portal2).

Really?  It should get reported at some execution of CHECK_FOR_INTERRUPTS
after we pass the 2-second mark in execute(portal1).  If that's not what
you're observing, maybe you've found a code path that's missing some
CHECK_FOR_INTERRUPTS call(s).
        regards, tom lane

> Really?  It should get reported at some execution of CHECK_FOR_INTERRUPTS
> after we pass the 2-second mark in execute(portal1).  If that's not what
> you're observing, maybe you've found a code path that's missing some
> CHECK_FOR_INTERRUPTS call(s).

Oops. Previous example was not appropriate. Here are revised
examples. (in any case, the time consumed at parse and bind are small,
and I omit the CHECK_FOR_INTERRUPTS after these commands)

[example 1]

statement_timeout = 3s

parse(statement1) -- time 0. set statement timout timer
bind(statement1, portal1)
execute(portal1) -- took 2 seconds
CHECK_FOR_INTERRUPTS -- 2 seconds passed since time 0. statement timeout does not fire
parse(statement2)
bind(statement2, portal2)
execute(portal2) -- took 2 seconds
CHECK_FOR_INTERRUPTS -- 4 seconds passed since time 0. the statement timeout fires!

Another example.

[example 2]

statement_timeout = 3s

parse(statement1) -- time 0. set statement timout timer
bind(statement1, portal1)
execute(portal1) -- took 1 second
CHECK_FOR_INTERRUPTS -- 1 second passed since time 0. statement timeout does not fire
parse(statement2)
bind(statement2, portal2)
execute(portal2) -- took 1 second
CHECK_FOR_INTERRUPTS -- 2 seconds passed since time 0. the statement timeout fires!
[client is idle for 2 seconds]
sync
CHECK_FOR_INTERRUPTS -- 4 seconds passed since time 0. the statement timeout fires!

I think current code is good in detecting statement timeout if each
command execution time actually exceeds the specified timeout. However
it could report false statement timeout in some cases like above.

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

> Oops. Previous example was not appropriate. Here are revised
> examples. (in any case, the time consumed at parse and bind are small,
> and I omit the CHECK_FOR_INTERRUPTS after these commands)
> 
> [example 1]
> 
> statement_timeout = 3s
> 
> parse(statement1) -- time 0. set statement timout timer
> bind(statement1, portal1)
> execute(portal1) -- took 2 seconds
> CHECK_FOR_INTERRUPTS -- 2 seconds passed since time 0. statement timeout does not fire
> parse(statement2)
> bind(statement2, portal2)
> execute(portal2) -- took 2 seconds
> CHECK_FOR_INTERRUPTS -- 4 seconds passed since time 0. the statement timeout fires!
> 
> Another example.
> 
> [example 2]
> 
> statement_timeout = 3s
> 
> parse(statement1) -- time 0. set statement timout timer
> bind(statement1, portal1)
> execute(portal1) -- took 1 second
> CHECK_FOR_INTERRUPTS -- 1 second passed since time 0. statement timeout does not fire
> parse(statement2)
> bind(statement2, portal2)
> execute(portal2) -- took 1 second
> CHECK_FOR_INTERRUPTS -- 2 seconds passed since time 0. the statement timeout fires!
> [client is idle for 2 seconds]
> sync
> CHECK_FOR_INTERRUPTS -- 4 seconds passed since time 0. the statement timeout fires!
> 
> I think current code is good in detecting statement timeout if each
> command execution time actually exceeds the specified timeout. However
> it could report false statement timeout in some cases like above.

Here is the patch against master branch to deal with the problem. I
create new functions in tcop/postgres.c:

static void enable_statement_timeout(void);
static void disable_statement_timeout(void);

Before the code was in start_xact_command() and finish_xact_command()
but I want to manage to disable timeout in exec_execute_command, so I
separated the code into the new functions.

Also start_xact_command() and finish_xact_command() were modified to
use these new functions to avoid code duplication.

I tested the patch using small C program linked with modified libpq
(PQsendQueryParams was modified to issue "flush" message instead of
"sync" message). The statement timeout was set to 3 seconds. With
these test programs, client sends pg_sleep(2) and flush message then
sleep 10 seconds. With current PostgreSQL, this triggers statement
timeout while the client is sleeping. With patched PostgreSQL, this
does not trigger the timeout as expected.

All regression tests passed.

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 b185c1b..564855a 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 *parseTrees);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);/* ----------------------------------------------------------------
@@ -2002,6 +2009,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 */
@@ -2433,14 +2445,10 @@ start_xact_command(void)                (errmsg_internal("StartTransactionCommand")));
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();    }}
@@ -2450,7 +2458,7 @@ finish_xact_command(void)    if (xact_started)    {        /* Cancel any active statement timeout
beforecommitting */
 
-        disable_timeout(STATEMENT_TIMEOUT, false);
+        disable_statement_timeout();        /* Now commit the command */        ereport(DEBUG3,
@@ -4510,3 +4518,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;
+    }
+}
#include <stdio.h>
#include <stdlib.h>
#include <stdint.h>
#include <string.h>
#include <sys/types.h>
#include "libpq-fe.h"

static void
exit_nicely(PGconn *conn)
{PQfinish(conn);exit(1);
}

main()
{char *conninfo = "port=11003 dbname=test";PGconn       *conn;PGresult   *res;const char *paramValues[1];
conn = PQconnectdb(conninfo);if (PQstatus(conn) != CONNECTION_OK){    fprintf(stderr, "Connection to database failed:
%s",           PQerrorMessage(conn));    exit_nicely(conn);}
 
paramValues[0] = "2";
fprintf(stderr, "start #1 query\n");PQsendQueryParams(conn,                  "SELECT pg_sleep($1::int)",
 1,        /* one param */                  NULL,    /* let the backend deduce param type */
paramValues,                 NULL,    /* don't need param lengths since text */                  NULL,    /* default to
alltext params */                  0);        /* ask for text results */
 
fprintf(stderr, "end #1 query\n");
sleep(10);
exit(0);
}

Tatsuo Ishii <ishii@postgresql.org> writes:
>> Oops. Previous example was not appropriate. Here are revised
>> examples. (in any case, the time consumed at parse and bind are small,
>> and I omit the CHECK_FOR_INTERRUPTS after these commands)

FWIW, I think the existing behavior is just fine.  It corresponds to what
PQexec has always done with multi-statement query strings; that is,
statement_timeout governs the total time to execute the transaction (the
whole query string, unless you put transaction control commands in there).
In extended query mode, since you can only put one textual query per Parse
message, that maps to statement_timeout governing the total time from
initial Parse to Sync.  Which is what it does.

What you propose here is not a bug fix but a redefinition of what
statement_timeout does; and you've made it inconsistent with simple query
mode.  I don't really think it's an improvement.

BTW, aren't you missing a re-enable of the timeout for statements after
the first one?
        regards, tom lane

> FWIW, I think the existing behavior is just fine.  It corresponds to what
> PQexec has always done with multi-statement query strings; that is,
> statement_timeout governs the total time to execute the transaction (the
> whole query string, unless you put transaction control commands in there).
> In extended query mode, since you can only put one textual query per Parse
> message, that maps to statement_timeout governing the total time from
> initial Parse to Sync.  Which is what it does.

I've never thought about that. And I cannot imagine anyone is using
that way in extended protocol to simulate multi-statement queries. Is
that documented somewhere?

> What you propose here is not a bug fix but a redefinition of what
> statement_timeout does; and you've made it inconsistent with simple query
> mode.  I don't really think it's an improvement.

From the document about statement_timeout (config.sgml):
       Abort any statement that takes more than the specified number of       milliseconds, starting from the time the
commandarrives at the server       from the client.  If <varname>log_min_error_statement</> is set to
<literal>ERROR</>or lower, the statement that timed out will also be       logged.  A value of zero (the default) turns
thisoff.
 

Apparently "starting from the time the command arrives at the server
from the client" referrers to the timing of execute message arrives to
server the in my example. And I think current behavior of our code is
doing different from what he document advertises. Or at least counter
intuitive to users.

> BTW, aren't you missing a re-enable of the timeout for statements after
> the first one?

Will check.

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

> Well, multiple parse/bind/execute messages before a sync are definitely
> used by PgJDBC and nPgSQL for batching,

Yes, I realized in JDBC.

> and I just posted a patch for it
> for libpq.

I didn't noticed it. Could you give me the message id or URL?

I wouldn't have considered it to simulate multi-statement
> simple-protocol queries, but I guess there are some parallels.
> 
> I am very surprised to find out that statement_timeout tracks the total
> time and isn't reset by a new statement, but I guess it makes sense - what,
> exactly, delimits a "query" in extended query mode? statement_timeout in
> simple-query mode starts at parse time and runs until the end of execute.
> In e.q.p. there might be only one parse, then a series of Bind and Execute
> messages, or there may be repeated Parse messages.

Another issue is inconsistency with log duration, which shows the the
elapsed time for each execute message. I think statement timeout
should be consistent with statement duration. Otherwise users will be
confused.

> Personally I'd be fairly happy with statement-timeout applying per-message
> in the extended query protocol. That would mean that it behaves slightly
> differently, and a query with a long slow parse and bind phase followed by
> quick execution might fail to time out in the extended query protocol where
> it would time out as a simple query.
> It'd behave as if the query was
> PREPAREd then separately EXECUTEd in simple-query protocol. I'm not hugely
> bothered by that, but if it's really a concern I'd ideally like to add a
> new protocol message that resets the statement timeout counter, so the
> client can define what delimits a statement. Not practical in the near term.
> 
> For now I'd be OK with documenting this as a quirk/limitation of
> statement_timeout, that it applies to a whole extended-query-protocol
> batch.

Probably we should apply the code change for 10.0 if any. (of course
this will not be applied if many uses are getting angry with current
behavior of statement timeout).

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

>> I didn't noticed it. Could you give me the message id or URL?
>>
>>
> https://commitfest.postgresql.org/10/634/
> 
>
https://www.postgresql.org/message-id/flat/CAMsr+YFUjJytRyV4J-16bEoiZyH=4nj+sQ7JP9ajwz=B4dMMZw@mail.gmail.com#CAMsr+YFUjJytRyV4J-16bEoiZyH=4nj+sQ7JP9ajwz=B4dMMZw@mail.gmail.com

Thanks.

>> Another issue is inconsistency with log duration, which shows the the
>> elapsed time for each execute message. I think statement timeout
>> should be consistent with statement duration. Otherwise users will be
>> confused.
>>
> 
> While I agree that's confusing, I think that's actualyl a problem with
> log_duration.
> 
> log_duration is really more of an internal trace parameter that should be
> named debug_log_duration or something IMO. It also fails to print the
> message type, which makes it even more confusing since it for a typical
> extended protocl query it usually logs 3 durations with no indication of
> which is what.

It's definitely a poor design.

> Users should be using log_min_duration_statement. You know, the confusingly
> named one. Or is it log_duration_min_statement or
> log_statement_min_duration or ...?
> 
> Yeah, log_duration is confusing to the point I think it needs a comment
> like "To record query run-time you probably want
> log_min_duration_statement, not log_duration".

I'm confused. Regarding the timing whether duration is emitted at sync
or each message, log_duration and log_min_duration_statement behave
exactly same, no? If so, log_min_duration_statement is not consistent
with statement_timeout, anyway.

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

>> BTW, aren't you missing a re-enable of the timeout for statements after
>> the first one?
> 
> Will check.

You are right. Here is the revised patch.

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 b185c1b..88f5c54 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 *parseTrees);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);/* ----------------------------------------------------------------
@@ -1227,6 +1234,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
 
@@ -1516,6 +1528,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);
@@ -1931,6 +1948,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
@@ -2002,6 +2024,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 */
@@ -2433,14 +2460,10 @@ start_xact_command(void)                (errmsg_internal("StartTransactionCommand")));
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();    }}
@@ -2450,7 +2473,7 @@ finish_xact_command(void)    if (xact_started)    {        /* Cancel any active statement timeout
beforecommitting */
 
-        disable_timeout(STATEMENT_TIMEOUT, false);
+        disable_statement_timeout();        /* Now commit the command */        ereport(DEBUG3,
@@ -4510,3 +4533,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;
+    }
+}