[postgis-users] Nested loop join = very bad performance
Mike Leahy
mgleahy at alumni.uwaterloo.ca
Sun Mar 28 08:57:53 PDT 2010
Sorry all...here's the explain output I promised in my previous message...
On Sunday 28 March 2010 11:57:01 Mike Leahy wrote:
> Hello list,
>
> Following up from the bug that was successfully resolved last week
> (http://trac.osgeo.org/postgis/ticket/469), I've found that nested loop
> joins are actually causing very bad performance with my queries.
>
> Thanks to the observations of Leo and Regina in that discussion, I have
> found that I can work around this by setting enable_nestloop = off. Once
> that is specified, queries start working about as fast. With
> enable_nestloop = on, a query may take ~15000 ms, while enable_nestloop =
> off returns the same query in ~90 ms.
>
> I have attached a textfile showing the different 'explain analzye' results
> for the full query with/without nestloop enabled. You could also refer to
> the somewhat simplified queries I put together in discussion thread
> related to bug #469 (see
> http://postgis.refractions.net/pipermail/postgis-users/2010-
> March/026235.html for some examples).
>
> Is this something that should be looked into, or should I just incorporate
> the workaround of disabling nested loop joins into my code?
>
> Thanks,
> Mike
>
-------------- next part --------------
enable_nestloop = on:
QUERY PLAN
--------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
Sort (cost=260.10..260.10 rows=1 width=385) (actual time=15084.727..15084.730 rows=25 loops=1)
Sort Key: cl.id
Sort Method: quicksort Memory: 32kB
-> Limit (cost=260.07..260.08 rows=1 width=360) (actual time=15084.700..15084.708 rows=25 loops=1)
-> Sort (cost=260.07..260.08 rows=1 width=360) (actual time=15084.699..15084.704 rows=25 loops=1)
Sort Key: cl.id
Sort Method: top-N heapsort Memory: 32kB
-> Nested Loop Left Join (cost=212.58..260.06 rows=1 width=360) (actual time=68.629..15083.483 rows=204 loops=1)
Join Filter: (csl1.chat_id = cl.id)
-> Nested Loop Left Join (cost=159.35..202.70 rows=1 width=328) (actual time=68.070..10418.323 rows=204 loops=1)
Join Filter: (csl2.chat_id = cl.id)
-> Nested Loop Left Join (cost=99.82..134.88 rows=1 width=296) (actual time=7.868..18.477 rows=204 loops=1)
Join Filter: (cl.id = chat_log.parent_id)
-> Hash Left Join (cost=87.20..120.09 rows=1 width=264) (actual time=0.040..1.787 rows=204 loops=1)
Hash Cond: (cl.id = ctu.id)
Filter: (((ctu.num_target_users IS NULL) AND (ctg.num_target_groups IS NULL)) OR ((ctu.num_target_users + ctg.num_target_groups) = 0) OR ((((cl.username)::text = 'admin'::text) OR ('admin'::text = ANY (ctu.target_users_array)) OR ('{admin,everyone}'::text[] && ctg.target_groups_array)) AND (cl."time" > '2010-03-28 10:54:44.382616-04'::timestamp with time zone)))
-> Hash Left Join (cost=43.60..63.86 rows=205 width=256) (actual time=0.030..1.302 rows=204 loops=1)
Hash Cond: (cl.id = ctg.id)
-> Seq Scan on chat_log cl (cost=0.00..12.62 rows=205 width=184) (actual time=0.015..0.833 rows=204 loops=1)
Filter: ((NOT deleted) AND (id < 5090) AND (depth = 0))
-> Hash (cost=41.10..41.10 rows=200 width=76) (actual time=0.004..0.004 rows=0 loops=1)
-> Subquery Scan ctg (cost=34.60..41.10 rows=200 width=76) (actual time=0.004..0.004 rows=0 loops=1)
-> HashAggregate (cost=34.60..39.10 rows=200 width=36) (actual time=0.004..0.004 rows=0 loops=1)
-> Seq Scan on chat_target_groups (cost=0.00..22.30 rows=1230 width=36) (actual time=0.001..0.001 rows=0 loops=1)
-> Hash (cost=41.10..41.10 rows=200 width=76) (actual time=0.003..0.003 rows=0 loops=1)
-> Subquery Scan ctu (cost=34.60..41.10 rows=200 width=76) (actual time=0.002..0.002 rows=0 loops=1)
-> HashAggregate (cost=34.60..39.10 rows=200 width=36) (actual time=0.002..0.002 rows=0 loops=1)
-> Seq Scan on chat_target_users (cost=0.00..22.30 rows=1230 width=36) (actual time=0.001..0.001 rows=0 loops=1)
-> HashAggregate (cost=12.62..13.70 rows=48 width=8) (actual time=0.041..0.070 rows=49 loops=204)
-> Seq Scan on chat_log (cost=0.00..11.08 rows=308 width=8) (actual time=0.003..0.190 rows=308 loops=1)
-> HashAggregate (cost=59.53..62.49 rows=237 width=6240) (actual time=0.017..50.908 rows=219 loops=204)
-> Hash Join (cost=10.56..57.87 rows=333 width=6240) (actual time=0.358..1.104 rows=279 loops=1)
Hash Cond: (us2.id = csl2.selection_id)
-> Seq Scan on user_selections us2 (cost=0.00..42.39 rows=422 width=6240) (actual time=0.006..0.397 rows=343 loops=1)
Filter: (user_drawing AND deleted)
-> Hash (cost=6.40..6.40 rows=333 width=8) (actual time=0.339..0.339 rows=333 loops=1)
-> Seq Scan on chat_selection_links csl2 (cost=0.00..6.40 rows=333 width=8) (actual time=0.007..0.178 rows=333 loops=1)
Filter: (NOT deleted)
-> HashAggregate (cost=53.23..54.68 rows=116 width=6240) (actual time=0.004..22.842 rows=20 loops=204)
-> Hash Join (cost=43.84..52.65 rows=116 width=6240) (actual time=0.260..0.414 rows=54 loops=1)
Hash Cond: (csl1.selection_id = us1.id)
-> Seq Scan on chat_selection_links csl1 (cost=0.00..6.40 rows=333 width=8) (actual time=0.011..0.092 rows=333 loops=1)
Filter: (NOT deleted)
-> Hash (cost=42.39..42.39 rows=116 width=6240) (actual time=0.228..0.228 rows=138 loops=1)
-> Seq Scan on user_selections us1 (cost=0.00..42.39 rows=116 width=6240) (actual time=0.009..0.165 rows=138 loops=1)
Filter: (NOT user_drawing)
Total runtime: 15085.197 ms
enable_nestloop = off:
QUERY PLAN
--------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
Sort (cost=260.17..260.17 rows=1 width=385) (actual time=88.643..88.645 rows=25 loops=1)
Sort Key: cl.id
Sort Method: quicksort Memory: 32kB
-> Limit (cost=260.14..260.15 rows=1 width=360) (actual time=88.618..88.626 rows=25 loops=1)
-> Sort (cost=260.14..260.15 rows=1 width=360) (actual time=88.617..88.620 rows=25 loops=1)
Sort Key: cl.id
Sort Method: top-N heapsort Memory: 32kB
-> Hash Left Join (cost=227.09..260.13 rows=1 width=360) (actual time=87.445..88.392 rows=204 loops=1)
Hash Cond: (cl.id = csls.chat_id)
-> Hash Left Join (cost=169.81..202.76 rows=1 width=328) (actual time=64.063..64.633 rows=204 loops=1)
Hash Cond: (cl.id = csld.chat_id)
-> Hash Left Join (cost=101.98..134.89 rows=1 width=296) (actual time=8.303..8.737 rows=204 loops=1)
Hash Cond: (cl.id = clr.id)
-> Hash Left Join (cost=87.20..120.09 rows=1 width=264) (actual time=0.040..0.386 rows=204 loops=1)
Hash Cond: (cl.id = ctu.id)
Filter: (((ctu.num_target_users IS NULL) AND (ctg.num_target_groups IS NULL)) OR ((ctu.num_target_users + ctg.num_target_groups) = 0) OR ((((cl.username)::text = 'admin'::text) OR ('admin'::text = ANY (ctu.target_users_array)) OR ('{admin,everyone}'::text[] && ctg.target_groups_array)) AND (cl."time" > '2010-03-28 10:54:44.382616-04'::timestamp with time zone)))
-> Hash Left Join (cost=43.60..63.86 rows=205 width=256) (actual time=0.030..0.278 rows=204 loops=1)
Hash Cond: (cl.id = ctg.id)
-> Seq Scan on chat_log cl (cost=0.00..12.62 rows=205 width=184) (actual time=0.015..0.171 rows=204 loops=1)
Filter: ((NOT deleted) AND (id < 5090) AND (depth = 0))
-> Hash (cost=41.10..41.10 rows=200 width=76) (actual time=0.005..0.005 rows=0 loops=1)
-> Subquery Scan ctg (cost=34.60..41.10 rows=200 width=76) (actual time=0.003..0.003 rows=0 loops=1)
-> HashAggregate (cost=34.60..39.10 rows=200 width=36) (actual time=0.003..0.003 rows=0 loops=1)
-> Seq Scan on chat_target_groups (cost=0.00..22.30 rows=1230 width=36) (actual time=0.000..0.000 rows=0 loops=1)
-> Hash (cost=41.10..41.10 rows=200 width=76) (actual time=0.003..0.003 rows=0 loops=1)
-> Subquery Scan ctu (cost=34.60..41.10 rows=200 width=76) (actual time=0.003..0.003 rows=0 loops=1)
-> HashAggregate (cost=34.60..39.10 rows=200 width=36) (actual time=0.002..0.002 rows=0 loops=1)
-> Seq Scan on chat_target_users (cost=0.00..22.30 rows=1230 width=36) (actual time=0.000..0.000 rows=0 loops=1)
-> Hash (cost=14.18..14.18 rows=48 width=36) (actual time=8.254..8.254 rows=48 loops=1)
-> Subquery Scan clr (cost=12.62..14.18 rows=48 width=36) (actual time=8.159..8.224 rows=49 loops=1)
-> HashAggregate (cost=12.62..13.70 rows=48 width=8) (actual time=8.158..8.202 rows=49 loops=1)
-> Seq Scan on chat_log (cost=0.00..11.08 rows=308 width=8) (actual time=0.003..0.198 rows=308 loops=1)
-> Hash (cost=64.86..64.86 rows=237 width=36) (actual time=55.749..55.749 rows=219 loops=1)
-> Subquery Scan csld (cost=59.53..64.86 rows=237 width=36) (actual time=3.565..55.590 rows=219 loops=1)
-> HashAggregate (cost=59.53..62.49 rows=237 width=6240) (actual time=3.564..55.517 rows=219 loops=1)
-> Hash Join (cost=10.56..57.87 rows=333 width=6240) (actual time=0.347..1.164 rows=279 loops=1)
Hash Cond: (us2.id = csl2.selection_id)
-> Seq Scan on user_selections us2 (cost=0.00..42.39 rows=422 width=6240) (actual time=0.006..0.453 rows=343 loops=1)
Filter: (user_drawing AND deleted)
-> Hash (cost=6.40..6.40 rows=333 width=8) (actual time=0.333..0.333 rows=333 loops=1)
-> Seq Scan on chat_selection_links csl2 (cost=0.00..6.40 rows=333 width=8) (actual time=0.008..0.169 rows=333 loops=1)
Filter: (NOT deleted)
-> Hash (cost=55.84..55.84 rows=116 width=36) (actual time=23.342..23.342 rows=20 loops=1)
-> Subquery Scan csls (cost=53.23..55.84 rows=116 width=36) (actual time=0.531..23.319 rows=20 loops=1)
-> HashAggregate (cost=53.23..54.68 rows=116 width=6240) (actual time=0.530..23.304 rows=20 loops=1)
-> Hash Join (cost=43.84..52.65 rows=116 width=6240) (actual time=0.254..0.414 rows=54 loops=1)
Hash Cond: (csl1.selection_id = us1.id)
-> Seq Scan on chat_selection_links csl1 (cost=0.00..6.40 rows=333 width=8) (actual time=0.011..0.096 rows=333 loops=1)
Filter: (NOT deleted)
-> Hash (cost=42.39..42.39 rows=116 width=6240) (actual time=0.229..0.229 rows=138 loops=1)
-> Seq Scan on user_selections us1 (cost=0.00..42.39 rows=116 width=6240) (actual time=0.009..0.161 rows=138 loops=1)
Filter: (NOT user_drawing)
Total runtime: 89.130 ms
More information about the postgis-users
mailing list