Understanding EXPLAIN ANALYZE output

From: "Ed L(dot)" <pgsql(at)bluepolka(dot)net>
To: pgsql-general(at)postgresql(dot)org
Subject: Understanding EXPLAIN ANALYZE output
Date: 2005-02-09 18:00:00
Message-ID: 200502091100.00799.pgsql@bluepolka.net
Views: Raw Message | Whole Thread | Download mbox | Resend email
Thread:
Lists: pgsql-general

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)
23 -> Nested Loop (cost=0.00..40.68 rows=4 width=103) (actual time=0.34..46.51 rows=1014 loops=1)
24 -> Nested Loop (cost=0.00..32.40 rows=3 width=52) (actual time=0.24..11.07 rows=689 loops=1)
25 -> Index Scan using uc_review_reviewnum on review (cost=0.00..3.85 rows=1 width=28) (actual time=0.12..0.13 rows=1 loops=1)
26 Index Cond: (reviewnum = '1890382'::bpchar)
27 -> Index Scan using idx_customerorder_review_key on customerorder (cost=0.00..27.90 rows=52 width=24) (actual time=0.11..8.07 rows=689 loops=1)
28 Index Cond: ("outer"."key" = customerorder.review_key)
29 Filter: (ordertype = 'TEST'::bpchar)
30 -> Index Scan using idx_occurrencehistory_customerorder_key on occurrencehistory (cost=0.00..3.05 rows=2 width=51) (actual time=0.02..0.04 rows=1 loops=689)
31 Index Cond: ("outer"."key" = occurrencehistory.customerorder_key)
32 -> Index Scan using pk_user on user (cost=0.00..5.80 rows=1 width=28) (actual time=0.01..0.01 rows=1 loops=1014)
33 Index Cond: ("outer".user_key = user."key")
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)
36 -> Index Scan using pk_querydefinition on querydefinition (cost=0.00..5.99 rows=1 width=58) (never executed)
37 Index Cond: ("outer".querydefinition_key = querydefinition."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.
That would seem to mean 4696.79ms were spent executing the
nested loop on line 21 prior to returning the first row.

If I got that right, how do I figure out what constitutes the
nested loop of line 21?

TIA.

Ed

Responses

Browse pgsql-general by date

  From Date Subject
Next Message Roy Souther 2005-02-09 18:29:21 EXTPROC External Procedure
Previous Message Shachar Shemesh 2005-02-09 17:32:09 Re: ADO adCmdStoredProc PlPgSql-SP Parameters