On Wed, Feb 09, 2005 at 02:37:39PM -0700, Ed L. wrote:
> Very helpful, thanks. So time spent in that node & its children
> = first number of "actual time" * loops? That seems consistent
> with the fact that reindexing the index led to the huge speedup.
> If the second number of the "actual time" part means time
> elapsed in this node and its children until the last row was
> returned, why does it say "actual time=4.63..4.63" instead of
> "actual time=4.63..4767.62"? Would it say that if there had
> been 1 row returned instead of none?
The meaning of the times is (IIRC) derived from the numbers used in the
planning. The first number is "time to first result", the second number
is "time to last result". So if you're doing a "LIMIT 1" query, only
the first number is relevent.
The purpose of the explain output is to determine where the bottlenecks
are and as such each node only counts time spent in it and all its
subnodes. So for example a Sort node has a really high start time
(because all subnodes must complete before sorting can complete) but
the end time is shortly after because it only needs to pump out tuples.
The complication comes because nodes can be executed in their entirety
repeatedly, especially with nested joins, the inner loop is repeatedly
executed with different parameters. I was one of the major contributers
of this feature originally and there was discussion about how to
represent this. I think the rationale is that the figures should not
appear radically different just because a Node is reexecuted a lot, so
you get an extra result "loops" and the numbers look like a single
index scan. If you look at the numbers the planner uses, it follows the
same pattern.
In general, the EXPLAIN ANALYZE output follows the planner output as
close as possible. If you look at the original query posted, it showed
an Index Scan costing 4.63..4.63 which means the index scan is taking
(on average) 4.63ms to return 1 row! If it displayed as 4000 or
something it would be a lot less clear what was going on.
Hope this helps,
--
Martijn van Oosterhout <kleptog@svana.org> http://svana.org/kleptog/
> Patent. n. Genius is 5% inspiration and 95% perspiration. A patent is a
> tool for doing 5% of the work and then sitting around waiting for someone
> else to do the other 95% so you can sue them.