Re: 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

On Wed, Feb 22, 2017 at 11:50:44AM +0900, Tatsuo Ishii wrote:
> 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)

Does it seem reasonable to start making this into a regression test
and/or fuzz test for the protocol itself?

Best,
David.
--
David Fetter <david(at)fetter(dot)org> http://fetter.org/
Phone: +1 415 235 3778 AIM: dfetter666 Yahoo!: dfetter
Skype: davidfetter XMPP: david(dot)fetter(at)gmail(dot)com

Remember to vote!
Consider donating to Postgres: http://www.postgresql.org/about/donate

> On Wed, Feb 22, 2017 at 11:50:44AM +0900, Tatsuo Ishii wrote:
>> 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)
>
> Does it seem reasonable to start making this into a regression test
> and/or fuzz test for the protocol itself?

I personally think the regression tests ought to include tests for
extended query protocols and pgproto could be an useful tool to
implement that. Of course if we are going for that direction, pgproto
needs to be a contrib module first.

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

Hello,

I've reviewed the patch. My understanding is as follows. Please correct me if I'm wrong.

* The difference is that the Execute message stops the statement_timeout timer, so that the execution of one statement doesn't shorten the timeout period of subsequent statements when they are run in batch followed by a single Sync message.

* This patch is also necessary (or desirable) for the feature "Pipelining/batch mode support for libpq," which is being developed for PG 10. This patch enables correct timeout handling for each statement execution in a batch. Without this patch, the entire batch of statements is subject to statement_timeout. That's different from what the manual describes about statement_timeout. statement_timeout should measure execution of each statement.

Below are what I found in the patch.

(1)
+static bool st_timeout = false;

I think the variable name would better be stmt_timeout_enabled or stmt_timer_started, because other existing names use stmt to abbreviate statement, and thhis variable represents a state (see xact_started for example.)

