Re: EXPLAIN ANALYZE much slower than running query normally

"Chris Hutchinson" <chris(at)hutchinsonsoftware(dot)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