Re: Timing overhead and Linux clock sources

On 12/06/2011 10:20 PM, Robert Haas wrote:
> EXPLAIN ANALYZE is extremely
> expensive mostly because it's timing entry and exit into every plan
> node, and the way our executor works, those are very frequent
> operations.

The plan for the query I was timing looks like this:

Aggregate (cost=738.00..738.01 rows=1 width=0) (actual
time=3.045..3.045 rows=1 loops=1)
-> Seq Scan on customers (cost=0.00..688.00 rows=20000 width=0)
(actual time=0.002..1.700 rows=20000 loops=1)

That's then 20000 * 2 timing calls for the Seq Scan dominating the
runtime. On the system with fast TSC, the fastest execution was
1.478ms, the slowest with timing 2.945ms. That's 1.467ms of total
timing overhead, worst-case, so approximately 37ns per timing call. If
you're executing something that is only ever hitting data in
shared_buffers, you can measure that; any other case, probably not.

Picking apart the one with slow timing class on my laptop, fastest is
5.52ms, and the fastest with timing is 57.959ms. That makes for a
minimum of 1311ns per timing call, best-case.

> I'm not sure about buffer I/Os - on a big sequential scan, you might do quite a lot of those in a pretty
> tight loop.

To put this into perspective relative to the number of explain time
calls, there are 488 pages in the relation my test is executing again.

I think we need to be careful to keep timing calls from happening at
every buffer allocation. I wouldn't expect sprinkling one around every
buffer miss would be a problem on a system with a fast clocksource. And
that is what was shown by the testing Ants Aasma did before submitting
the "add timing of buffer I/O requests" patch; his results make more
sense to me now. He estimated 22ns per gettimeofday on the system with
fast timing calls--presumably using TSC, and possibly faster than I saw
because his system had less cores than mine to worry about. He got 990
ns on his slower system, and a worst case there of 3% overhead.

Whether people who are on one of these slower timing call systems would
be willing to pay 3% overhead is questionable. But I now believe Ants's
claim that it's below the noise level on ones with a good TSC driven
timer. I got a 35:1 ratio between fast and slow clock sources, he got
45:1. If we try to estimate the timing overhead that is too small to
measure, I'd guess it's ~3% / >30 = <0.1%. I'd just leave that on all
the time on a good TSC-driven system. Buffer hits and tuple-level
operations you couldn't afford to time, just about anything else would
be fine.

> One random thought: I wonder if there's a way for us to just time
> every N'th event or something like that, to keep the overhead low.
>

I'm predicting we got a lot of future demand for instrumentation
features like this, where we want to make them available but would like
to keep them from happening too often when the system is busy. Tossing
a percentage of them might work. Caching them in queue somewhere for
processing by a background process, and not collecting the data, if that
queue fills is another idea I've been thinking about recently. I'm
working on some ideas for making "is the server busy?" something you can
ask the background writer usefully too. There's a number of things that
become practical for that process to do, when it's decoupled from doing
the checkpoint sync job so its worst-case response time is expected to
tighten up.

--
Greg Smith 2ndQuadrant US greg(at)2ndQuadrant(dot)com Baltimore, MD
PostgreSQL Training, Services, and 24x7 Support www.2ndQuadrant.us