(2)
+static void enable_statement_timeout(void)
+{

+static void disable_statement_timeout(void)
+{

"static void" and the remaining line should be on different lines, as other functions do.

(3)
+ /*
+ * Sanity check
+ */
+ if (!xact_started)
+ {
+ ereport(ERROR,
+ (errcode(ERRCODE_INVALID_PARAMETER_VALUE),
+ errmsg("Transaction must have been already started to set statement timeout")));
+ }

I think this fragment can be deleted, because enable/disable_timeout() is used only at limited places in postgres.c, so I don't see the chance of misuse.

Regards
Takayuki Tsunakawa

Thank you for reviewing my patch!

> Hello,
>
>
> I've reviewed the patch. My understanding is as follows. Please correct me if I'm wrong.
>
> * The difference is that the Execute message stops the statement_timeout timer,

No. Parse, bind and Execute message indivually stops and starts the
statement_timeout timer with the patch. Unless there's a lock
conflict, parse and bind will take very short time. So actually users
could only observe the timeout in execute message though.

> so that the execution of one statement doesn't shorten the timeout
> period of subsequent statements when they are run in batch followed by
> a single Sync message.

This is true. Currently multiple set of parse/bind/execute will not
trigger statement timeout until sync message is sent to
backend. Suppose statement_timeout is set to 3 seconds, combo A
(parse/bind/execute) takes 2 seconds and combo B (parse/bind/execute)
takes 2 seconds then a sync message is followed. Currently statement
timeout is fired in the run of combo B (assuming that parse and bind
take almost 0 seconds). With my patch, no statement timeout will be
fired because both combo A and combo B runs within 3 seconds.

> * This patch is also necessary (or desirable) for the feature "Pipelining/batch mode support for libpq," which is being developed for PG 10. This patch enables correct timeout handling for each statement execution in a batch. Without this patch, the entire batch of statements is subject to statement_timeout. That's different from what the manual describes about statement_timeout. statement_timeout should measure execution of each statement.

True.

> Below are what I found in the patch.
>
>
> (1)
> +static bool st_timeout = false;
>
> I think the variable name would better be stmt_timeout_enabled or stmt_timer_started, because other existing names use stmt to abbreviate statement, and thhis variable represents a state (see xact_started for example.)

Agreed. Chaged to stmt_timer_started.

> (2)
> +static void enable_statement_timeout(void)
> +{
>
> +static void disable_statement_timeout(void)
> +{
>
> "static void" and the remaining line should be on different lines, as other functions do.

Fixed.

> (3)
> + /*
> + * Sanity check
> + */
> + if (!xact_started)
> + {
> + ereport(ERROR,
> + (errcode(ERRCODE_INVALID_PARAMETER_VALUE),
> + errmsg("Transaction must have been already started to set statement timeout")));
> + }
>
> I think this fragment can be deleted, because enable/disable_timeout() is used only at limited places in postgres.c, so I don't see the chance of misuse.

I'd suggest leave it as it is. Because it might be possible that the
function is used in different place in the future. Or at least we
should document the pre-condition as a comment.

revised patch attached.
--
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)sraoss(dot)co(dot)jp> writes:
>> * The difference is that the Execute message stops the statement_timeout timer,

> No. Parse, bind and Execute message indivually stops and starts the
> statement_timeout timer with the patch.

That seems like it could represent quite a lot of added overhead,
on machines where gettimeofday() is slow ... which is still a lot
of them, unfortunately.

regards, tom lane

> That seems like it could represent quite a lot of added overhead,
> on machines where gettimeofday() is slow ... which is still a lot
> of them, unfortunately.

Maybe. I think we could eliminate restarting the timer for parse and
bind.

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

On 2017-04-03 23:31:59 +0900, Tatsuo Ishii wrote:
> > That seems like it could represent quite a lot of added overhead,
> > on machines where gettimeofday() is slow ... which is still a lot
> > of them, unfortunately.
>
> Maybe. I think we could eliminate restarting the timer for parse and
> bind.

I've moved this patch to the next CF - it's been submitted fairly late
in the v10 cycle and there's obviously design work ongoing.

- Andres

From: pgsql-hackers-owner(at)postgresql(dot)org
> [mailto:pgsql-hackers-owner(at)postgresql(dot)org] On Behalf Of Tatsuo Ishii
> No. Parse, bind and Execute message indivually stops and starts the
> statement_timeout timer with the patch. Unless there's a lock conflict,
> parse and bind will take very short time. So actually users could only
> observe the timeout in execute message though.

Where is the statement_timeout timer stopped when processing Parse and Bind messages? Do you mean the following sequence of operations are performed in this patch?

Parse(statement1)
start timer
stop timer
Bind(statement1, portal1)
start timer
stop timer
Execute(portal1)
start timer
stop timer
Sync

It looks like the patch does the following. I think this is desirable, because starting and stopping the timer for each message may be costly as Tom said.

Parse(statement1)
start timer
Bind(statement1, portal1)
Execute(portal1)
stop timer
Sync

> > (3)
> > + /*
> > + * Sanity check
> > + */
> > + if (!xact_started)
> > + {
> > + ereport(ERROR,
> > +
> (errcode(ERRCODE_INVALID_PARAMETER_VALUE),
> > + errmsg("Transaction
> must have been already started to set statement timeout")));
> > + }
> >
> > I think this fragment can be deleted, because enable/disable_timeout()
> is used only at limited places in postgres.c, so I don't see the chance
> of misuse.
>
> I'd suggest leave it as it is. Because it might be possible that the function
> is used in different place in the future. Or at least we should document
> the pre-condition as a comment.

OK, I favor documenting to reduce code, but I don't have a strong opinion. I'd like to leave this to the committer. One thing to note is that you can remove { and } in the following code like other places.

+ if (!xact_started)
+ {
+ ereport(ERROR,
+ (errcode(ERRCODE_INVALID_PARAMETER_VALUE),
+ errmsg("Transaction must have been already started to set statement timeout")));
+ }

Regards
Takayuki Tsunakawa

> Where is the statement_timeout timer stopped when processing Parse and Bind messages?

Actually the statement timer is replaced with new statement timer
value in enable_statement_timeout().

> Do you mean the following sequence of operations are performed in this patch?
>
> Parse(statement1)
> start timer
> stop timer
> Bind(statement1, portal1)
> start timer
> stop timer
> Execute(portal1)
> start timer
> stop timer
> Sync

Yes.

> It looks like the patch does the following. I think this is desirable, because starting and stopping the timer for each message may be costly as Tom said.
> Parse(statement1)
> start timer
> Bind(statement1, portal1)
> Execute(portal1)
> stop timer
> Sync

This doesn't work in general use cases. Following pattern appears
frequently in applications.

Parse(statement1)
Bind(statement1, portal1)
Execute(portal1)
Bind(statement1, portal1)
Execute(portal1)
:
:
Sync

Also what would happen if client just send a parse message and does
nothing after that?

So I think following is better:

Parse(statement1)
Bind(statement1, portal1)
Execute(portal1)
start timer
stop timer
Bind(statement1, portal1)
Execute(portal1)
start timer
stop timer
:
:
Sync

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

From: pgsql-hackers-owner(at)postgresql(dot)org
> [mailto:pgsql-hackers-owner(at)postgresql(dot)org] On Behalf Of Tatsuo Ishii
> Actually the statement timer is replaced with new statement timer value
> in enable_statement_timeout().

The patch doesn't seem to behave like that. The Parse message calls start_xact_command() -> enable_statement_timeout() -> enable_timeout(), and set stmt_timer_started to true. Subsequent Bind and Execute messages call enable_statement_timeout(), but enable_statement_timeout() doesn't call enable_timeout() because stmt_timer_started is already true.

> > It looks like the patch does the following. I think this is desirable,
> because starting and stopping the timer for each message may be costly as
> Tom said.
> > Parse(statement1)
> > start timer
> > Bind(statement1, portal1)
> > Execute(portal1)
> > stop timer
> > Sync

I ran one INSERT statement using JDBC with log_min_messages = DEBUG3, and the server log shows what I said.

DEBUG: parse <unnamed>: insert into a values(2)
DEBUG: Set statement timeout
LOG: duration: 0.431 ms parse <unnamed>: insert into a values(2)
DEBUG: bind <unnamed> to <unnamed>
LOG: duration: 0.127 ms bind <unnamed>: insert into a values(2)
DEBUG: Disable statement timeout
LOG: duration: 0.184 ms execute <unnamed>: insert into a values(2)
DEBUG: snapshot of 1+0 running transaction ids (lsn 0/163BF28 oldest xid 561 latest complete 560 next xid 562)

> This doesn't work in general use cases. Following pattern appears frequently
> in applications.
>
> Parse(statement1)
> Bind(statement1, portal1)
> Execute(portal1)
> Bind(statement1, portal1)
> Execute(portal1)
> :
> :
> Sync

It works. The first Parse-Bind-Execute is measured as one unit, then subsequent Bind-Execute pairs are measured as other units. That's because each Execute ends the statement_timeout timer and the Bind message starts it again. I think this is desirable, so the current patch looks good. May I mark this as ready for committer? FYI, make check-world passed successfully.

> Also what would happen if client just send a parse message and does nothing
> after that?

It's correct to trigger the statement timeout in this case, because the first SQL statement started (with the Parse message) and its execution is not finished (with Execute message.)

Regards
Takayuki Tsunakawa

> The patch doesn't seem to behave like that. The Parse message calls start_xact_command() -> enable_statement_timeout() -> enable_timeout(), and set stmt_timer_started to true. Subsequent Bind and Execute messages call enable_statement_timeout(), but enable_statement_timeout() doesn't call enable_timeout() because stmt_timer_started is already true.
>
>
>> > It looks like the patch does the following. I think this is desirable,
>> because starting and stopping the timer for each message may be costly as
>> Tom said.
>> > Parse(statement1)
>> > start timer
>> > Bind(statement1, portal1)
>> > Execute(portal1)
>> > stop timer
>> > Sync
>
> I ran one INSERT statement using JDBC with log_min_messages = DEBUG3, and the server log shows what I said.
>
> DEBUG: parse <unnamed>: insert into a values(2)
> DEBUG: Set statement timeout
> LOG: duration: 0.431 ms parse <unnamed>: insert into a values(2)
> DEBUG: bind <unnamed> to <unnamed>
> LOG: duration: 0.127 ms bind <unnamed>: insert into a values(2)
> DEBUG: Disable statement timeout
> LOG: duration: 0.184 ms execute <unnamed>: insert into a values(2)
> DEBUG: snapshot of 1+0 running transaction ids (lsn 0/163BF28 oldest xid 561 latest complete 560 next xid 562)

Check.

>> This doesn't work in general use cases. Following pattern appears frequently
>> in applications.
>>
>> Parse(statement1)
>> Bind(statement1, portal1)
>> Execute(portal1)
>> Bind(statement1, portal1)
>> Execute(portal1)
>> :
>> :
>> Sync
>
> It works. The first Parse-Bind-Execute is measured as one unit, then subsequent Bind-Execute pairs are measured as other units. That's because each Execute ends the statement_timeout timer and the Bind message starts it again. I think this is desirable, so the current patch looks good. May I mark this as ready for committer? FYI, make check-world passed successfully.

It's too late. Someone has already moved the patch to the next CF (for
PostgreSQL 11).

>> Also what would happen if client just send a parse message and does nothing
>> after that?
>
> It's correct to trigger the statement timeout in this case, because the first SQL statement started (with the Parse message) and its execution is not finished (with Execute message.)
>
>
> Regards
> Takayuki Tsunakawa
>
>
>

From: Tatsuo Ishii [mailto:ishii(at)sraoss(dot)co(dot)jp]
> It's too late. Someone has already moved the patch to the next CF (for
> PostgreSQL 11).

Yes, but this patch will be necessary by the final release of PG 10 if the libpq batch/pipelining is committed in PG 10.

I marked this as ready for committer in the next CF, so that some committer can pick up this patch and consider putting it in PG 10. If you decide to modify the patch, please change the status.

Regards
Takayuki Tsunakawa

On 2017-04-04 06:18:04 +0000, Tsunakawa, Takayuki wrote:
> From: Tatsuo Ishii [mailto:ishii(at)sraoss(dot)co(dot)jp]
> > It's too late. Someone has already moved the patch to the next CF (for
> > PostgreSQL 11).
>
> Yes, but this patch will be necessary by the final release of PG 10 if the libpq batch/pipelining is committed in PG 10.
>
> I marked this as ready for committer in the next CF, so that some committer can pick up this patch and consider putting it in PG 10. If you decide to modify the patch, please change the status.

Given the concern raised in http://archives.postgresql.org/message-id/12207.1491228316%40sss.pgh.pa.us
I don't see this being ready for committer.

- Andres

From: Andres Freund [mailto:andres(at)anarazel(dot)de]
Given the concern raised in
> http://archives.postgresql.org/message-id/12207.1491228316%40sss.pgh.p
> a.us
> I don't see this being ready for committer.

If what Tatsuo-san said to Tom is correct (i.e. each Parse/Bind/Execute starts and stops the timer), then it's a concern and the patch should not be ready for committer. However, the current patch is not like that -- it seems to do what others in this thread are expecting.

Regards
Takayuki Tsunakawa

On 2017-04-04 06:35:00 +0000, Tsunakawa, Takayuki wrote:
> From: Andres Freund [mailto:andres(at)anarazel(dot)de]
> Given the concern raised in
> > http://archives.postgresql.org/message-id/12207.1491228316%40sss.pgh.p
> > a.us
> > I don't see this being ready for committer.
>
> If what Tatsuo-san said to Tom is correct (i.e. each Parse/Bind/Execute starts and stops the timer), then it's a concern and the patch should not be ready for committer. However, the current patch is not like that -- it seems to do what others in this thread are expecting.

Oh, interesting - I kind of took the author's statement as, uh,
authoritative ;). A quick look over the patch confirms your
understanding.

I think the code needs a few clarifying comments around this, but
otherwise seems good. Not restarting the timeout in those cases
obviously isn't entirely "perfect"/"correct", but a tradeoff - the
comments should note that.

Tatsuo-san, do you want to change those, and push? I can otherwise.

Unfortunately I can't move the patch back to the current CF, but I guess
we can just mark it as committed in the next.

- Andres

>> If what Tatsuo-san said to Tom is correct (i.e. each Parse/Bind/Execute starts and stops the timer), then it's a concern and the patch should not be ready for committer. However, the current patch is not like that -- it seems to do what others in this thread are expecting.
>
> Oh, interesting - I kind of took the author's statement as, uh,
> authoritative ;). A quick look over the patch confirms your
> understanding.

Yes, Tsunakawa-san is correct. Sorry for confusion.

> I think the code needs a few clarifying comments around this, but
> otherwise seems good. Not restarting the timeout in those cases
> obviously isn't entirely "perfect"/"correct", but a tradeoff - the
> comments should note that.
>
> Tatsuo-san, do you want to change those, and push? I can otherwise.

Andres,

If you don't mind, could you please fix the comments and push it.

> Unfortunately I can't move the patch back to the current CF, but I guess
> we can just mark it as committed in the next.

That will be great.

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

Andres,

>> I think the code needs a few clarifying comments around this, but
>> otherwise seems good. Not restarting the timeout in those cases
>> obviously isn't entirely "perfect"/"correct", but a tradeoff - the
>> comments should note that.
>>
>> Tatsuo-san, do you want to change those, and push? I can otherwise.
>
> Andres,
>
> If you don't mind, could you please fix the comments and push it.

I have changed the comments as you suggested. If it's ok, I can push
the patch myself (today I have time to work on this).

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

On 2017-04-04 16:10:32 +0900, Tatsuo Ishii wrote:
> >> If what Tatsuo-san said to Tom is correct (i.e. each Parse/Bind/Execute starts and stops the timer), then it's a concern and the patch should not be ready for committer. However, the current patch is not like that -- it seems to do what others in this thread are expecting.
> >
> > Oh, interesting - I kind of took the author's statement as, uh,
> > authoritative ;). A quick look over the patch confirms your
> > understanding.
>
> Yes, Tsunakawa-san is correct. Sorry for confusion.
>
> > I think the code needs a few clarifying comments around this, but
> > otherwise seems good. Not restarting the timeout in those cases
> > obviously isn't entirely "perfect"/"correct", but a tradeoff - the
> > comments should note that.
> >
> > Tatsuo-san, do you want to change those, and push? I can otherwise.
>
> Andres,
>
> If you don't mind, could you please fix the comments and push it.

