Re: idle_in_transaction_timeout

On 2014-06-29 17:28:06 -0400, Tom Lane wrote:
> Andres Freund <andres(at)2ndquadrant(dot)com> writes:
> > On 2014-06-29 15:48:15 -0400, Tom Lane wrote:
> >> Robert Haas <robertmhaas(at)gmail(dot)com> writes:
> >>> Yeah, I think someone should do some analysis of whether this is
> >>> adding gettimeofday() calls, and how many, and what the performance
> >>> implications are.
>
> >> I believe that as the patch stands, we'd incur one new gettimeofday()
> >> per query-inside-a-transaction, inside the enable_timeout_after() call.
> >> (I think the disable_timeout() call would not result in a gettimeofday
> >> call, since there would be no remaining live timeout events.)
> >>
> >> We could possibly refactor enough to share the clock reading with the call
> >> done in pgstat_report_activity. Not sure how ugly that would be or
> >> whether it's worth the trouble. Note that in the not-a-transaction-block
> >> case, we already have got two gettimeofday calls in this sequence, one in
> >> pgstat_report_stat and one in pgstat_report_activity :-(
>
> > I've seen several high throughput production servers where code around
> > gettimeofday is in the top three profile entries - so I'd be hesitant to
> > add more there. Especially as the majority of people here seems to think
> > we should enable this by default.
>
> Note that we'd presumably also be adding two kernel calls associated
> with setting/killing the SIGALRM timer. I'm not sure how much those
> cost, but it likely wouldn't be negligible compared to the gettimeofday
> cost.

It's probably higher, at least if we get around to replacing
gettimeofday() with clock_gettime() :(

So, i've traced a SELECT 1. We're currently doing:
1) gettimeofday() in SetCurrentStatementStartTimestamp
2) gettimeofday() pgstat_report_activity()
3) gettimeofday() for enable_timeout_after (id=STATEMENT_TIMEOUT)
4) setitimer() for schedule_alarm for STATEMENT_TIMEOUT
5) gettimeofday() for pgstat_report_activity()

Interestingly recvfrom(), setitimer(), sendto() are the only calls to
actually fully hit the kernel via syscalls (i.e. visible via strace).

The performance difference of setting up statement_timeout=10s for a
pgbench run that does:
\setrandom aid 1 1000000
SELECT * FROM pgbench_accounts WHERE aid = :aid;
is 164850.368336 (no statment_timeout) vs 157866.924725
(statement_timeout=10s). That's the best of 10 10s runs.
for SELECT 1 it's 242846.348628 vs 236764.177593.

Not too bad. Absolutely bleeding edge kernel/libc though; I seem to
recall different results with earlier libc/kernel combos.

I think statement_timeout's overhead should be fairly similar to what's
proposed for iit_t?

> A thought that comes to mind in connection with that is whether we
> shouldn't be doing the ReadyForQuery call (which I believe includes
> fflush'ing the previous query response out to the client) before
> rather than after all this statistics housekeeping. Then at least
> we'd have a shot at spending these cycles in parallel with the
> network I/O and client think-time, rather than serializing it all.

Worth a try. It'd be also rather neat to to consolidate the first three
gettimeofday()'s above. Afaics they should all be consolidated via
GetCurrentTransactionStartTimestamp()...

Greetings,

Andres Freund

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