query slower on 8.1 than 7.3 - Mailing list pgsql-performance

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)
(actualtime=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=475loops=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=626loops=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=626loops=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)
(actualtime=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=0loops=1) 
                                                   ->  Seq Scan on software_binary  (cost=0.00..21.59 rows=20 width=4)
(actualtime=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=25544loops=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.66rows=325 loops=1) 
                                 ->  Aggregate  (cost=4363.24..4610.85 rows=2476 width=12) (actual
time=1714.03..1818.08rows=325 loops=1) 
                                       ->  Group  (cost=4363.24..4548.95 rows=24761 width=12) (actual
time=1714.01..1796.43rows=25544 loops=1) 
                                             ->  Sort  (cost=4363.24..4425.15 rows=24761 width=12) (actual
time=1714.00..1739.34rows=25544 loops=1) 
                                                   Sort Key: entityid, rmsbinaryid
                                                   ->  Seq Scan on msg306u  (cost=0.00..2556.22 rows=24761 width=12)
(actualtime=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.48rows=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)
(actualtime=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=472loops=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.679rows=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.111rows=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=25542loops=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.010rows=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.007rows=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)
(actualtime=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=472loops=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.494rows=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.112rows=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=323loops=1) 
                                 ->  Seq Scan on msg306u  (cost=0.00..1797.28 rows=26230 width=12) (actual
time=0.009..68.861rows=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.850rows=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=25542loops=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