Re: left outer join terrible slow compared to inner join - Mailing list pgsql-general

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

claycle@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=1780loops=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=1780loops=1) 
                           Join Filter: (("inner".tkservice = 11) AND ("inner".paramname =
'MLPPDomainIdentifier'::charactervarying)) 
                           ->  Nested Loop  (cost=1.15..17157414766.93 rows=1229 width=1871) (actual
time=2717.94..83141.71rows=1780 loops=1) 
                                 Join Filter: (("inner".tkservice = 11) AND ("inner".paramname =
'MLPPPreemptionSetting'::charactervarying)) 
                                 ->  Nested Loop  (cost=1.15..17157396090.02 rows=1229 width=1836) (actual
time=2714.90..76002.08rows=1780 loops=1) 
                                       Join Filter: (("inner".tkservice = 11) AND ("inner".paramname =
'MLPPIndicationStatus'::charactervarying)) 
                                       ->  Nested Loop  (cost=1.15..17157377413.11 rows=1229 width=1801) (actual
time=2712.05..68810.87rows=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.45rows=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)
(actualtime=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=946width=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=946width=1563) (actual time=2708.58..63948.35 rows=1780 loops=1) 
                                                                                 Join Filter:
("inner".fkcallmanagergroup= "outer".pkid) 
                                                                                 ->  Nested Loop
(cost=1.15..17157368659.26rows=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.34rows=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.05rows=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.14rows=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) 
                                                                                                               ->
NestedLoop  (cost=1.15..17157364629.30 rows=473 width=1251) (actual time=2705.19..60567.86 rows=890 loops=1) 

JoinFilter: ("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=808loops=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=808loops=1) 

                                Join Filter: ("outer".fkcallingsearchspace_aar = "inner".pkid) 

                                ->  Nested Loop  (cost=0.00..17157316076.55 rows=462 width=342) (actual
time=2656.46..4706.90rows=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.22rows=808 loops=1) 

                                            Filter: ((tkdeviceprofile = 0) AND (subplan)) 

                                            SubPlan 

                                              ->  Materialize  (cost=12307973.61..12307973.61 rows=40 width=145)
(actualtime=2.87..3.44 rows=455 loops=924) 

                                                    ->  Unique  (cost=0.00..12307973.61 rows=40 width=145) (actual
time=803.51..2650.40rows=808 loops=1) 

                                                          ->  Nested Loop  (cost=0.00..12307972.62 rows=396 width=145)
(actualtime=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=396width=64) (actual time=803.12..2505.12 rows=808 loops=1) 

                                                                                  Join Filter: ("outer".fkdevicepool =
"inner".pkid)

                                                                                  ->  Index Scan using device_pkey on
deviced  (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.26rows=1394 width=145) (actual time=0.99..1.55 rows=451 loops=810) 

                                                                                                ->  Nested Loop
(cost=0.00..8827.26rows=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.56rows=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) 

                                                                                                                  ->
NestedLoop  (cost=0.00..4272.37 rows=1394 width=64) (actual time=0.62..597.83 rows=1394 loops=1) 


JoinFilter: ("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) 

                                                                                                                  ->
SeqScan on callmanagergroup cmg  (cost=0.00..1.03 rows=3 width=16) (actual time=0.01..0.02 rows=3 loops=1394) 

                                                                                                            ->  Seq
Scanon callmanagergroupmember gm  (cost=0.00..1.06 rows=6 width=36) (actual time=0.01..0.04 rows=6 loops=1394) 

                                                                                                      ->  Seq Scan on
callmanagercm  (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.45rows=45 width=32) (actual time=0.01..0.28 rows=45 loops=808) 

                                                                            ->  Seq Scan on callmanagergroup cmg
(cost=0.00..1.03rows=3 width=16) (actual time=0.01..0.02 rows=3 loops=808) 

                                                                      ->  Seq Scan on callmanagergroupmember gm
(cost=0.00..1.06rows=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.21rows=31 loops=808) 

                                ->  Seq Scan on callingsearchspace aarcs  (cost=0.00..1.31 rows=31 width=90) (actual
time=0.01..0.18rows=31 loops=808) 

                          ->  Seq Scan on "location" l  (cost=0.00..0.00 rows=1 width=20) (actual time=0.00..0.00
rows=0loops=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.11rows=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
Scanon callingsearchspace css  (cost=0.00..1.31 rows=31 width=90) (actual time=0.01..0.21 rows=31 loops=890) 
                                                                                                         ->  Seq Scan
oncallingsearchspace cst  (cost=0.00..1.31 rows=31 width=90) (actual time=0.01..0.19 rows=31 loops=890) 
                                                                                                   ->  Seq Scan on
devicepooldp  (cost=0.00..2.45 rows=45 width=68) (actual time=0.03..0.61 rows=45 loops=890) 
                                                                                             ->  Seq Scan on
mediaresourcelistdl  (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.02rows=2 width=16) (actual time=0.01..0.02 rows=2 loops=1780) 
                                                                     ->  Seq Scan on digitdiscardinstruction ddi
(cost=0.00..2.31rows=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)
(actualtime=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.49rows=368 loops=1780) 
                                 ->  Seq Scan on processconfig pcc  (cost=0.00..9.68 rows=368 width=35) (actual
time=0.02..2.45rows=368 loops=1780) 
                           ->  Seq Scan on processconfig pcd  (cost=0.00..9.68 rows=368 width=35) (actual
time=0.02..2.42rows=368 loops=1780) 
                     ->  Seq Scan on processconfig pcf  (cost=0.00..9.68 rows=368 width=35) (actual time=0.02..2.45
rows=368loops=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@chittenden.org]
> Sent: Thursday, August 28, 2003 1:32 PM
> To: Clay Luther
> Cc: pgsql-general@postgresql.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
>