Statement timeout behavior in extended queries

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.

/messages/by-id/20160528.220442.1489791680347556026.t-ishii@sraoss.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

--
Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-hackers

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.

/messages/by-id/20160528.220442.1489791680347556026.t-ishii@sraoss.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

--
Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-hackers

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

--
Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-hackers

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@sraoss.co.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

--
Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-hackers

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

--
Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-hackers

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

--
Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-hackers

From: pgsql-hackers-owner@postgresql.org

[mailto:pgsql-hackers-owner@postgresql.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

--
Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-hackers

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

--
Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-hackers

From: pgsql-hackers-owner@postgresql.org

[mailto:pgsql-hackers-owner@postgresql.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

--
Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-hackers

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

--
Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-hackers

From: Tatsuo Ishii [mailto:ishii@sraoss.co.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

--
Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-hackers

On 2017-04-04 06:18:04 +0000, Tsunakawa, Takayuki wrote:

From: Tatsuo Ishii [mailto:ishii@sraoss.co.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

--
Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-hackers

From: Andres Freund [mailto:andres@anarazel.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

--
Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-hackers

On 2017-04-04 06:35:00 +0000, Tsunakawa, Takayuki wrote:

From: Andres Freund [mailto:andres@anarazel.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

--
Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-hackers

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

--
Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-hackers

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

--
Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-hackers

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

--
Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-hackers