Hm. I started to edit it, but I'm halfway coming back to my previous
view that this isn't necessarily ready.

If a client were to to prepare a large number of prepared statements
(i.e. a lot of parse messages), this'll only start the timeout once, at
the first statement sent. It's not an issue for libpq which sends a
sync message after each PQprepare, nor does it look to be an issue for
pgjdbc based on a quick look.

Does anybody think there might be a driver out there that sends a bunch
of 'parse' messages, without syncs?

- Andres

On 2017-04-05 08:34:43 +0900, Tatsuo Ishii wrote:
> Andres,
>
> >> I think the code needs a few clarifying comments around this, but
> >> otherwise seems good. Not restarting the timeout in those cases
> >> obviously isn't entirely "perfect"/"correct", but a tradeoff - the
> >> comments should note that.
> >>
> >> Tatsuo-san, do you want to change those, and push? I can otherwise.
> >
> > Andres,
> >
> > If you don't mind, could you please fix the comments and push it.
>
> I have changed the comments as you suggested. If it's ok, I can push
> the patch myself (today I have time to work on this).

I'm working on the patch, and I've edited it more heavily, so please
hold off.

Changes:
I don't think the debugging statements are a good idea, the
!xact_started should be an assert, and disable_timeout should be called
from within enable_statement_timeout independent of stmt_timer_started.

