Re: 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 which looks
inconsistent with #1.

3) If the sync message arrives long time after execute(portal2) (say,
3 seconds), statement timeout will raised even if execute(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(at)postgresql(dot)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

Tatsuo Ishii <ishii(at)postgresql(dot)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 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.

> 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(at)postgresql(dot)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.
>

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.

With Regards,
Amit Kapila.
EnterpriseDB: http://www.enterprisedb.com

On 1 June 2016 at 08:33, Tatsuo Ishii <ishii(at)postgresql(dot)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.

--
Craig Ringer http://www.2ndQuadrant.com/
PostgreSQL Development, 24x7 Support, Training & Services

> 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(at)postgresql(dot)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?
>
>
https://commitfest.postgresql.org/10/634/

https://www.postgresql.org/message-id/flat/CAMsr+YFUjJytRyV4J-16bEoiZyH=4nj+sQ7JP9ajwz=B4dMMZw(at)mail(dot)gmail(dot)com#CAMsr+YFUjJytRyV4J-16bEoiZyH=4nj+sQ7JP9ajwz=B4dMMZw@mail.gmail.com

> > 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".

--
Craig Ringer http://www.2ndQuadrant.com/
PostgreSQL Development, 24x7 Support, Training & Services

>> 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(at)mail(dot)gmail(dot)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