Thread: 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