Re: Understanding EXPLAIN ANALYZE output

"Ed L." <pgsql(at)bluepolka(dot)net> writes:
> I'm trying to optimize a large query by looking at
> EXPLAIN ANALYZE output. Here's what I think may be
> the most relevant snippet:

> 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.

regards, tom lane