Porting app from 7.3 to 8.1, have hit a query that is slower. Everything
is analyzed / vacuumed appropriately. I've managed to pare the query
down into something manageable that still gives me a problem, it looks
like this:
SELECT
*
FROM
(
SELECT
software_download.*
FROM
(
SELECT
host_id, max(mtime) as mtime
FROM
software_download
JOIN software_binary USING (software_binary_id)
WHERE
binary_type_id IN (3,5,6) AND bds_status_id not in (6,17,18)
GROUP BY
host_id, software_binary_id
) latest_download
JOIN software_download using (host_id,mtime)
) ld
LEFT JOIN
(
SELECT
entityid, rmsbinaryid, rmsbinaryid as software_binary_id, timestamp as downloaded, ia.host_id
FROM
(
SELECT
entityid, rmsbinaryid,max(msgid) as msgid
FROM
msg306u
WHERE
downloadstatus=1
GROUP BY entityid,rmsbinaryid
) a1
JOIN myapp_app ia on (entityid=myapp_app_id)
JOIN (
SELECT
*
FROM
msg306u
WHERE
downloadstatus != 0
) a2 USING(entityid,rmsbinaryid,msgid)
) aa USING (host_id,software_binary_id)
The problem seems to stem from 8.1's thinking that using a nested loop
left join is a good idea. The 7.3 explain plan looks like this:
Hash Join (cost=10703.38..11791.64 rows=1 width=150) (actual time=2550.23..2713.26 rows=475 loops=1)
Hash Cond: ("outer".host_id = "inner".host_id)
Join Filter: ("outer".software_binary_id = "inner".rmsbinaryid)
-> Merge Join (cost=1071.80..2160.07 rows=1 width=110) (actual time=93.16..252.12 rows=475 loops=1)
Merge Cond: ("outer".host_id = "inner".host_id)
Join Filter: ("inner".mtime = "outer".mtime)
-> Index Scan using software_download_host_id on software_download (cost=0.00..973.16 rows=18513 width=98) (actual time=0.05..119.89 rows=15587 loops=1)
-> Sort (cost=1071.80..1072.81 rows=403 width=20) (actual time=90.82..94.97 rows=7328 loops=1)
Sort Key: latest_download.host_id
-> Subquery Scan latest_download (cost=1014.00..1054.34 rows=403 width=20) (actual time=85.60..90.12 rows=475 loops=1)
-> Aggregate (cost=1014.00..1054.34 rows=403 width=20) (actual time=85.59..89.27 rows=475 loops=1)
-> Group (cost=1014.00..1044.26 rows=4034 width=20) (actual time=85.55..87.61 rows=626 loops=1)
-> Sort (cost=1014.00..1024.09 rows=4034 width=20) (actual time=85.54..85.86 rows=626 loops=1)
Sort Key: software_download.host_id, software_download.software_binary_id
-> Hash Join (cost=21.64..772.38 rows=4034 width=20) (actual time=1.06..84.14 rows=626 loops=1)
Hash Cond: ("outer".software_binary_id = "inner".software_binary_id)
-> Seq Scan on software_download (cost=0.00..565.98 rows=17911 width=16) (actual time=0.06..67.26 rows=15364 loops=1)
Filter: ((bds_status_id <> 6) AND (bds_status_id <> 17) AND (bds_status_id <> 18))
-> Hash (cost=21.59..21.59 rows=20 width=4) (actual time=0.94..0.94 rows=0 loops=1)
-> Seq Scan on software_binary (cost=0.00..21.59 rows=20 width=4) (actual time=0.32..0.91 rows=23 loops=1)
Filter: ((binary_type_id = 3) OR (binary_type_id = 5) OR (binary_type_id = 6))
-> Hash (cost=9631.57..9631.57 rows=1 width=40) (actual time=2457.04..2457.04 rows=0 loops=1)
-> Merge Join (cost=9495.38..9631.57 rows=1 width=40) (actual time=2345.77..2456.74 rows=240 loops=1)
Merge Cond: (("outer".rmsbinaryid = "inner".rmsbinaryid) AND ("outer".msgid = "inner".msgid) AND ("outer".entityid = "inner".entityid))
-> Sort (cost=4629.24..4691.15 rows=24761 width=20) (actual time=514.19..539.04 rows=25544 loops=1)
Sort Key: msg306u.rmsbinaryid, msg306u.msgid, msg306u.entityid
-> Seq Scan on msg306u (cost=0.00..2556.22 rows=24761 width=20) (actual time=0.08..228.09 rows=25544 loops=1)
Filter: (downloadstatus <> '0'::text)
-> Sort (cost=4866.14..4872.33 rows=2476 width=20) (actual time=1831.55..1831.68 rows=241 loops=1)
Sort Key: a1.rmsbinaryid, a1.msgid, a1.entityid
-> Hash Join (cost=4429.43..4726.56 rows=2476 width=20) (actual time=1724.39..1830.63 rows=325 loops=1)
Hash Cond: ("outer".entityid = "inner".myapp_app_id)
-> Subquery Scan a1 (cost=4363.24..4610.85 rows=2476 width=12) (actual time=1714.04..1818.66 rows=325 loops=1)
-> Aggregate (cost=4363.24..4610.85 rows=2476 width=12) (actual time=1714.03..1818.08 rows=325 loops=1)
-> Group (cost=4363.24..4548.95 rows=24761 width=12) (actual time=1714.01..1796.43 rows=25544 loops=1)
-> Sort (cost=4363.24..4425.15 rows=24761 width=12) (actual time=1714.00..1739.34 rows=25544 loops=1)
Sort Key: entityid, rmsbinaryid
-> Seq Scan on msg306u (cost=0.00..2556.22 rows=24761 width=12) (actual time=0.03..152.94 rows=25544 loops=1)
Filter: (downloadstatus = '1'::text)
-> Hash (cost=61.95..61.95 rows=1695 width=8) (actual time=10.25..10.25 rows=0 loops=1)
-> Seq Scan on myapp_app ia (cost=0.00..61.95 rows=1695 width=8) (actual time=0.09..5.48 rows=1698 loops=1)
Total runtime: 2716.84 msec
Compared to the 8.1 plan:
Nested Loop Left Join (cost=2610.56..6491.82 rows=1 width=112) (actual time=166.411..4468.322 rows=472 loops=1)
Join Filter: (("outer".host_id = "inner".host_id) AND ("outer".software_binary_id = "inner".rmsbinaryid))
-> Merge Join (cost=616.56..1495.06 rows=1 width=96) (actual time=47.004..120.085 rows=472 loops=1)
Merge Cond: ("outer".host_id = "inner".host_id)
Join Filter: ("inner".mtime = "outer".mtime)
-> Index Scan using software_download_host_id on software_download (cost=0.00..615.92 rows=13416 width=96) (actual time=0.017..35.243 rows=13372 loops=1)
-> Sort (cost=616.56..620.45 rows=1555 width=12) (actual time=46.034..53.978 rows=6407 loops=1)
Sort Key: latest_download.host_id
-> Subquery Scan latest_download (cost=499.13..534.12 rows=1555 width=12) (actual time=43.137..45.058 rows=472 loops=1)
-> HashAggregate (cost=499.13..518.57 rows=1555 width=16) (actual time=43.132..43.887 rows=472 loops=1)
-> Hash Join (cost=5.64..477.57 rows=2875 width=16) (actual time=0.206..41.782 rows=623 loops=1)
Hash Cond: ("outer".software_binary_id = "inner".software_binary_id)
-> Seq Scan on software_download (cost=0.00..377.78 rows=13080 width=16) (actual time=0.007..23.679 rows=13167 loops=1)
Filter: ((bds_status_id <> 6) AND (bds_status_id <> 17) AND (bds_status_id <> 18))
-> Hash (cost=5.59..5.59 rows=20 width=4) (actual time=0.155..0.155 rows=22 loops=1)
-> Seq Scan on software_binary (cost=0.00..5.59 rows=20 width=4) (actual time=0.011..0.111 rows=22 loops=1)
Filter: ((binary_type_id = 3) OR (binary_type_id = 5) OR (binary_type_id = 6))
-> Nested Loop (cost=1994.00..4996.74 rows=1 width=20) (actual time=0.259..8.870 rows=238 loops=472)
-> Nested Loop (cost=1994.00..4992.28 rows=1 width=16) (actual time=0.249..5.851 rows=238 loops=472)
Join Filter: ("outer".rmsbinaryid = "inner".rmsbinaryid)
-> HashAggregate (cost=1994.00..2001.41 rows=593 width=12) (actual time=0.236..0.942 rows=323 loops=472)
-> Seq Scan on msg306u (cost=0.00..1797.28 rows=26230 width=12) (actual time=0.009..69.590 rows=25542 loops=1)
Filter: (downloadstatus = '1'::text)
-> Index Scan using msg306u_entityid_msgid_idx on msg306u (cost=0.00..5.02 rows=1 width=20) (actual time=0.008..0.010 rows=1 loops=152456)
Index Cond: (("outer".entityid = msg306u.entityid) AND ("outer"."?column3?" = msg306u.msgid))
Filter: (downloadstatus <> '0'::text)
-> Index Scan using myapp_app_pkey on myapp_app ia (cost=0.00..4.44 rows=1 width=8) (actual time=0.006..0.007 rows=1 loops=112336)
Index Cond: ("outer".entityid = ia.myapp_app_id)
Total runtime: 4469.506 ms
What is really tossing me here is I set enable_nestloop = off and got this plan:
Hash Left Join (cost=7034.77..7913.29 rows=1 width=112) (actual time=483.840..551.136 rows=472 loops=1)
Hash Cond: (("outer".host_id = "inner".host_id) AND ("outer".software_binary_id = "inner".rmsbinaryid))
-> Merge Join (cost=616.56..1495.06 rows=1 width=96) (actual
time=46.696..112.434 rows=472 loops=1)
Merge Cond: ("outer".host_id = "inner".host_id)
Join Filter: ("inner".mtime = "outer".mtime)
-> Index Scan using software_download_host_id on software_download (cost=0.00..615.92 rows=13416 width=96) (actual time=0.019..30.345 rows=13372 loops=1)
-> Sort (cost=616.56..620.45 rows=1555 width=12) (actual time=45.720..53.265 rows=6407 loops=1)
Sort Key: latest_download.host_id
-> Subquery Scan latest_download (cost=499.13..534.12 rows=1555 width=12) (actual time=42.867..44.763 rows=472 loops=1)
-> HashAggregate (cost=499.13..518.57 rows=1555 width=16) (actual time=42.862..43.628 rows=472 loops=1)
-> Hash Join (cost=5.64..477.57 rows=2875 width=16) (actual time=0.206..41.503 rows=623 loops=1)
Hash Cond: ("outer".software_binary_id = "inner".software_binary_id)
-> Seq Scan on software_download (cost=0.00..377.78 rows=13080 width=16) (actual time=0.007..23.494 rows=13167 loops=1)
Filter: ((bds_status_id <> 6) AND (bds_status_id <> 17) AND (bds_status_id <> 18))
-> Hash (cost=5.59..5.59 rows=20 width=4) (actual time=0.155..0.155 rows=22 loops=1)
-> Seq Scan on software_binary (cost=0.00..5.59 rows=20 width=4) (actual time=0.011..0.112 rows=22 loops=1)
Filter: ((binary_type_id = 3) OR (binary_type_id = 5) OR (binary_type_id = 6))
-> Hash (cost=6418.20..6418.20 rows=1 width=20) (actual time=437.111..437.111 rows=238 loops=1)
-> Merge Join (cost=6149.96..6418.20 rows=1 width=20) (actual time=367.555..436.667 rows=238 loops=1)
Merge Cond: (("outer".rmsbinaryid = "inner".rmsbinaryid) AND ("outer".msgid = "inner".msgid) AND ("outer".entityid = "inner".entityid))
-> Sort (cost=2119.55..2121.03 rows=593 width=16) (actual time=117.104..117.476 rows=323 loops=1)
Sort Key: a1.rmsbinaryid, a1.msgid, a1.entityid
-> Hash Join (cost=2054.19..2092.23 rows=593 width=16) (actual time=114.671..116.280 rows=323 loops=1)
Hash Cond: ("outer".entityid = "inner".myapp_app_id)
-> HashAggregate (cost=1994.00..2001.41 rows=593 width=12) (actual time=108.909..109.486 rows=323 loops=1)
-> Seq Scan on msg306u (cost=0.00..1797.28 rows=26230 width=12) (actual time=0.009..68.861 rows=25542 loops=1)
Filter: (downloadstatus = '1'::text)
-> Hash (cost=55.95..55.95 rows=1695 width=8) (actual time=5.736..5.736 rows=1695 loops=1)
-> Seq Scan on myapp_app ia (cost=0.00..55.95 rows=1695 width=8) (actual time=0.005..2.850 rows=1695 loops=1)
-> Sort (cost=4030.42..4095.99 rows=26230 width=20) (actual time=250.434..286.311 rows=25542 loops=1)
Sort Key: public.msg306u.rmsbinaryid, public.msg306u.msgid, public.msg306u.entityid
-> Seq Scan on msg306u (cost=0.00..1797.28 rows=26230 width=20) (actual time=0.009..80.478 rows=25542 loops=1)
Filter: (downloadstatus <> '0'::text)
Total runtime: 553.409 ms
Ah, a beautiful scheme! So given I can't run with enable_nestloop off,
anyone have a suggestion on how to get this thing moving in the right
direction? I tried raising statistics estimates on some of the columns
but that didn't help, though maybe I was raising it on the right
columns.. any suggestions there? Or perhaps a better way to write the
query... I'm open to suggestions. TIA,
Robert Treat
--
Build A Brighter Lamp :: Linux Apache {middleware} PostgreSQL
