Re: left outer join terrible slow compared to inner join

Interstingly enough, the EXPLAIN ANALYZE itself took 90+ seconds:

claycle(at)gkar:.../PhoneInserter/PhoneInserter > time psql -f e_stationd.sql ccm > analyzed.txt

real 1m46.770s
user 0m0.010s
sys 0m0.010s

Here is the output of the above explain analyze execution:

QUERY PLAN
---------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
Sort (cost=17157472946.49..17157472949.56 rows=1229 width=2066) (actual time=106513.59..106515.67 rows=1780 loops=1)
Sort Key: d.name
-> Nested Loop (cost=1.15..17157472883.44 rows=1229 width=2066) (actual time=2724.18..106407.50 rows=1780 loops=1)
Join Filter: ("outer".fkcallingsearchspace = "inner".pkid)
-> Nested Loop (cost=1.15..17157470797.64 rows=1229 width=1976) (actual time=2723.56..104804.55 rows=1780 loops=1)
Join Filter: (("inner".tkservice = 11) AND ("inner".paramname = 'DefaultNetworkLocale'::character varying))
-> Nested Loop (cost=1.15..17157452120.74 rows=1229 width=1941) (actual time=2721.32..97560.43 rows=1780 loops=1)
Join Filter: (("inner".tkservice = 11) AND ("inner".paramname = 'DefaultUserLocale'::character varying))
-> Nested Loop (cost=1.15..17157433443.83 rows=1229 width=1906) (actual time=2719.93..90288.85 rows=1780 loops=1)
Join Filter: (("inner".tkservice = 11) AND ("inner".paramname = 'MLPPDomainIdentifier'::character varying))
-> Nested Loop (cost=1.15..17157414766.93 rows=1229 width=1871) (actual time=2717.94..83141.71 rows=1780 loops=1)
Join Filter: (("inner".tkservice = 11) AND ("inner".paramname = 'MLPPPreemptionSetting'::character varying))
-> Nested Loop (cost=1.15..17157396090.02 rows=1229 width=1836) (actual time=2714.90..76002.08 rows=1780 loops=1)
Join Filter: (("inner".tkservice = 11) AND ("inner".paramname = 'MLPPIndicationStatus'::character varying))
-> Nested Loop (cost=1.15..17157377413.11 rows=1229 width=1801) (actual time=2712.05..68810.87 rows=1780 loops=1)
Join Filter: ((("outer".fkvoicemessagingpilot IS NULL) OR ("outer".fkvoicemessagingpilot = "inner".pkid)) AND (("inner".isdefault = true) OR ("outer".fkvoicemessagingpilot = "inner".pkid)))
-> Nested Loop (cost=1.15..17157376083.00 rows=1229 width=1759) (actual time=2711.44..68020.45 rows=1780 loops=1)
Join Filter: ((("outer".fkvoicemessagingprofile IS NULL) OR ("outer".fkvoicemessagingprofile = "inner".pkid)) AND (("inner".isdefault = true) OR ("outer".fkvoicemessagingprofile = "inner".pkid)))
-> Nested Loop (cost=1.15..17157375032.94 rows=946 width=1722) (actual time=2710.83..67240.60 rows=1780 loops=1)
Join Filter: ("outer".fkroutefilter = "inner".pkid)
-> Nested Loop (cost=1.15..17157373703.81 rows=946 width=1623) (actual time=2710.21..66328.33 rows=1780 loops=1)
Join Filter: ("outer".fkdialplan = "inner".pkid)
-> Nested Loop (cost=1.15..17157372736.52 rows=946 width=1599) (actual time=2709.74..65695.13 rows=1780 loops=1)
Join Filter: ("outer".fkdigitdiscardinstruction = "inner".pkid)
-> Nested Loop (cost=1.15..17157370184.69 rows=946 width=1579) (actual time=2709.01..64628.50 rows=1780 loops=1)
Join Filter: ("outer".fkcallmanager = "inner".pkid)
-> Nested Loop (cost=1.15..17157369196.12 rows=946 width=1563) (actual time=2708.58..63948.35 rows=1780 loops=1)
Join Filter: ("inner".fkcallmanagergroup = "outer".pkid)
-> Nested Loop (cost=1.15..17157368659.26 rows=473 width=1531) (actual time=2708.13..63271.44 rows=890 loops=1)
Join Filter: ("outer".fkcallmanagergroup = "inner".pkid)
-> Nested Loop (cost=1.15..17157368154.34 rows=473 width=1515) (actual time=2707.69..62936.58 rows=890 loops=1)
Join Filter: ("outer".fkmediaresourcelist = "inner".pkid)
-> Nested Loop (cost=1.15..17157367660.05 rows=473 width=1499) (actual time=2707.29..62613.05 rows=890 loops=1)
Join Filter: ("outer".fkdevicepool = "inner".pkid)
-> Nested Loop (cost=1.15..17157366235.14 rows=473 width=1431) (actual time=2706.54..61664.68 rows=890 loops=1)
Join Filter: ("outer".fkcallingsearchspace_translation = "inner".pkid)
-> Nested Loop (cost=1.15..17157365432.22 rows=473 width=1341) (actual time=2705.92..61180.46 rows=890 loops=1)
Join Filter: ("outer".fkcallingsearchspace_sharedlineappear = "inner".pkid)
-> Nested Loop (cost=1.15..17157364629.30 rows=473 width=1251) (actual time=2705.19..60567.86 rows=890 loops=1)
Join Filter: ("outer".fkroutepartition = "inner".pkid)
-> Nested Loop (cost=1.15..17157363751.89 rows=473 width=1221) (actual time=2704.59..59883.81 rows=890 loops=1)
Join Filter: ("outer".fknumplan = "inner".pkid)
-> Nested Loop (cost=1.15..17157345954.08 rows=473 width=605) (actual time=2691.46..32912.02 rows=890 loops=1)
Join Filter: ("outer".pkid = "inner".fkdevice)
-> Nested Loop (cost=1.15..17157317358.59 rows=462 width=504) (actual time=2657.87..5239.00 rows=808 loops=1)
Join Filter: ("outer".fkmediaresourcelist = "inner".pkid)
-> Hash Join (cost=1.15..17157316875.80 rows=462 width=472) (actual time=2657.66..5139.98 rows=808 loops=1)
Hash Cond: ("outer".tkdeviceprotocol = "inner".enum)
-> Nested Loop (cost=0.00..17157316866.57 rows=462 width=452) (actual time=2656.96..5062.74 rows=808 loops=1)
Join Filter: ("outer".fklocation = "inner".pkid)
-> Nested Loop (cost=0.00..17157316860.79 rows=462 width=432) (actual time=2656.88..4992.47 rows=808 loops=1)
Join Filter: ("outer".fkcallingsearchspace_aar = "inner".pkid)
-> Nested Loop (cost=0.00..17157316076.55 rows=462 width=342) (actual time=2656.46..4706.90 rows=808 loops=1)
Join Filter: ("outer".fkcallingsearchspace = "inner".pkid)
-> Seq Scan on device d (cost=0.00..17157315292.30 rows=462 width=252) (actual time=2655.97..4380.22 rows=808 loops=1)
Filter: ((tkdeviceprofile = 0) AND (subplan))
SubPlan
-> Materialize (cost=12307973.61..12307973.61 rows=40 width=145) (actual time=2.87..3.44 rows=455 loops=924)
-> Unique (cost=0.00..12307973.61 rows=40 width=145) (actual time=803.51..2650.40 rows=808 loops=1)
-> Nested Loop (cost=0.00..12307972.62 rows=396 width=145) (actual time=803.50..2645.21 rows=808 loops=1)
Join Filter: ("outer".fkcallmanager = "inner".pkid)
Filter: ("inner".name = 'DAL-CCM2'::character varying)
-> Nested Loop (cost=0.00..12307556.90 rows=396 width=116) (actual time=803.38..2603.11 rows=808 loops=1)
Join Filter: ("inner".fkcallmanagergroup = "outer".pkid)
Filter: ("inner".priority = 0)
-> Nested Loop (cost=0.00..12307101.59 rows=396 width=80) (actual time=803.23..2540.22 rows=808 loops=1)
Join Filter: ("outer".fkcallmanagergroup = "inner".pkid)
-> Nested Loop (cost=0.00..12306678.94 rows=396 width=64) (actual time=803.12..2505.12 rows=808 loops=1)
Join Filter: ("outer".fkdevicepool = "inner".pkid)
-> Index Scan using device_pkey on device d (cost=0.00..12305486.23 rows=396 width=32) (actual time=802.92..2160.98 rows=808 loops=1)
Filter: (((tkclass = 1) OR (tkclass = 10)) AND (subplan))
SubPlan
-> Materialize (cost=8827.26..8827.26 rows=1394 width=145) (actual time=0.99..1.55 rows=451 loops=810)
-> Nested Loop (cost=0.00..8827.26 rows=1394 width=145) (actual time=1.44..799.37 rows=898 loops=1)
Join Filter: ("outer".fkcallmanager = "inner".pkid)
Filter: ("inner".name = 'DAL-SJ-CCM3'::character varying)
-> Nested Loop (cost=0.00..7363.56 rows=1394 width=116) (actual time=1.30..750.11 rows=898 loops=1)
Join Filter: ("inner".fkcallmanagergroup = "outer".pkid)
Filter: ("inner".priority <> 0)
-> Nested Loop (cost=0.00..5760.46 rows=1394 width=80) (actual time=0.76..655.61 rows=1394 loops=1)
Join Filter: ("outer".fkcallmanagergroup = "inner".pkid)
-> Nested Loop (cost=0.00..4272.37 rows=1394 width=64) (actual time=0.62..597.83 rows=1394 loops=1)
Join Filter: ("outer".fkdevicepool = "inner".pkid)
-> Seq Scan on device d (cost=0.00..72.94 rows=1394 width=32) (actual time=0.02..11.42 rows=1394 loops=1)
-> Seq Scan on devicepool dp (cost=0.00..2.45 rows=45 width=32) (actual time=0.01..0.28 rows=45 loops=1394)
-> Seq Scan on callmanagergroup cmg (cost=0.00..1.03 rows=3 width=16) (actual time=0.01..0.02 rows=3 loops=1394)
-> Seq Scan on callmanagergroupmember gm (cost=0.00..1.06 rows=6 width=36) (actual time=0.01..0.04 rows=6 loops=1394)
-> Seq Scan on callmanager cm (cost=0.00..1.02 rows=2 width=29) (actual time=0.01..0.02 rows=2 loops=898)
-> Seq Scan on devicepool dp (cost=0.00..2.45 rows=45 width=32) (actual time=0.01..0.28 rows=45 loops=808)
-> Seq Scan on callmanagergroup cmg (cost=0.00..1.03 rows=3 width=16) (actual time=0.01..0.02 rows=3 loops=808)
-> Seq Scan on callmanagergroupmember gm (cost=0.00..1.06 rows=6 width=36) (actual time=0.01..0.04 rows=6 loops=808)
-> Seq Scan on callmanager cm (cost=0.00..1.02 rows=2 width=29) (actual time=0.01..0.02 rows=2 loops=808)
-> Seq Scan on callingsearchspace cs (cost=0.00..1.31 rows=31 width=90) (actual time=0.01..0.21 rows=31 loops=808)
-> Seq Scan on callingsearchspace aarcs (cost=0.00..1.31 rows=31 width=90) (actual time=0.01..0.18 rows=31 loops=808)
-> Seq Scan on "location" l (cost=0.00..0.00 rows=1 width=20) (actual time=0.00..0.00 rows=0 loops=808)
-> Hash (cost=1.12..1.12 rows=12 width=20) (actual time=0.16..0.16 rows=0 loops=1)
-> Seq Scan on typedeviceprotocol p (cost=0.00..1.12 rows=12 width=20) (actual time=0.05..0.11 rows=12 loops=1)
-> Seq Scan on mediaresourcelist ol (cost=0.00..1.02 rows=2 width=32) (actual time=0.01..0.02 rows=2 loops=808)
-> Seq Scan on devicenumplanmap dnp (cost=0.00..43.62 rows=1462 width=101) (actual time=0.03..27.03 rows=1462 loops=808)
-> Seq Scan on numplan np (cost=0.00..28.39 rows=739 width=616) (actual time=0.05..23.73 rows=739 loops=890)
-> Seq Scan on routepartition rp (cost=0.00..1.38 rows=38 width=30) (actual time=0.02..0.24 rows=38 loops=890)
-> Seq Scan on callingsearchspace css (cost=0.00..1.31 rows=31 width=90) (actual time=0.01..0.21 rows=31 loops=890)
-> Seq Scan on callingsearchspace cst (cost=0.00..1.31 rows=31 width=90) (actual time=0.01..0.19 rows=31 loops=890)
-> Seq Scan on devicepool dp (cost=0.00..2.45 rows=45 width=68) (actual time=0.03..0.61 rows=45 loops=890)
-> Seq Scan on mediaresourcelist dl (cost=0.00..1.02 rows=2 width=16) (actual time=0.01..0.02 rows=2 loops=890)
-> Seq Scan on callmanagergroup cmg (cost=0.00..1.03 rows=3 width=16) (actual time=0.01..0.03 rows=3 loops=890)
-> Seq Scan on callmanagergroupmember gm (cost=0.00..1.06 rows=6 width=32) (actual time=0.01..0.05 rows=6 loops=890)
-> Seq Scan on callmanager cm (cost=0.00..1.02 rows=2 width=16) (actual time=0.01..0.02 rows=2 loops=1780)
-> Seq Scan on digitdiscardinstruction ddi (cost=0.00..2.31 rows=31 width=20) (actual time=0.01..0.18 rows=31 loops=1780)
-> Seq Scan on dialplan dlp (cost=0.00..1.01 rows=1 width=24) (actual time=0.01..0.02 rows=1 loops=1780)
-> Seq Scan on routefilter rf (cost=0.00..1.18 rows=18 width=99) (actual time=0.01..0.12 rows=18 loops=1780)
-> Seq Scan on voicemessagingprofile vm (cost=0.00..1.04 rows=4 width=37) (actual time=0.02..0.05 rows=4 loops=1780)
-> Seq Scan on voicemessagingpilot vmp (cost=0.00..1.03 rows=3 width=42) (actual time=0.02..0.04 rows=3 loops=1780)
-> Seq Scan on processconfig pc (cost=0.00..9.68 rows=368 width=35) (actual time=0.02..2.49 rows=368 loops=1780)
-> Seq Scan on processconfig pcc (cost=0.00..9.68 rows=368 width=35) (actual time=0.02..2.45 rows=368 loops=1780)
-> Seq Scan on processconfig pcd (cost=0.00..9.68 rows=368 width=35) (actual time=0.02..2.42 rows=368 loops=1780)
-> Seq Scan on processconfig pcf (cost=0.00..9.68 rows=368 width=35) (actual time=0.02..2.45 rows=368 loops=1780)
-> Seq Scan on processconfig pcg (cost=0.00..9.68 rows=368 width=35) (actual time=0.02..2.43 rows=368 loops=1780)
-> Seq Scan on callingsearchspace cssv (cost=0.00..1.31 rows=31 width=90) (actual time=0.02..0.24 rows=31 loops=1780)
Total runtime: 106530.61 msec
(120 rows)

> -----Original Message-----
> From: Sean Chittenden [mailto:sean(at)chittenden(dot)org]
> Sent: Thursday, August 28, 2003 1:32 PM
> To: Clay Luther
> Cc: pgsql-general(at)postgresql(dot)org
> Subject: Re: [GENERAL] left outer join terrible slow compared to inner
> join
>
>
> > Actually, I was about to post some problems we have with large left
> > outer joins as well we've discovered in a porting project from
> > NT/SQL Server -> Linux/Postgres.
> >
> > We have a particular query that is rather large, left outer joining
> > across several tables. Under SQL Server, with identical data and
> > schema, this particular query takes 2 seconds.
> >
> > Under PostgreSQL, this same query takes 90 seconds -- that's right,
> > 90 seconds. 45x longer than SQL Server. This was quite a shock to
> > us (we'd not seen such a performance deficit between the two dbs
> > until this) and could, in fact, force us away from Postgres.
> >
> > I'd be happy to forward the explain to anyone who'd care to look at
> > it...
>
> Post an EXPLAIN ANALYZE of the query...
>
> -sc
>
> --
> Sean Chittenden
>