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@2ndQuadrant.com   Baltimore, MD
PostgreSQL Training, Services, and 24x7 Support  www.2ndQuadrant.us