Re: BUG #7602: Select with many joins against the same table is very slow compared to 9.2.0. - Mailing list pgsql-bugs
| From | Hedén Daniel |
|---|---|
| Subject | Re: BUG #7602: Select with many joins against the same table is very slow compared to 9.2.0. |
| Date | |
| Msg-id | 26526AB77242C544B86B458364BF5D4127414F@essth103.sweco.se Whole thread Raw |
| In response to | Re: BUG #7602: Select with many joins against the same table is very slow compared to 9.2.0. (Craig Ringer <ringerc@ringerc.id.au>) |
| List | pgsql-bugs |
I had never changed `join_collapse_limit` it is still out commented is this not default.
When I try to run EXPLAIN ANALYZE on my query in PostgreSQL 9.2.1 it runs for 6 hours (21724001 ms) and then gives this
error:
ERROR: could not load library "C:/Program Files/PostgreSQL/9.2/lib/postgis-2.0.dll": Invalid access to memory
location.
********** Error **********
ERROR: could not load library "C:/Program Files/PostgreSQL/9.2/lib/postgis-2.0.dll": Invalid access to memory location.
SQL state: 58P01
Running EXPLAIN ANALYZE on the query under 9.2.0 is no problem and it gives this result:
"HashAggregate (cost=3160.16..3160.19 rows=1 width=963) (actual time=191.083..192.107 rows=2171 loops=1)"
" -> Nested Loop (cost=395.14..3160.10 rows=1 width=963) (actual time=3.147..185.751 rows=2171 loops=1)"
" -> Nested Loop (cost=395.14..3153.84 rows=1 width=965) (actual time=3.128..174.052 rows=2171 loops=1)"
" Join Filter: (o."ObjectId" = a16."ObjectId")"
" -> Nested Loop (cost=395.14..3147.73 rows=1 width=1025) (actual time=3.125..168.864 rows=2171
loops=1)"
" -> Nested Loop (cost=395.14..3141.50 rows=1 width=1027) (actual time=3.121..163.960 rows=2171
loops=1)"
" Join Filter: (o."ObjectId" = a15."ObjectId")"
" -> Nested Loop (cost=395.14..3135.38 rows=1 width=1019) (actual time=3.118..158.695
rows=2197loops=1)"
" -> Nested Loop (cost=395.14..3129.12 rows=1 width=1021) (actual time=3.114..153.753
rows=2197loops=1)"
" Join Filter: (o."ObjectId" = a14."ObjectId")"
" -> Nested Loop (cost=395.14..3123.00 rows=1 width=1013) (actual
time=3.111..148.162rows=2197 loops=1)"
" -> Nested Loop (cost=395.14..3116.77 rows=1 width=1015) (actual
time=3.107..143.292rows=2197 loops=1)"
" Join Filter: (o."ObjectId" = a13."ObjectId")"
" -> Nested Loop (cost=395.14..3110.65 rows=1 width=1007) (actual
time=3.103..137.994rows=2197 loops=1)"
" -> Nested Loop (cost=395.14..3104.42 rows=1 width=1009)
(actualtime=3.100..132.970 rows=2197 loops=1)"
" Join Filter: (o."ObjectId" = a12."ObjectId")"
" -> Nested Loop (cost=395.14..3098.30 rows=1
width=1001)(actual time=3.096..127.668 rows=2197 loops=1)"
" -> Nested Loop (cost=395.14..3092.05 rows=1
width=1003)(actual time=3.092..122.811 rows=2197 loops=1)"
" Join Filter: (o."ObjectId" =
a11."ObjectId")"
" -> Nested Loop (cost=395.14..3085.93
rows=1width=995) (actual time=3.089..117.657 rows=2197 loops=1)"
" -> Nested Loop (cost=395.14..3079.68
rows=1width=997) (actual time=3.085..112.684 rows=2197 loops=1)"
" Join Filter: (o."ObjectId" =
a10."ObjectId")"
" -> Nested Loop
(cost=395.14..3073.56rows=1 width=989) (actual time=3.080..107.390 rows=2197 loops=1)"
" -> Nested Loop
(cost=395.14..3067.32rows=1 width=991) (actual time=3.077..102.504 rows=2197 loops=1)"
" Join Filter:
(o."ObjectId"= a9."ObjectId")"
" -> Nested Loop
(cost=395.14..3061.20rows=1 width=983) (actual time=3.073..97.326 rows=2197 loops=1)"
" -> Nested
Loop (cost=395.14..3054.97 rows=1 width=985) (actual time=3.069..92.368 rows=2197 loops=1)"
" Join
Filter:(o."ObjectId" = a8."ObjectId")"
" ->
NestedLoop (cost=395.14..3048.85 rows=1 width=977) (actual time=3.064..87.042 rows=2197 loops=1)"
" ->
Nested Loop (cost=395.14..3042.63 rows=1 width=979) (actual time=3.062..82.081 rows=2197 loops=1)"
"
Join Filter: (o."ObjectId" = a7."ObjectId")"
"
-> Nested Loop (cost=395.14..3036.51 rows=1 width=971) (actual time=3.058..76.742 rows=2197 loops=1)"
"
-> Nested Loop (cost=395.14..3030.32 rows=1 width=973) (actual time=3.054..71.805 rows=2197 loops=1)"
"
Join Filter: (o."ObjectId" = a6."ObjectId")"
"
-> Nested Loop (cost=395.14..3024.20 rows=1 width=965) (actual time=3.050..66.507 rows=2197 loops=1)"
"
-> Nested Loop (cost=395.14..3018.00 rows=1 width=967) (actual time=3.047..61.582 rows=2197
loops=1)"
"
Join Filter: (o."ObjectId" = a5."ObjectId")"
"
-> Nested Loop (cost=395.14..3011.88 rows=1 width=959) (actual time=3.043..56.385 rows=2197
loops=1)"
"
-> Nested Loop (cost=395.14..3005.68 rows=1 width=961) (actual time=3.039..51.412
rows=2197loops=1)"
"
Join Filter: (o."ObjectId" = a4."ObjectId")"
"
-> Nested Loop (cost=395.14..2999.57 rows=1 width=953) (actual
time=3.035..46.059rows=2197 loops=1)"
"
-> Nested Loop (cost=395.14..2993.31 rows=1 width=955) (actual
time=3.032..41.045rows=2197 loops=1)"
"
Join Filter: (o."ObjectId" = a3."ObjectId")"
"
-> Nested Loop (cost=395.14..2932.13 rows=10 width=947) (actual
time=3.027..35.512rows=2197 loops=1)"
"
-> Nested Loop (cost=395.14..2869.57 rows=10 width=949)
(actualtime=3.021..30.310 rows=2197 loops=1)"
"
-> Nested Loop Left Join (cost=395.14..2807.16 rows=10
width=951)(actual time=3.015..24.158 rows=2197 loops=1)"
"
-> Nested Loop (cost=395.14..2754.55 rows=10
width=942)(actual time=3.009..19.635 rows=2197 loops=1)"
"
-> Nested Loop (cost=395.14..2697.92
rows=10width=48) (actual time=3.004..14.230 rows=2197 loops=1)"
"
Join Filter: (o."ObjectId" =
a1."ObjectId")"
"
-> Hash Join (cost=395.14..2226.83
rows=77width=40) (actual time=2.989..5.702 rows=2197 loops=1)"
"
Hash Cond: (a2."ObjectId" =
o."ObjectId")"
"
-> Bitmap Heap Scan on
"Attribute"a2 (cost=40.68..1863.79 rows=2083 width=8) (actual time=0.226..1.177 rows=2227 loops=1)"
"
Recheck Cond: ("MetaId" =
2983)"
"
-> Bitmap Index Scan on
ix_metaid_attribute (cost=0.00..40.16 rows=2083 width=0) (actual time=0.175..0.175 rows=2227 loops=1)"
"
Index Cond: ("MetaId"
=2983)"
"
-> Hash (cost=346.15..346.15
rows=665width=32) (actual time=2.756..2.756 rows=2197 loops=1)"
"
Buckets: 1024 Batches: 1
MemoryUsage: 137kB"
"
-> Hash Join
(cost=235.20..346.15rows=665 width=32) (actual time=0.980..2.335 rows=2197 loops=1)"
"
Hash Cond:
(gr."ObjectId"= o."ObjectId")"
"
-> Seq Scan on
"GeoRel"gr (cost=0.00..77.53 rows=5353 width=8) (actual time=0.005..0.357 rows=5353 loops=1)"
"
-> Hash
(cost=207.37..207.37rows=2227 width=24) (actual time=0.966..0.966 rows=2227 loops=1)"
"
Buckets: 1024
Batches:1 Memory Usage: 122kB"
"
-> Bitmap Heap
Scanon "Object" o (cost=45.53..207.37 rows=2227 width=24) (actual time=0.153..0.581 rows=2227 loops=1)"
"
Recheck
Cond:("ClassId" = 12)"
"
->
BitmapIndex Scan on ix_classid_object (cost=0.00..44.97 rows=2227 width=0) (actual time=0.139..0.139 rows=2227
loops=1)"
"
IndexCond: ("ClassId" = 12)"
"
-> Index Scan using cover_attribute on
"Attribute"a1 (cost=0.00..6.11 rows=1 width=8) (actual time=0.003..0.003 rows=1 loops=2197)"
"
Index Cond: (("ObjectId" =
gr."ObjectId")AND ("MetaId" = 113))"
"
-> Index Scan using ix_objectid_geoobject on
"GeoObject"go (cost=0.00..5.65 rows=1 width=898) (actual time=0.002..0.002 rows=1 loops=2197)"
"
Index Cond: ("ObjectId" =
gr."GeoObjectId")"
"
-> Index Scan using "Definition_pkey" on
"Definition"d (cost=0.00..5.25 rows=1 width=17) (actual time=0.001..0.001 rows=1 loops=2197)"
"
Index Cond: (o."SubClassid" = "MetaId")"
"
-> Index Scan using ix_attributeid_attributevalue on
"AttributeValue"av1 (cost=0.00..6.23 rows=1 width=6) (actual time=0.002..0.002 rows=1 loops=2197)"
"
Index Cond: ("AttributeId" = a1."AttributeId")"
"
-> Index Scan using ix_attributeid_attributevalue on
"AttributeValue"av2 (cost=0.00..6.25 rows=1 width=6) (actual time=0.002..0.002 rows=1 loops=2197)"
"
Index Cond: ("AttributeId" = a2."AttributeId")"
"
-> Index Scan using cover_attribute on "Attribute" a3
(cost=0.00..6.11rows=1 width=8) (actual time=0.002..0.002 rows=1 loops=2197)"
"
Index Cond: (("ObjectId" = gr."ObjectId") AND ("MetaId" =
2534))"
"
-> Index Scan using ix_attributeid_attributevalue on "AttributeValue" av3
(cost=0.00..6.24rows=1 width=6) (actual time=0.002..0.002 rows=1 loops=2197)"
"
Index Cond: ("AttributeId" = a3."AttributeId")"
"
-> Index Scan using cover_attribute on "Attribute" a4 (cost=0.00..6.11 rows=1
width=8)(actual time=0.002..0.002 rows=1 loops=2197)"
"
Index Cond: (("ObjectId" = gr."ObjectId") AND ("MetaId" = 492))"
"
-> Index Scan using ix_attributeid_attributevalue on "AttributeValue" av4
(cost=0.00..6.19rows=1 width=6) (actual time=0.001..0.002 rows=1 loops=2197)"
"
Index Cond: ("AttributeId" = a4."AttributeId")"
"
-> Index Scan using cover_attribute on "Attribute" a5 (cost=0.00..6.11 rows=1 width=8)
(actualtime=0.002..0.002 rows=1 loops=2197)"
"
Index Cond: (("ObjectId" = gr."ObjectId") AND ("MetaId" = 111))"
"
-> Index Scan using ix_attributeid_attributevalue on "AttributeValue" av5 (cost=0.00..6.19 rows=1
width=6)(actual time=0.001..0.002 rows=1 loops=2197)"
"
Index Cond: ("AttributeId" = a5."AttributeId")"
"
-> Index Scan using cover_attribute on "Attribute" a6 (cost=0.00..6.11 rows=1 width=8) (actual
time=0.002..0.002rows=1 loops=2197)"
"
Index Cond: (("ObjectId" = gr."ObjectId") AND ("MetaId" = 2470))"
"
-> Index Scan using ix_attributeid_attributevalue on "AttributeValue" av6 (cost=0.00..6.18 rows=1 width=6)
(actualtime=0.001..0.002 rows=1 loops=2197)"
"
Index Cond: ("AttributeId" = a6."AttributeId")"
"
-> Index Scan using cover_attribute on "Attribute" a7 (cost=0.00..6.11 rows=1 width=8) (actual time=0.002..0.002
rows=1loops=2197)"
"
Index Cond: (("ObjectId" = gr."ObjectId") AND ("MetaId" = 2469))"
" ->
Index Scan using ix_attributeid_attributevalue on "AttributeValue" av7 (cost=0.00..6.21 rows=1 width=6) (actual
time=0.001..0.002rows=1 loops=2197)"
"
Index Cond: ("AttributeId" = a7."AttributeId")"
" ->
IndexScan using cover_attribute on "Attribute" a8 (cost=0.00..6.11 rows=1 width=8) (actual time=0.002..0.002 rows=1
loops=2197)"
"
IndexCond: (("ObjectId" = gr."ObjectId") AND ("MetaId" = 2982))"
" -> Index Scan
usingix_attributeid_attributevalue on "AttributeValue" av8 (cost=0.00..6.22 rows=1 width=6) (actual time=0.001..0.002
rows=1loops=2197)"
" Index
Cond:("AttributeId" = a8."AttributeId")"
" -> Index Scan using
cover_attributeon "Attribute" a9 (cost=0.00..6.11 rows=1 width=8) (actual time=0.002..0.002 rows=1 loops=2197)"
" Index Cond:
(("ObjectId"= gr."ObjectId") AND ("MetaId" = 2961))"
" -> Index Scan using
ix_attributeid_attributevalueon "AttributeValue" av9 (cost=0.00..6.23 rows=1 width=6) (actual time=0.001..0.002 rows=1
loops=2197)"
" Index Cond:
("AttributeId"= a9."AttributeId")"
" -> Index Scan using
cover_attributeon "Attribute" a10 (cost=0.00..6.11 rows=1 width=8) (actual time=0.002..0.002 rows=1 loops=2197)"
" Index Cond: (("ObjectId" =
gr."ObjectId")AND ("MetaId" = 2965))"
" -> Index Scan using
ix_attributeid_attributevalueon "AttributeValue" av10 (cost=0.00..6.25 rows=1 width=6) (actual time=0.001..0.002
rows=1loops=2197)"
" Index Cond: ("AttributeId" =
a10."AttributeId")"
" -> Index Scan using cover_attribute on
"Attribute"a11 (cost=0.00..6.11 rows=1 width=8) (actual time=0.002..0.002 rows=1 loops=2197)"
" Index Cond: (("ObjectId" =
gr."ObjectId")AND ("MetaId" = 2970))"
" -> Index Scan using ix_attributeid_attributevalue
on"AttributeValue" av11 (cost=0.00..6.24 rows=1 width=6) (actual time=0.001..0.002 rows=1 loops=2197)"
" Index Cond: ("AttributeId" =
a11."AttributeId")"
" -> Index Scan using cover_attribute on "Attribute" a12
(cost=0.00..6.11rows=1 width=8) (actual time=0.002..0.002 rows=1 loops=2197)"
" Index Cond: (("ObjectId" = gr."ObjectId") AND
("MetaId"= 115))"
" -> Index Scan using ix_attributeid_attributevalue on
"AttributeValue"av12 (cost=0.00..6.22 rows=1 width=6) (actual time=0.001..0.002 rows=1 loops=2197)"
" Index Cond: ("AttributeId" = a12."AttributeId")"
" -> Index Scan using cover_attribute on "Attribute" a13
(cost=0.00..6.11rows=1 width=8) (actual time=0.002..0.002 rows=1 loops=2197)"
" Index Cond: (("ObjectId" = gr."ObjectId") AND ("MetaId" =
171))"
" -> Index Scan using ix_attributeid_attributevalue on "AttributeValue"
av13 (cost=0.00..6.22 rows=1 width=6) (actual time=0.001..0.002 rows=1 loops=2197)"
" Index Cond: ("AttributeId" = a13."AttributeId")"
" -> Index Scan using cover_attribute on "Attribute" a14 (cost=0.00..6.11 rows=1
width=8)(actual time=0.002..0.002 rows=1 loops=2197)"
" Index Cond: (("ObjectId" = gr."ObjectId") AND ("MetaId" = 172))"
" -> Index Scan using ix_attributeid_attributevalue on "AttributeValue" av14
(cost=0.00..6.25rows=1 width=6) (actual time=0.001..0.002 rows=1 loops=2197)"
" Index Cond: ("AttributeId" = a14."AttributeId")"
" -> Index Scan using cover_attribute on "Attribute" a15 (cost=0.00..6.11 rows=1 width=8)
(actualtime=0.002..0.002 rows=1 loops=2197)"
" Index Cond: (("ObjectId" = gr."ObjectId") AND ("MetaId" = 2987))"
" -> Index Scan using ix_attributeid_attributevalue on "AttributeValue" av15 (cost=0.00..6.22
rows=1width=6) (actual time=0.001..0.002 rows=1 loops=2171)"
" Index Cond: ("AttributeId" = a15."AttributeId")"
" -> Index Scan using cover_attribute on "Attribute" a16 (cost=0.00..6.11 rows=1 width=8) (actual
time=0.002..0.002rows=1 loops=2171)"
" Index Cond: (("ObjectId" = gr."ObjectId") AND ("MetaId" = 1590))"
" -> Index Scan using ix_attributeid_attributevalue on "AttributeValue" av16 (cost=0.00..6.24 rows=1 width=6)
(actualtime=0.001..0.002 rows=1 loops=2171)"
" Index Cond: ("AttributeId" = a16."AttributeId")"
"Total runtime: 192.953 ms"
Regards
/Daniel Hedén
-----Original Message-----
From: Craig Ringer [mailto:ringerc@ringerc.id.au]
Sent: den 16 oktober 2012 04:31
To: Hedén Daniel
Cc: pgsql-bugs@postgresql.org
Subject: Re: [BUGS] BUG #7602: Select with many joins against the same table is very slow compared to 9.2.0.
On 10/15/2012 06:55 PM, daniel.heden@sweco.se wrote:
> The following bug has been logged on the website:
>
> Bug reference: 7602
> Logged by: Daniel Hedén
> Email address: daniel.heden@sweco.se
> PostgreSQL version: 9.2.1
> Operating system: Windows 7 / Vista 64-Bit
> Description:
>
> Select with many joins against the same table is very slow compared to
> 9.2.0.
> In my case 16 times, this query takes a second max on 9.2.0 but on
> 9.2.1 it takes more than 30 minutes.
Could you have accidentally reset `join_collapse_limit` to its default value?
Show `EXPLAIN ANALYZE` output for both old and new cases, if possible.
At least for the new one.
(Please reply to the mailing list, not to me).
--
Craig Ringer
pgsql-bugs by date: