Обсуждение: 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
On Wed, Jun 1, 2016 at 6:03 AM, Tatsuo Ishii <ishii@postgresql.org> wrote:
>
> 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 command arrives 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 this off.
>
> 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.
>
>
> 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 command arrives 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 this off.
>
> 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.
>
It seems to me the above documentation is more relevant with respect to simple query. However, I agree that it is better if statement_timeout is the timeout for each execution of the parsed statement.
On 1 June 2016 at 08:33, Tatsuo Ishii <ishii@postgresql.org> wrote:
> 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?
Well, multiple parse/bind/execute messages before a sync are definitely used by PgJDBC and nPgSQL for batching, and I just posted a patch for it for libpq. 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.
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.
> 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
On 3 June 2016 at 09:45, Tatsuo Ishii <ishii@postgresql.org> wrote:
> 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 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.
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.
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 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; + } +}