Re: That EXPLAIN ANALYZE patch still needs work

On Thu, 2006-06-08 at 12:56 -0400, Tom Lane wrote:
> Simon Riggs <simon(at)2ndquadrant(dot)com> writes:
> > So far we have myself, Kevin, Martijn and Luke all saying there is a
> > distortion or a massive overhead caused by EXPLAIN ANALYZE.
> > http://archives.postgresql.org/pgsql-hackers/2006-03/msg00954.php
> > http://archives.postgresql.org/pgsql-patches/2006-05/msg00168.php
>
> Given that we're seeing diametrically opposed results on the same OS
> (FC5) and similar (at least all Intel) hardware, I think the prudent
> thing is to find out what's really going on before leaping in with
> proposed solutions. As the person who's *not* seeing the problem,
> I'm not in a position to do that investigation...

That seems reasonable.

I've cut a patch to remove timing from the EA results.
Output shown here:

postgres=# set explain_analyze_timing = on;
SET
Time: 0.673 ms
postgres=# explain analyze select count(*) from accounts;
QUERY PLAN
------------------------------------------------------------------------------------------------------------------------
Aggregate (cost=2890.00..2890.01 rows=1 width=0) (actual
time=0.000..690.780 rows=1 loops=1)
-> Seq Scan on accounts (cost=0.00..2640.00 rows=100000 width=0)
(actual time=0.000..2672.562 rows=100000 loops=1)
Total runtime: 734.474 ms
(3 rows)

Time: 891.822 ms
postgres=# set explain_analyze_timing = off;
SET
Time: 0.480 ms
postgres=# explain analyze select count(*) from accounts;
QUERY PLAN
--------------------------------------------------------------------------------------------
Aggregate (cost=2890.00..2890.01 rows=1 width=0) (rows=1 loops=1)
-> Seq Scan on accounts (cost=0.00..2640.00 rows=100000 width=0)
(rows=100000 loops=1)
Total runtime: 133.674 ms
(3 rows)

Time: 134.565 ms
postgres=# select count(*) from accounts;
count
--------
100000
(1 row)

Time: 130.528 ms

So the timing is clearly responsible for the additional time I'm
personally experiencing and very likely to be that for others also.

As to why that should be the case, I'm not sure. The timing overhead
seems fairly constant on particular hardware/OS, just different for
each.

--
Simon Riggs
EnterpriseDB http://www.enterprisedb.com