But more importantly I had just sent a question that I think merits
discussion.

- Andres

On 2017-04-04 16:38:53 -0700, Andres Freund wrote:
> On 2017-04-04 16:10:32 +0900, Tatsuo Ishii wrote:
> > >> If what Tatsuo-san said to Tom is correct (i.e. each Parse/Bind/Execute starts and stops the timer), then it's a concern and the patch should not be ready for committer. However, the current patch is not like that -- it seems to do what others in this thread are expecting.
> > >
> > > Oh, interesting - I kind of took the author's statement as, uh,
> > > authoritative ;). A quick look over the patch confirms your
> > > understanding.
> >
> > Yes, Tsunakawa-san is correct. Sorry for confusion.
> >
> > > I think the code needs a few clarifying comments around this, but
> > > otherwise seems good. Not restarting the timeout in those cases
> > > obviously isn't entirely "perfect"/"correct", but a tradeoff - the
> > > comments should note that.
> > >
> > > Tatsuo-san, do you want to change those, and push? I can otherwise.
> >
> > Andres,
> >
> > If you don't mind, could you please fix the comments and push it.
>
> Hm. I started to edit it, but I'm halfway coming back to my previous
> view that this isn't necessarily ready.
>
> If a client were to to prepare a large number of prepared statements
> (i.e. a lot of parse messages), this'll only start the timeout once, at
> the first statement sent. It's not an issue for libpq which sends a
> sync message after each PQprepare, nor does it look to be an issue for
> pgjdbc based on a quick look.
>
> Does anybody think there might be a driver out there that sends a bunch
> of 'parse' messages, without syncs?

