Re: Statement timeout behavior in extended queries

From: "Tsunakawa, Takayuki" <tsunakawa(dot)takay(at)jp(dot)fujitsu(dot)com>
To: 'Tatsuo Ishii' <ishii(at)sraoss(dot)co(dot)jp>
Cc: "david(at)fetter(dot)org" <david(at)fetter(dot)org>, "pgsql-hackers(at)postgresql(dot)org" <pgsql-hackers(at)postgresql(dot)org>
Subject: Re: Statement timeout behavior in extended queries
Date: 2017-04-04 05:24:40
Message-ID: 0A3221C70F24FB45833433255569204D1F6BFE04@G01JPEXMBYT05
Views: Raw Message | Whole Thread | Download mbox | Resend email
Thread:
Lists: pgsql-hackers

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

In response to

Responses

Browse pgsql-hackers by date

  From Date Subject
Next Message Amit Khandekar 2017-04-04 05:28:32 Re: Parallel Append implementation
Previous Message Amit Langote 2017-04-04 05:20:33 Re: ANALYZE command progress checker