Re: Understanding EXPLAIN ANALYZE output

On Wednesday February 9 2005 2:21, Tom Lane wrote:
> "Ed L." <pgsql(at)bluepolka(dot)net> writes:
> >
> > 21 -> Nested Loop (cost=0.00..108.85 rows=1
> > width=1196) (actual time=4769.59..4769.59 rows=0 loops=1) 22
> > -> Nested Loop (cost=0.00..64.78 rows=4 width=131)
> > (actual time=0.41..72.80 rows=1014 loops=1) ...
> > 34 -> Index Scan using
> > idx_queryoutcome_occurrencehistory_key on queryoutcome
> > (cost=0.00..10.28 rows=28 width=1065) (actual
> > time=4.63..4.63 rows=0 loops=1014) 35 Index
> > Cond: ("outer"."key" = queryoutcome.occurrencehistory_key)
> >
> > If I understand these correctly, line 22's nested loop
> > finished returning the last row 72.80ms into the query, and
> > then line 21's nested loop returns its 0 rows 4769.59ms into
> > the query.
>
> No, you don't understand correctly. The numbers are not "time
> into the query", they are "elapsed time spent within this node
> and its children". The above says that we spent a total of
> 72.80 msec executing line 22 and its children, and a total of
> 4.63*1014 msec executing line 34 (which has no children, so
> that's all in the indexscan). That adds up to 4767.62 msec,
> so the actual joining at line 21 took only 1.97 msec. None of
> this tells you anything about how far "into the query" all
> this stuff happened. It is however clear that line 34 is the
> bulk of the time.

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?

Ed