Looks to me like npgsql doesn't do that either. None of libpq, pgjdbs
and npgsql doing it seems like some evidence that it's ok.

- Andres

From: Andres Freund [mailto:andres(at)anarazel(dot)de]
> Looks to me like npgsql doesn't do that either. None of libpq, pgjdbs and
> npgsql doing it seems like some evidence that it's ok.

And psqlODBC now uses always libpq.

Now time for final decision?

Regards
Takayuki Tsunakawa

On 2017-04-04 23:52:28 +0000, Tsunakawa, Takayuki wrote:
> From: Andres Freund [mailto:andres(at)anarazel(dot)de]
> > Looks to me like npgsql doesn't do that either. None of libpq, pgjdbs and
> > npgsql doing it seems like some evidence that it's ok.
>
> And psqlODBC now uses always libpq.
>
> Now time for final decision?

I'll send an updated patch in a bit, and then will wait till tomorrow to
push. Giving others a chance to chime in seems fair.

- Andres

> Hm. I started to edit it, but I'm halfway coming back to my previous
> view that this isn't necessarily ready.
>
> If a client were to to prepare a large number of prepared statements
> (i.e. a lot of parse messages), this'll only start the timeout once, at
> the first statement sent. It's not an issue for libpq which sends a
> sync message after each PQprepare, nor does it look to be an issue for
> pgjdbc based on a quick look.
>
> Does anybody think there might be a driver out there that sends a bunch
> of 'parse' messages, without syncs?

What's your point of the question? What kind of problem do you expect
if the timeout starts only once at the first parse meesage out of
bunch of parse messages?

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

On 2017-04-05 10:05:19 +0900, Tatsuo Ishii wrote:
> > Hm. I started to edit it, but I'm halfway coming back to my previous
> > view that this isn't necessarily ready.
> >
> > If a client were to to prepare a large number of prepared statements
> > (i.e. a lot of parse messages), this'll only start the timeout once, at
> > the first statement sent. It's not an issue for libpq which sends a
> > sync message after each PQprepare, nor does it look to be an issue for
> > pgjdbc based on a quick look.
> >
> > Does anybody think there might be a driver out there that sends a bunch
> > of 'parse' messages, without syncs?
>
> What's your point of the question? What kind of problem do you expect
> if the timeout starts only once at the first parse meesage out of
> bunch of parse messages?

