Please excuse the attachment but these EXPLAIN ANALYSE were getting so
wide, email was making it hard to fight word-wrap.
The attached output is from 3 consecutive EXPLAIN ANALYSEs of the exact
same query. Each has a merge join floating somewhere within the query.
This has to be the culprit in terms of performance as this should be a
straightforward (albeit lengthy) step ladder keyed join query. The
question then becomes why chose to do merge.
Based on Tom's comment about GEQC, we then did a "set geqc to false" and
ran the query again and got great results. They too are included in the
log.
So, is GEQC broken or just misconfigured on our box? If the latter, what
is the proper config? We've made no changes from the default settings? If
the former, can I simply shut it off? Is the only time this comes into
play equate to the number of times I see the debug message appear in the
postmaster log?
Marc
----- Original Message -----
From: "Tom Lane" <[EMAIL PROTECTED]>
To: "Marc Mitchell" <[EMAIL PROTECTED]>
Cc: <[EMAIL PROTECTED]>
Sent: Thursday, November 21, 2002 1:45 PM
Subject: Re: [ADMIN] Query performanc issue - too many table?
> "Marc Mitchell" <[EMAIL PROTECTED]> writes:
> > I am having a problem with the below SQL taking an extreme amount of
time
> > to run. The problem is that the explain looks great with all index
scans.
> > But the query itself takes minutes to run. The query contains 11
tables.
> > We've found that by dropping any one table, performance reverts to
being
> > nearly instantaneous.
>
> 11 tables is the default GEQO threshold, so I'm wondering if the GEQO
> planner is missing the best plan. It's hard to tell much though without
> seeing plans for *both* queries you are comparing. EXPLAIN ANALYZE
> output would be much more useful than just EXPLAIN, too.
>
> regards, tom lane
\i report.sql
psql:report.sql:42: NOTICE: QUERY PLAN:
Nested Loop (cost=71078.34..71123.20 rows=8 width=552) (actual
time=22741.25..22741.28 rows=1 loops=1)
-> Merge Join (cost=71078.34..71099.82 rows=8 width=548) (actual
time=22740.72..22740.74 rows=1 loops=1)
-> Sort (cost=71078.34..71078.34 rows=8 width=490) (actual
time=22739.63..22739.63 rows=1 loops=1)
-> Nested Loop (cost=11547.95..71078.23 rows=8 width=490) (actual
time=19104.00..22739.46 rows=1 loops=1)
-> Nested Loop (cost=11547.95..71049.68 rows=8 width=486)
(actual time=19103.66..22739.10 rows=1 loops=1)
-> Nested Loop (cost=11547.95..71019.95 rows=8 width=320)
(actual time=19103.38..22738.82 rows=1 loops=1)
-> Nested Loop (cost=11547.95..70989.20 rows=8
width=262) (actual time=19103.05..22738.48 rows=1 loops=1)
-> Nested Loop (cost=11547.95..70959.00 rows=8
width=204) (actual time=19102.87..22738.30 rows=1 loops=1)
-> Nested Loop (cost=11547.95..70928.80
rows=8 width=142) (actual time=19102.56..22737.97 rows=1 loops=1)
-> Hash Join
(cost=11547.95..70892.21 rows=12 width=60) (actual time=19102.15..22737.55 rows=1
loops=1)
-> Hash Join
(cost=11544.92..67740.21 rows=629765 width=36) (actual time=2625.42..21917.30
rows=629614 loops=1)
-> Index Scan using
txl_fgp_uid on transloading txl (cost=0.00..29898.75 rows=629765 width=28) (actual
time=0.41..6581.90 rows=629765 loops=1)
-> Hash
(cost=9935.04..9935.04 rows=251153 width=8) (actual time=2622.99..2622.99 rows=0
loops=1)
-> Index Scan
using stp_trp_uid on trip_stop stp (cost=0.00..9935.04 rows=251153 width=8) (actual
time=0.39..1949.98 rows=251153 loops=1)
-> Hash (cost=3.03..3.03
rows=1 width=24) (actual time=0.35..0.35 rows=0 loops=1)
-> Index Scan using
trip_pkey on trip trp (cost=0.00..3.03 rows=1 width=24) (actual time=0.33..0.34
rows=1 loops=1)
-> Index Scan using
freight_group_pkey on freight_group fgp (cost=0.00..3.01 rows=1 width=82) (actual
time=0.38..0.38 rows=1 loops=1)
-> Index Scan using place_pkey on place
plc1 (cost=0.00..3.90 rows=1 width=62) (actual time=0.28..0.28 rows=1 loops=1)
-> Index Scan using place_pkey on place plc2
(cost=0.00..3.90 rows=1 width=58) (actual time=0.14..0.15 rows=1 loops=1)
-> Index Scan using trailer_pkey on trailer trl
(cost=0.00..3.97 rows=1 width=58) (actual time=0.29..0.29 rows=1 loops=1)
-> Index Scan using driver_pkey on driver dri
(cost=0.00..3.84 rows=1 width=166) (actual time=0.23..0.23 rows=1 loops=1)
-> Index Scan using geo_location_pkey on geo_location loc1
(cost=0.00..3.68 rows=1 width=4) (actual time=0.29..0.30 rows=1 loops=1)
-> Index Scan using power_unit_pkey on power_unit pwu (cost=0.00..20.71
rows=260 width=58) (actual time=0.23..0.91 rows=46 loops=1)
-> Index Scan using customer_order_pkey on customer_order ord (cost=0.00..3.01
rows=1 width=4) (actual time=0.49..0.49 rows=1 loops=1)
Total runtime: 22742.21 msec
EXPLAIN
test=# \i report.sql
psql:report.sql:42: NOTICE: QUERY PLAN:
Nested Loop (cost=0.00..94043.77 rows=8 width=552) (actual time=21399.22..23452.35
rows=1 loops=1)
-> Nested Loop (cost=0.00..94015.22 rows=8 width=548) (actual
time=21398.88..23452.01 rows=1 loops=1)
-> Nested Loop (cost=0.00..93985.02 rows=8 width=490) (actual
time=21398.68..23451.80 rows=1 loops=1)
-> Nested Loop (cost=0.00..93954.83 rows=8 width=428) (actual
time=21398.32..23451.43 rows=1 loops=1)
-> Nested Loop (cost=0.00..93931.44 rows=8 width=424) (actual
time=21397.89..23450.99 rows=1 loops=1)
-> Merge Join (cost=0.00..93894.85 rows=12 width=342)
(actual time=21397.43..23450.52 rows=1 loops=1)
-> Nested Loop (cost=0.00..36211.15 rows=629765
width=334) (actual time=0.93..13795.69 rows=629765 loops=1)
-> Nested Loop (cost=0.00..14.75 rows=1
width=306) (actual time=0.52..0.56 rows=1 loops=1)
-> Nested Loop (cost=0.00..10.86 rows=1
width=248) (actual time=0.48..0.50 rows=1 loops=1)
-> Nested Loop (cost=0.00..6.88
rows=1 width=190) (actual time=0.43..0.45 rows=1 loops=1)
-> Index Scan using trip_pkey
on trip trp (cost=0.00..3.03 rows=1 width=24) (actual time=0.39..0.39 rows=1 loops=1)
-> Index Scan using
driver_pkey on driver dri (cost=0.00..3.84 rows=1 width=166) (actual time=0.03..0.04
rows=1 loops=1)
-> Index Scan using trailer_pkey on
trailer trl (cost=0.00..3.97 rows=1 width=58) (actual time=0.03..0.03 rows=1 loops=1)
-> Index Scan using power_unit_pkey on
power_unit pwu (cost=0.00..3.88 rows=1 width=58) (actual time=0.02..0.03 rows=1
loops=1)
-> Index Scan using txl_fgp_uid on transloading
txl (cost=0.00..29898.75 rows=629765 width=28) (actual time=0.39..6634.66 rows=629765
loops=1)
-> Index Scan using stp_trp_uid on trip_stop stp
(cost=0.00..9935.04 rows=251153 width=8) (actual time=0.36..5318.80 rows=863408
loops=1)
-> Index Scan using freight_group_pkey on freight_group fgp
(cost=0.00..3.01 rows=1 width=82) (actual time=0.41..0.42 rows=1 loops=1)
-> Index Scan using customer_order_pkey on customer_order ord
(cost=0.00..3.01 rows=1 width=4) (actual time=0.38..0.38 rows=1 loops=1)
-> Index Scan using place_pkey on place plc1 (cost=0.00..3.90 rows=1
width=62) (actual time=0.30..0.31 rows=1 loops=1)
-> Index Scan using place_pkey on place plc2 (cost=0.00..3.90 rows=1
width=58) (actual time=0.15..0.16 rows=1 loops=1)
-> Index Scan using geo_location_pkey on geo_location loc1 (cost=0.00..3.68 rows=1
width=4) (actual time=0.30..0.30 rows=1 loops=1)
Total runtime: 23453.23 msec
EXPLAIN
test=# \i report.sql
psql:report.sql:42: NOTICE: QUERY PLAN:
Nested Loop (cost=70989.31..71123.20 rows=8 width=552) (actual
time=22852.85..22852.91 rows=1 loops=1)
-> Nested Loop (cost=70989.31..71094.65 rows=8 width=548) (actual
time=22852.51..22852.57 rows=1 loops=1)
-> Nested Loop (cost=70989.31..71064.92 rows=8 width=382) (actual
time=22852.23..22852.27 rows=1 loops=1)
-> Nested Loop (cost=70989.31..71041.53 rows=8 width=378) (actual
time=22851.82..22851.86 rows=1 loops=1)
-> Merge Join (cost=70989.31..71010.79 rows=8 width=320) (actual
time=22851.46..22851.49 rows=1 loops=1)
-> Sort (cost=70989.31..70989.31 rows=8 width=262) (actual
time=22850.38..22850.38 rows=1 loops=1)
-> Nested Loop (cost=11547.95..70989.20 rows=8
width=262) (actual time=19246.44..22850.20 rows=1 loops=1)
-> Nested Loop (cost=11547.95..70959.00 rows=8
width=200) (actual time=19246.27..22850.02 rows=1 loops=1)
-> Nested Loop (cost=11547.95..70928.80
rows=8 width=142) (actual time=19245.96..22849.71 rows=1 loops=1)
-> Hash Join
(cost=11547.95..70892.21 rows=12 width=60) (actual time=19245.55..22849.28 rows=1
loops=1)
-> Hash Join
(cost=11544.92..67740.21 rows=629765 width=36) (actual time=2630.57..22035.24
rows=629614 loops=1)
-> Index Scan using
txl_fgp_uid on transloading txl (cost=0.00..29898.75 rows=629765 width=28) (actual
time=0.40..6558.70 rows=629765 loops=1)
-> Hash
(cost=9935.04..9935.04 rows=251153 width=8) (actual time=2628.13..2628.13 rows=0
loops=1)
-> Index Scan
using stp_trp_uid on trip_stop stp (cost=0.00..9935.04 rows=251153 width=8) (actual
time=0.39..1952.20 rows=251153 loops=1)
-> Hash (cost=3.03..3.03
rows=1 width=24) (actual time=0.22..0.22 rows=0 loops=1)
-> Index Scan using
trip_pkey on trip trp (cost=0.00..3.03 rows=1 width=24) (actual time=0.21..0.21
rows=1 loops=1)
-> Index Scan using
freight_group_pkey on freight_group fgp (cost=0.00..3.01 rows=1 width=82) (actual
time=0.38..0.38 rows=1 loops=1)
-> Index Scan using place_pkey on place
plc2 (cost=0.00..3.90 rows=1 width=58) (actual time=0.27..0.27 rows=1 loops=1)
-> Index Scan using place_pkey on place plc1
(cost=0.00..3.90 rows=1 width=62) (actual time=0.14..0.14 rows=1 loops=1)
-> Index Scan using power_unit_pkey on power_unit pwu
(cost=0.00..20.71 rows=260 width=58) (actual time=0.24..0.92 rows=46 loops=1)
-> Index Scan using trailer_pkey on trailer trl (cost=0.00..3.97
rows=1 width=58) (actual time=0.31..0.32 rows=1 loops=1)
-> Index Scan using customer_order_pkey on customer_order ord
(cost=0.00..3.01 rows=1 width=4) (actual time=0.35..0.36 rows=1 loops=1)
-> Index Scan using driver_pkey on driver dri (cost=0.00..3.84 rows=1
width=166) (actual time=0.23..0.23 rows=1 loops=1)
-> Index Scan using geo_location_pkey on geo_location loc1 (cost=0.00..3.68 rows=1
width=4) (actual time=0.29..0.30 rows=1 loops=1)
Total runtime: 22853.82 msec
EXPLAIN
test=# \i report.sql
psql:report.sql:42: NOTICE: QUERY PLAN:
Merge Join (cost=71101.73..71123.20 rows=8 width=552) (actual time=23122.51..23122.53
rows=1 loops=1)
-> Sort (cost=71101.73..71101.73 rows=8 width=494) (actual time=23121.42..23121.43
rows=1 loops=1)
-> Nested Loop (cost=11547.95..71101.62 rows=8 width=494) (actual
time=19490.96..23121.25 rows=1 loops=1)
-> Nested Loop (cost=11547.95..71073.07 rows=8 width=490) (actual
time=19490.60..23120.88 rows=1 loops=1)
-> Nested Loop (cost=11547.95..71042.32 rows=8 width=432)
(actual time=19490.26..23120.53 rows=1 loops=1)
-> Nested Loop (cost=11547.95..71012.12 rows=8 width=374)
(actual time=19490.06..23120.32 rows=1 loops=1)
-> Nested Loop (cost=11547.95..70981.92 rows=8
width=312) (actual time=19489.73..23119.98 rows=1 loops=1)
-> Nested Loop (cost=11547.95..70952.19 rows=8
width=146) (actual time=19489.47..23119.71 rows=1 loops=1)
-> Nested Loop (cost=11547.95..70928.80
rows=8 width=142) (actual time=19489.13..23119.36 rows=1 loops=1)
-> Hash Join
(cost=11547.95..70892.21 rows=12 width=60) (actual time=19488.71..23118.92 rows=1
loops=1)
-> Hash Join
(cost=11544.92..67740.21 rows=629765 width=36) (actual time=2604.06..22287.42
rows=629614 loops=1)
-> Index Scan using
txl_fgp_uid on transloading txl (cost=0.00..29898.75 rows=629765 width=28) (actual
time=0.39..6577.41 rows=629765 loops=1)
-> Hash
(cost=9935.04..9935.04 rows=251153 width=8) (actual time=2601.67..2601.67 rows=0
loops=1)
-> Index Scan
using stp_trp_uid on trip_stop stp (cost=0.00..9935.04 rows=251153 width=8) (actual
time=0.40..1937.33 rows=251153 loops=1)
-> Hash (cost=3.03..3.03
rows=1 width=24) (actual time=0.35..0.35 rows=0 loops=1)
-> Index Scan using
trip_pkey on trip trp (cost=0.00..3.03 rows=1 width=24) (actual time=0.34..0.34
rows=1 loops=1)
-> Index Scan using
freight_group_pkey on freight_group fgp (cost=0.00..3.01 rows=1 width=82) (actual
time=0.38..0.39 rows=1 loops=1)
-> Index Scan using customer_order_pkey
on customer_order ord (cost=0.00..3.01 rows=1 width=4) (actual time=0.31..0.32 rows=1
loops=1)
-> Index Scan using driver_pkey on driver dri
(cost=0.00..3.84 rows=1 width=166) (actual time=0.22..0.23 rows=1 loops=1)
-> Index Scan using place_pkey on place plc1
(cost=0.00..3.90 rows=1 width=62) (actual time=0.29..0.29 rows=1 loops=1)
-> Index Scan using place_pkey on place plc2
(cost=0.00..3.90 rows=1 width=58) (actual time=0.15..0.15 rows=1 loops=1)
-> Index Scan using trailer_pkey on trailer trl (cost=0.00..3.97
rows=1 width=58) (actual time=0.29..0.29 rows=1 loops=1)
-> Index Scan using geo_location_pkey on geo_location loc1
(cost=0.00..3.68 rows=1 width=4) (actual time=0.30..0.31 rows=1 loops=1)
-> Index Scan using power_unit_pkey on power_unit pwu (cost=0.00..20.71 rows=260
width=58) (actual time=0.24..0.94 rows=46 loops=1)
Total runtime: 23123.46 msec
EXPLAIN
test=# SET geqo to false;
SET VARIABLEtest=# \i report.sql
psql:report.sql:42: NOTICE: QUERY PLAN:
Nested Loop (cost=0.00..1404.93 rows=8 width=552) (actual time=1.68..1.75 rows=1
loops=1)
-> Nested Loop (cost=0.00..1381.55 rows=8 width=548) (actual time=1.60..1.67
rows=1 loops=1)
-> Nested Loop (cost=0.00..1351.35 rows=8 width=490) (actual time=1.51..1.58
rows=1 loops=1)
-> Nested Loop (cost=0.00..1322.80 rows=8 width=486) (actual
time=1.44..1.50 rows=1 loops=1)
-> Nested Loop (cost=0.00..1292.60 rows=8 width=424) (actual
time=1.36..1.41 rows=1 loops=1)
-> Nested Loop (cost=0.00..1256.01 rows=12 width=342)
(actual time=1.27..1.32 rows=1 loops=1)
-> Nested Loop (cost=0.00..18.07 rows=5 width=314)
(actual time=0.93..0.97 rows=1 loops=1)
-> Nested Loop (cost=0.00..14.75 rows=1
width=306) (actual time=0.52..0.55 rows=1 loops=1)
-> Nested Loop (cost=0.00..10.90 rows=1
width=140) (actual time=0.47..0.49 rows=1 loops=1)
-> Nested Loop (cost=0.00..7.01
rows=1 width=82) (actual time=0.43..0.45 rows=1 loops=1)
-> Index Scan using trip_pkey
on trip trp (cost=0.00..3.03 rows=1 width=24) (actual time=0.38..0.39 rows=1 loops=1)
-> Index Scan using
trailer_pkey on trailer trl (cost=0.00..3.97 rows=1 width=58) (actual time=0.03..0.04
rows=1 loops=1)
-> Index Scan using power_unit_pkey
on power_unit pwu (cost=0.00..3.88 rows=1 width=58) (actual time=0.02..0.03 rows=1
loops=1)
-> Index Scan using driver_pkey on driver
dri (cost=0.00..3.84 rows=1 width=166) (actual time=0.03..0.03 rows=1 loops=1)
-> Index Scan using stp_trp_uid on trip_stop
stp (cost=0.00..3.17 rows=12 width=8) (actual time=0.38..0.38 rows=1 loops=1)
-> Index Scan using txl_stp_uid on transloading txl
(cost=0.00..253.05 rows=296 width=28) (actual time=0.31..0.31 rows=1 loops=1)
-> Index Scan using freight_group_pkey on freight_group fgp
(cost=0.00..3.01 rows=1 width=82) (actual time=0.05..0.05 rows=1 loops=1)
-> Index Scan using place_pkey on place plc1 (cost=0.00..3.90
rows=1 width=62) (actual time=0.03..0.04 rows=1 loops=1)
-> Index Scan using geo_location_pkey on geo_location loc1
(cost=0.00..3.68 rows=1 width=4) (actual time=0.03..0.03 rows=1 loops=1)
-> Index Scan using place_pkey on place plc2 (cost=0.00..3.90 rows=1
width=58) (actual time=0.04..0.04 rows=1 loops=1)
-> Index Scan using customer_order_pkey on customer_order ord (cost=0.00..3.01
rows=1 width=4) (actual time=0.04..0.04 rows=1 loops=1)
Total runtime: 2.65 msec
EXPLAIN
test=#
---------------------------(end of broadcast)---------------------------
TIP 5: Have you checked our extensive FAQ?
http://www.postgresql.org/users-lounge/docs/faq.html
