Обсуждение: EXPLAIN ANALYZE much slower than running query normally

Running a trivial query in v7.4.2 (installed with fedora core2) using
EXPLAIN ANALYZE is taking considerably longer than just running the query
(2mins vs 6 secs). I was using this query to quickly compare a couple of
systems after installing a faster disk.

Is this sort of slowdown to be expected?

Here's the query:
----------------------------------------
[chris@fedora tmp]$ time psql dbt << ENDSQL
> select count(*) from etab;
> ENDSQL
  count
---------
 9646782
(1 row)


real    0m6.532s
user    0m0.005s
sys     0m0.002s
[chris@fedora tmp]$ time psql dbt << ENDSQL
> explain analyze select count(*) from etab;
> ENDSQL
                                                       QUERY PLAN

----------------------------------------------------------------------------
---------------
-----------------------------
 Aggregate  (cost=182029.78..182029.78 rows=1 width=0) (actual
time=112701.488..112701.493
rows=1 loops=1)
   ->  Seq Scan on etab  (cost=0.00..157912.82 rows=9646782 width=0) (actual
time=0.053..578
59.120 rows=9646782 loops=1)
 Total runtime: 112701.862 ms
(3 rows)


real    1m52.716s
user    0m0.003s
sys     0m0.005s
---------------------------------------

Thanks in advance for any clues.

Chris Hutchinson

Am Dienstag, 5. Oktober 2004 08:49 schrieb Chris Hutchinson:
> Running a trivial query in v7.4.2 (installed with fedora core2) using
> EXPLAIN ANALYZE is taking considerably longer than just running the query
> (2mins vs 6 secs). I was using this query to quickly compare a couple of
> systems after installing a faster disk.
>
> Is this sort of slowdown to be expected?

no.

did you run VACCUM ANALYZE before? you should do it after pg_restore your db
to a new filesystem

in which order did you ran the queries. If you start your server and run two
equal queries, the second one will be much faster because of some or even all
data needed to answer the query is still in the shared buffers.

janning

"Chris Hutchinson" <chris@hutchinsonsoftware.com> writes:
> Running a trivial query in v7.4.2 (installed with fedora core2) using
> EXPLAIN ANALYZE is taking considerably longer than just running the query
> (2mins vs 6 secs). I was using this query to quickly compare a couple of
> systems after installing a faster disk.

Turning on EXPLAIN ANALYZE will incur two gettimeofday() kernel calls
per row (in this particular plan), which is definitely nontrivial
overhead if there's not much I/O going on.  I couldn't duplicate your
results exactly, but I did see a test case with 2.5 million one-column
rows go from <4 seconds to 21 seconds, which makes the cost of a
gettimeofday about 3.4 microseconds on my machine (Fedora Core 3, P4
running at something over 1Ghz).  When I widened the rows to a couple
hundred bytes, the raw runtime went up to 30 seconds and the analyzed
time to 50, so the overhead per row is pretty constant, as you'd expect.

Some tests with a simple loop around a gettimeofday call yielded a value
of 2.16 microsec/gettimeofday, so there's some overhead attributable to
the EXPLAIN mechanism as well, but the kernel call is clearly the bulk
of it.

            regards, tom lane