It's perfectly valid to send a lot of Parse messages without
interspersed Sync or Bind/Execute message. There'll be one timeout
covering all of those Parse messages, which can thus lead to a timeout,
even though nothing actually takes long individually.

Greetings,

Andres Freund

>> What's your point of the question? What kind of problem do you expect
>> if the timeout starts only once at the first parse meesage out of
>> bunch of parse messages?
>
> It's perfectly valid to send a lot of Parse messages without
> interspersed Sync or Bind/Execute message. There'll be one timeout
> covering all of those Parse messages, which can thus lead to a timeout,
> even though nothing actually takes long individually.

Hmm. IMO, that could happen even with the current statement timeout
implementation as well.

Or we could start/stop the timeout in exec_execute_message()
only. This could avoid the problem above. Also this is more consistent
with log_duration/log_min_duration_statement behavior than now.

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

On 2017-04-04 16:56:26 -0700, 'Andres Freund' wrote:
> On 2017-04-04 23:52:28 +0000, Tsunakawa, Takayuki wrote:
> > From: Andres Freund [mailto:andres(at)anarazel(dot)de]
> > > Looks to me like npgsql doesn't do that either. None of libpq, pgjdbs and
> > > npgsql doing it seems like some evidence that it's ok.
> >
> > And psqlODBC now uses always libpq.
> >
> > Now time for final decision?
>
> I'll send an updated patch in a bit, and then will wait till tomorrow to
> push. Giving others a chance to chime in seems fair.

Attached. I did not like that the previous patch had the timeout
handling duplicated in the individual functions, I instead centralized
it into start_xact_command(). Given that it already activated the
timeout in the most common cases, that seems to make more sense to
me. In your version we'd have called enable_statement_timeout() twice
consecutively (which behaviourally is harmless).

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.

- Andres

> On 2017-04-04 16:56:26 -0700, 'Andres Freund' wrote:
>> On 2017-04-04 23:52:28 +0000, Tsunakawa, Takayuki wrote:
>> > From: Andres Freund [mailto:andres(at)anarazel(dot)de]
>> > > Looks to me like npgsql doesn't do that either. None of libpq, pgjdbs and
>> > > npgsql doing it seems like some evidence that it's ok.
>> >
>> > And psqlODBC now uses always libpq.
>> >
>> > Now time for final decision?
>>
>> I'll send an updated patch in a bit, and then will wait till tomorrow to
>> push. Giving others a chance to chime in seems fair.
>
> Attached. I did not like that the previous patch had the timeout
> handling duplicated in the individual functions, I instead centralized
> it into start_xact_command(). Given that it already activated the
> timeout in the most common cases, that seems to make more sense to
> me. In your version we'd have called enable_statement_timeout() twice
> consecutively (which behaviourally is harmless).
>
> 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.

Ok, I will look into your patch and test it out using pgproto.

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

From: pgsql-hackers-owner(at)postgresql(dot)org
> [mailto:pgsql-hackers-owner(at)postgresql(dot)org] On Behalf Of Tatsuo Ishii
> Hmm. IMO, that could happen even with the current statement timeout
> implementation as well.
>
> Or we could start/stop the timeout in exec_execute_message() only. This
> could avoid the problem above. Also this is more consistent with
> log_duration/log_min_duration_statement behavior than now.

I think it's better to include Parse and Bind as now. Parse or Bind could take long time when the table has many partitions, the query is complex and/or very long, some DDL statement is running against a target table, or the system load is high.

Firing statement timeout during or after many Parses is not a problem, because the first Parse started running some statement and it's not finished. Plus, Andres confirmed that major client drivers don't use such a pattern. There may be an odd behavior purely from the perspective of E.Q.P, that's a compromise, which Andres meant by "not perfect but."

Regards
Takayuki Tsunakawa

Andres Freund <andres(at)anarazel(dot)de> writes:
> On 2017-04-05 10:05:19 +0900, Tatsuo Ishii wrote:
>> What's your point of the question? What kind of problem do you expect
>> if the timeout starts only once at the first parse meesage out of
>> bunch of parse messages?

> It's perfectly valid to send a lot of Parse messages without
> interspersed Sync or Bind/Execute message. There'll be one timeout
> covering all of those Parse messages, which can thus lead to a timeout,
> even though nothing actually takes long individually.

It might well be reasonable to redefine statement_timeout as limiting the
total time from the first client input to the response to Sync ... but
if that's what we're doing, let's make sure we do it consistently.

I haven't read the patch, but the comments in this thread make me fear
that it's introducing some ad-hoc, inconsistent behavior.

regards, tom lane

