Re: BUG #7602: Select with many joins against the same table is very slow compared to 9.2.0.

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=2197 loops=1)"
" -> Nested Loop (cost=395.14..3129.12 rows=1 width=1021) (actual time=3.114..153.753 rows=2197 loops=1)"
" Join Filter: (o."ObjectId" = a14."ObjectId")"
" -> Nested Loop (cost=395.14..3123.00 rows=1 width=1013) (actual time=3.111..148.162 rows=2197 loops=1)"
" -> Nested Loop (cost=395.14..3116.77 rows=1 width=1015) (actual time=3.107..143.292 rows=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.994 rows=2197 loops=1)"
" -> Nested Loop (cost=395.14..3104.42 rows=1 width=1009) (actual time=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=1 width=995) (actual time=3.089..117.657 rows=2197 loops=1)"
" -> Nested Loop (cost=395.14..3079.68 rows=1 width=997) (actual time=3.085..112.684 rows=2197 loops=1)"
" Join Filter: (o."ObjectId" = a10."ObjectId")"
" -> Nested Loop (cost=395.14..3073.56 rows=1 width=989) (actual time=3.080..107.390 rows=2197 loops=1)"
" -> Nested Loop (cost=395.14..3067.32 rows=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.20 rows=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")"
" -> Nested Loop (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=2197 loops=1)"
" Join Filter: (o."ObjectId" = a4."ObjectId")"
" -> Nested Loop (cost=395.14..2999.57 rows=1 width=953) (actual time=3.035..46.059 rows=2197 loops=1)"
" -> Nested Loop (cost=395.14..2993.31 rows=1 width=955) (actual time=3.032..41.045 rows=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.512 rows=2197 loops=1)"
" -> Nested Loop (cost=395.14..2869.57 rows=10 width=949) (actual time=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=10 width=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=77 width=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=665 width=32) (actual time=2.756..2.756 rows=2197 loops=1)"
" Buckets: 1024 Batches: 1 Memory Usage: 137kB"
" -> Hash Join (cost=235.20..346.15 rows=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.37 rows=2227 width=24) (actual time=0.966..0.966 rows=2227 loops=1)"
" Buckets: 1024 Batches: 1 Memory Usage: 122kB"
" -> Bitmap Heap Scan on "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)"
" -> Bitmap Index Scan on ix_classid_object (cost=0.00..44.97 rows=2227 width=0) (actual time=0.139..0.139 rows=2227 loops=1)"
" Index Cond: ("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.11 rows=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.24 rows=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.19 rows=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) (actual time=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.002 rows=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) (actual time=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=1 loops=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.002 rows=1 loops=2197)"
" Index Cond: ("AttributeId" = a7."AttributeId")"
" -> Index Scan 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)"
" Index Cond: (("ObjectId" = gr."ObjectId") AND ("MetaId" = 2982))"
" -> Index Scan using ix_attributeid_attributevalue on "AttributeValue" av8 (cost=0.00..6.22 rows=1 width=6) (actual time=0.001..0.002 rows=1 loops=2197)"
" Index Cond: ("AttributeId" = a8."AttributeId")"
" -> Index Scan using cover_attribute on "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_attributevalue on "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_attribute on "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_attributevalue on "AttributeValue" av10 (cost=0.00..6.25 rows=1 width=6) (actual time=0.001..0.002 rows=1 loops=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.11 rows=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.11 rows=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.25 rows=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) (actual time=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=1 width=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.002 rows=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) (actual time=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(at)ringerc(dot)id(dot)au]
Sent: den 16 oktober 2012 04:31
To: Hedén Daniel
Cc: pgsql-bugs(at)postgresql(dot)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(dot)heden(at)sweco(dot)se wrote:
> The following bug has been logged on the website:
>
> Bug reference: 7602
> Logged by: Daniel Hedén
> Email address: daniel(dot)heden(at)sweco(dot)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