From: pgsql-hackers-owner(at)postgresql(dot)org
> [mailto:pgsql-hackers-owner(at)postgresql(dot)org] On Behalf Of 'Andres Freund'
> Attached. I did not like that the previous patch had the timeout handling
> duplicated in the individual functions, I instead centralized it into
> start_xact_command(). Given that it already activated the timeout in the
> most common cases, that seems to make more sense to me. In your version
> we'd have called enable_statement_timeout() twice consecutively (which
> behaviourally is harmless).
>
> 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.

The patch looks good and cleaner. It looks like the code works as expected. As before, I ran one INSERT statement with PgJDBC, with gdb's breakpoints set on enable_timeout() and disable_timeout(). I confirmed that enable_timeout() is called just once at Parse message, and disable_timeout() is called just once at Execute message.

I'd like to wait for Tatsuo-san's thorough testing with pgproto.

Regards
Takayuki Tsunakawa

>> 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.
>
> The patch looks good and cleaner. It looks like the code works as expected. As before, I ran one INSERT statement with PgJDBC, with gdb's breakpoints set on enable_timeout() and disable_timeout(). I confirmed that enable_timeout() is called just once at Parse message, and disable_timeout() is called just once at Execute message.
>
> I'd like to wait for Tatsuo-san's thorough testing with pgproto.

I have done tests using pgproto. One thing I noticed a strange
behavior. Below is an output of pgproto. The test first set the
timeout to 3 seconds, and parse/bind for "SELECT pg_sleep(2)" then set
timeout to 1 second using extended query. Subsequent Execute emits a
statement timeout error as expected, but next "SELECT pg_sleep(2)"
call using extended query does not emit a statement error. The test
for this is "007-timeout-twice". Attached is the test cases including
this.

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
<= 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 2968 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

From: pgsql-hackers-owner(at)postgresql(dot)org
> [mailto:pgsql-hackers-owner(at)postgresql(dot)org] On Behalf Of Tatsuo Ishii
> I have done tests using pgproto. One thing I noticed a strange behavior.
> Below is an output of pgproto. The test first set the timeout to 3 seconds,
> and parse/bind for "SELECT pg_sleep(2)" then set timeout to 1 second using
> extended query. Subsequent Execute emits a statement timeout error as
> expected, but next "SELECT pg_sleep(2)"
> call using extended query does not emit a statement error. The test for
> this is "007-timeout-twice". Attached is the test cases including this.

What's the handling of transactions like in pgproto? I guess the first statement timeout error rolled back the effect of "SET statement_timeout = '1s'", and the timeout reverted to 3s or some other value.

Regards
Takayuki Tsunakawa

> From: pgsql-hackers-owner(at)postgresql(dot)org
>> [mailto:pgsql-hackers-owner(at)postgresql(dot)org] On Behalf Of Tatsuo Ishii
>> I have done tests using pgproto. One thing I noticed a strange behavior.
>> Below is an output of pgproto. The test first set the timeout to 3 seconds,
>> and parse/bind for "SELECT pg_sleep(2)" then set timeout to 1 second using
>> extended query. Subsequent Execute emits a statement timeout error as
>> expected, but next "SELECT pg_sleep(2)"
>> call using extended query does not emit a statement error. The test for
>> this is "007-timeout-twice". Attached is the test cases including this.
>
> What's the handling of transactions like in pgproto? I guess the first statement timeout error rolled back the effect of "SET statement_timeout = '1s'", and the timeout reverted to 3s or some other value.

Since pgproto is a dumb protocol machine, it does not start a
transaction automatically (user needs to explicitly send a start
transaction command via either simple or extended query). In this
particular case no explicit transaction has started.

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

From: pgsql-hackers-owner(at)postgresql(dot)org
> [mailto:pgsql-hackers-owner(at)postgresql(dot)org] On Behalf Of Tatsuo Ishii
> Since pgproto is a dumb protocol machine, it does not start a transaction
> automatically (user needs to explicitly send a start transaction command
> via either simple or extended query). In this particular case no explicit
> transaction has started.
>

Then, the following sequence should have occurred. The test result is valid.

# Execute statement which takes 2 seconds.
'P' "S1" "SELECT pg_sleep(2)" 0
-> start transaction T1
'B' "S2" "S1" 0 0 0

'P' "" "SET statement_timeout = '1s'" 0
'B' "" "" 0 0 0
'E' "" 0

# Execute statement which takes 2 seconds (statement timeout expected).
'E' "S2" 0
-> timeout error occurred, T1 aborted

# Issue Sync message
'S'
-> rolled back T1, so statement_timeout reverted to 3s

# Receive response from backend
'Y'

# Execute statement which takes 2 seconds (statement timeout expected).
'P' "S3" "SELECT pg_sleep(2)" 0
-> start transaction T2
'B' "S2" "S3" 0 0 0
'E' "S2" 0

# Issue Sync message
'S'
-> committed T2

Regards
Takayuki Tsunakawa

On 2017-04-05 00:39:51 -0400, Tom Lane wrote:
> Andres Freund <andres(at)anarazel(dot)de> writes:
> > On 2017-04-05 10:05:19 +0900, Tatsuo Ishii wrote:
> >> What's your point of the question? What kind of problem do you expect
> >> if the timeout starts only once at the first parse meesage out of
> >> bunch of parse messages?
>
> > It's perfectly valid to send a lot of Parse messages without
> > interspersed Sync or Bind/Execute message. There'll be one timeout
> > covering all of those Parse messages, which can thus lead to a timeout,
> > even though nothing actually takes long individually.
>
> It might well be reasonable to redefine statement_timeout as limiting the
> total time from the first client input to the response to Sync ...

That's actually the current behaviour. start_xact_command arms the timer
in the !xact_started case, and only finish_xact_command() disarms it.
finish_xact_command() is issued for Sync messsages and simple statements.

I brought the case up because what we're discussing is changing things
so Execute resets the clock (more precisely disables it, and have it
reenabled later). So it'd be "fixed" for pipelined Execute statements,
but not for pipelined Parses. Changing things so that Parse/Bind also
reset the timing would increase overhead - and it'd not be useful in
practice, because Sync's are sent by the drivers that support
pipelining when statements are prepared.

> but
> if that's what we're doing, let's make sure we do it consistently.
> I haven't read the patch, but the comments in this thread make me fear
> that it's introducing some ad-hoc, inconsistent behavior.

I'm a bit worried too due to the time constraints here, but I think
resetting the clock at Execute too actually makes a fair amount sense.

Greetings,

Andres Freund

> Then, the following sequence should have occurred. The test result is valid.

Yes, I remembered that and was about to make a posting :-)

> # Execute statement which takes 2 seconds.
> 'P' "S1" "SELECT pg_sleep(2)" 0
> -> start transaction T1
> 'B' "S2" "S1" 0 0 0

Yes, an extended query automatically starts a transaction if there's
no ongoing transaction.

> 'P' "" "SET statement_timeout = '1s'" 0
> 'B' "" "" 0 0 0
> 'E' "" 0
>
> # Execute statement which takes 2 seconds (statement timeout expected).
> 'E' "S2" 0
> -> timeout error occurred, T1 aborted

Right. The automatically started transaction is aborted and the effect
of the set statement is canceled.

In summary, as far as I know Andres's patch is working as expected.

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

Andres Freund <andres(at)anarazel(dot)de> writes:
> On 2017-04-05 00:39:51 -0400, Tom Lane wrote:
>> but
>> if that's what we're doing, let's make sure we do it consistently.
>> I haven't read the patch, but the comments in this thread make me fear
>> that it's introducing some ad-hoc, inconsistent behavior.

> I'm a bit worried too due to the time constraints here, but I think
> resetting the clock at Execute too actually makes a fair amount sense.

Meh. Two days before feature freeze is not the time to be introducing
a rushed redefinition of the wire protocol --- and let's not fool
ourselves, that is what this amounts to. Let's push this out to v11
and think about it more carefully.

regards, tom lane

On 2017-04-05 09:46:31 -0400, Tom Lane wrote:
> Andres Freund <andres(at)anarazel(dot)de> writes:
> > On 2017-04-05 00:39:51 -0400, Tom Lane wrote:
> >> but
> >> if that's what we're doing, let's make sure we do it consistently.
> >> I haven't read the patch, but the comments in this thread make me fear
> >> that it's introducing some ad-hoc, inconsistent behavior.
>
> > I'm a bit worried too due to the time constraints here, but I think
> > resetting the clock at Execute too actually makes a fair amount sense.
>
> Meh. Two days before feature freeze is not the time to be introducing
> a rushed redefinition of the wire protocol --- and let's not fool
> ourselves, that is what this amounts to. Let's push this out to v11
> and think about it more carefully.

What I was trying to say is that I think the change makes sense and
isn't particularly ad-hoc, but that I don't think we need to force this
for v10.

Greetings,

Andres Freund

> 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

Andres,

If you don't mind, can you please commit/push the patch?

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

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

Hi,

On 2017-09-11 09:10:49 +0900, Tatsuo Ishii wrote:
> If you don't mind, can you please commit/push the patch?

Ok, will do so.

Greetings,

Andres Freund

On 2017-09-10 17:12:19 -0700, Andres Freund wrote:
> On 2017-09-11 09:10:49 +0900, Tatsuo Ishii wrote:
> > If you don't mind, can you please commit/push the patch?
>
> Ok, will do so.

And, done. Thanks for patch and reminder!

- Andres

> On 2017-09-10 17:12:19 -0700, Andres Freund wrote:
>> On 2017-09-11 09:10:49 +0900, Tatsuo Ishii wrote:
>> > If you don't mind, can you please commit/push the patch?
>>
>> Ok, will do so.
>
> And, done. Thanks for patch and reminder!

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