Endless loop in ExecNestLoop - Mailing list pgsql-bugs

Hi,

The symptom:

The PostgreSQL backend sometimes does not terminate a query. (Killed after
the backend consumed 1h30 of CPU time.)

That query usually executes in less than 2 seconds, see also the explain=20
analyze.

Version: 8.0.2

Query:
select cel.objid,
             cel.shortname, ser.shortname,
             con.isInventoryFlag,
             dev.objid, dty.objid, loc.objid,
             dev.shortname, loc.shortname, loc.name, man.shortName,
             dty.type, dev.serNr, dev.invNr, dev.component,
             loc.zip, loc.city, con.shortname, con.name,
            CASE
       WHEN CURRENT_DATE between loc.locationstateFrom  and=20
loc.locationstateTo  THEN loc.locationstateText
       WHEN CURRENT_DATE between loc.locationstate2From and=20
loc.locationstate2To THEN loc.locationstate2Text
       ELSE null
     END
     ,      CASE
       WHEN CURRENT_DATE between loc.locationstateFrom  and=20
loc.locationstateTo  THEN loc.locationstateColorCode
       WHEN CURRENT_DATE between loc.locationstate2From and=20
loc.locationstate2To THEN loc.locationstate2ColorCode
       ELSE null
     END
     ,
            loc.locationcategory, loc.province
       from contracts con, contractelements cel
            left outer join servicetypes ser on ser.objid =3D cel.ser_objid,
            devices dev, locations loc, devicetypes dty, bpartners man
     where con.csp_objid in=20
(587703,587726,728917,969346,1043154,1368907,1368915,1368944,4176279,449240=
5,4493459,5682484,7465538)
  and cel.con_objid =3D con.objid
       and dev.cel_objid =3D cel.objid
       and loc.objid =3D dev.loc_objid
       and dty.objid =3D dev.dty_objid
       and man.objid =3D dty.bpa_objid
       and upper(cel.isActiv) =3D 'Y'
       and upper(coalesce(dev.isActiv,'Y')) =3D 'Y'
       and upper(coalesce(dev.IsCommittedSP,'Y')) =3D 'Y'
       and upper(coalesce(dev.IsCommittedCust,'Y')) =3D 'Y'
      and upper(loc.shortName)  =3D 'WNB531'
       order by 18 ASC

Explain Analyze:

 Sort  (cost=3D12084.89..12084.89 rows=3D1 width=3D477) (actual=20
time=3D1344.417..1344.424 rows=3D5 loops=3D1)
   Sort Key: con.shortname
   ->  Nested Loop  (cost=3D79.18..12084.88 rows=3D1 width=3D477) (actual=
=20
time=3D977.884..1343.987 rows=3D5 loops=3D1)
         ->  Nested Loop  (cost=3D79.18..12081.71 rows=3D1 width=3D130) (ac=
tual=20
time=3D6.363..1215.421 rows=3D12829 loops=3D1)
               ->  Nested Loop  (cost=3D79.18..12078.64 rows=3D1 width=3D12=
5)=20
(actual time=3D6.315..1045.691 rows=3D12829 loops=3D1)
                     ->  Nested Loop  (cost=3D79.18..12075.58 rows=3D1 widt=
h=3D111)=20
(actual time=3D6.256..855.119 rows=3D12829 loops=3D1)
                           ->  Hash Join  (cost=3D79.18..4321.10 rows=3D8=
=20
width=3D52) (actual time=3D5.668..666.173 rows=3D101 loops=3D1)
                                 Hash Cond: ("outer".con_objid =3D=20
"inner".objid)
                                 ->  Hash Left Join  (cost=3D1.18..4241.09=
=20
rows=3D385 width=3D27) (actual time=3D3.067..535.397 rows=3D73383 loops=3D1)
                                       Hash Cond: ("outer".ser_objid =3D=20
"inner".objid)
                                       ->  Seq Scan on contractelements cel=
=20=20
(cost=3D0.00..4237.98 rows=3D385 width=3D21) (actual time=3D2.869..285.115 =
rows=3D73383=20
loops=3D1)
                                             Filter: (upper((isactiv)::text=
) =3D=20
'Y'::text)
                                       ->  Hash  (cost=3D1.14..1.14 rows=3D=
14=20
width=3D14) (actual time=3D0.092..0.092 rows=3D14 loops=3D1)
                                             ->  Seq Scan on servicetypes s=
er=20=20
(cost=3D0.00..1.14 rows=3D14 width=3D14) (actual time=3D0.024..0.052 rows=
=3D14 loops=3D1)
                                 ->  Hash  (cost=3D77.82..77.82 rows=3D73=
=20
width=3D33) (actual time=3D0.378..0.378 rows=3D31 loops=3D1)
                                       ->  Bitmap Heap Scan on contracts co=
n=20=20
(cost=3D26.26..77.82 rows=3D73 width=3D33) (actual time=3D0.196..0.304 rows=
=3D31=20
loops=3D1)
                                             Recheck Cond: ((csp_objid =3D=
=20
587703) OR (csp_objid =3D 587726) OR (csp_objid =3D 728917) OR (csp_objid =
=3D=20
969346) OR (csp_objid =3D 1043154) OR (csp_objid =3D 1368907) OR (csp_objid=
 =3D=20
1368915) OR (csp_objid =3D 1368944) OR (csp_objid =3D 4176279) OR (csp_obji=
d =3D=20
4492405) OR (csp_objid =3D 4493459) OR (csp_objid =3D 5682484) OR (csp_obji=
d =3D=20
7465538))
                                             ->  BitmapOr  (cost=3D26.26..2=
6.26=20
rows=3D74 width=3D0) (actual time=3D0.160..0.160 rows=3D0 loops=3D1)
                                                   ->  Bitmap Index Scan on=
=20
contracts_csp_objid  (cost=3D0.00..2.12 rows=3D34 width=3D0) (actual=20
time=3D0.077..0.077 rows=3D31 loops=3D1)
                                                         Index Cond:=20
(csp_objid =3D 587703)
                                                   ->  Bitmap Index Scan on=
=20
contracts_csp_objid  (cost=3D0.00..2.01 rows=3D3 width=3D0) (actual=20
time=3D0.005..0.005 rows=3D0 loops=3D1)
                                                         Index Cond:=20
(csp_objid =3D 587726)
                                                   ->  Bitmap Index Scan on=
=20
contracts_csp_objid  (cost=3D0.00..2.01 rows=3D3 width=3D0) (actual=20
time=3D0.004..0.004 rows=3D0 loops=3D1)
                                                         Index Cond:=20
(csp_objid =3D 728917)
                                                   ->  Bitmap Index Scan on=
=20
contracts_csp_objid  (cost=3D0.00..2.01 rows=3D3 width=3D0) (actual=20
time=3D0.004..0.004 rows=3D0 loops=3D1)
                                                         Index Cond:=20
(csp_objid =3D 969346)
                                                   ->  Bitmap Index Scan on=
=20
contracts_csp_objid  (cost=3D0.00..2.01 rows=3D3 width=3D0) (actual=20
time=3D0.004..0.004 rows=3D0 loops=3D1)
                                                         Index Cond:=20
(csp_objid =3D 1043154)
                                                   ->  Bitmap Index Scan on=
=20
contracts_csp_objid  (cost=3D0.00..2.01 rows=3D3 width=3D0) (actual=20
time=3D0.010..0.010 rows=3D0 loops=3D1)
                                                         Index Cond:=20
(csp_objid =3D 1368907)
                                                   ->  Bitmap Index Scan on=
=20
contracts_csp_objid  (cost=3D0.00..2.01 rows=3D3 width=3D0) (actual=20
time=3D0.004..0.004 rows=3D0 loops=3D1)
                                                         Index Cond:=20
(csp_objid =3D 1368915)
                                                   ->  Bitmap Index Scan on=
=20
contracts_csp_objid  (cost=3D0.00..2.01 rows=3D3 width=3D0) (actual=20
time=3D0.004..0.004 rows=3D0 loops=3D1)
                                                         Index Cond:=20
(csp_objid =3D 1368944)
                                                   ->  Bitmap Index Scan on=
=20
contracts_csp_objid  (cost=3D0.00..2.01 rows=3D3 width=3D0) (actual=20
time=3D0.005..0.005 rows=3D0 loops=3D1)
                                                         Index Cond:=20
(csp_objid =3D 4176279)
                                                   ->  Bitmap Index Scan on=
=20
contracts_csp_objid  (cost=3D0.00..2.01 rows=3D3 width=3D0) (actual=20
time=3D0.004..0.004 rows=3D0 loops=3D1)
                                                         Index Cond:=20
(csp_objid =3D 4492405)
                                                   ->  Bitmap Index Scan on=
=20
contracts_csp_objid  (cost=3D0.00..2.01 rows=3D3 width=3D0) (actual=20
time=3D0.004..0.004 rows=3D0 loops=3D1)
                                                         Index Cond:=20
(csp_objid =3D 4493459)
                                                   ->  Bitmap Index Scan on=
=20
contracts_csp_objid  (cost=3D0.00..2.01 rows=3D3 width=3D0) (actual=20
time=3D0.004..0.004 rows=3D0 loops=3D1)
                                                         Index Cond:=20
(csp_objid =3D 5682484)
                                                   ->  Bitmap Index Scan on=
=20
contracts_csp_objid  (cost=3D0.00..2.01 rows=3D3 width=3D0) (actual=20
time=3D0.005..0.005 rows=3D0 loops=3D1)
                                                         Index Cond:=20
(csp_objid =3D 7465538)
                           ->  Index Scan using devices_cel_objid on device=
s=20
dev  (cost=3D0.00..969.30 rows=3D1 width=3D63) (actual time=3D0.588..1.401 =
rows=3D127=20
loops=3D101)
                                 Index Cond: (dev.cel_objid =3D "outer".obj=
id)
                                 Filter: ((upper((COALESCE(isactiv,=20
'Y'::character varying))::text) =3D 'Y'::text) AND=20
(upper((COALESCE(iscommittedsp, 'Y'::character varying))::text) =3D 'Y'::te=
xt)=20
AND (upper((COALESCE(iscommittedcust, 'Y'::character varying))::text) =3D=
=20
'Y'::text))
                     ->  Index Scan using devicetypes_pkey on devicetypes d=
ty=20=20
(cost=3D0.00..3.04 rows=3D1 width=3D18) (actual time=3D0.005..0.007 rows=3D=
1=20
loops=3D12829)
                           Index Cond: (dty.objid =3D "outer".dty_objid)
               ->  Index Scan using bpartners_pkey on bpartners man=20=20
(cost=3D0.00..3.06 rows=3D1 width=3D13) (actual time=3D0.004..0.006 rows=3D=
1=20
loops=3D12829)
                     Index Cond: (man.objid =3D "outer".bpa_objid)
         ->  Index Scan using locations_pkey on locations loc=20=20
(cost=3D0.00..3.11 rows=3D1 width=3D351) (actual time=3D0.006..0.006 rows=
=3D0=20
loops=3D12829)
               Index Cond: (loc.objid =3D "outer".loc_objid)
               Filter: (upper((shortname)::text) =3D 'WNB531'::text)
 Total runtime: 1345.103 ms
(55 rows)

Stack trace of the hanging backend.

#0  0x000000000043c743 in heap_deformtuple ()
#1  0x000000000043c949 in slot_getattr ()
#2  0x00000000004e3fae in ExecMakeTableFunctionResult ()
#3  0x00000000004e210d in ExecMakeFunctionResult ()
#4  0x00000000004e210d in ExecMakeFunctionResult ()
#5  0x00000000004e5063 in ExecQual ()
#6  0x00000000004e554e in ExecScan ()
#7  0x00000000004e0cc8 in ExecProcNode ()
#8  0x00000000004ebeb6 in ExecEndHashJoin ()
#9  0x00000000004eb7fa in ExecHashJoin ()
#10 0x00000000004e0d50 in ExecProcNode ()
#11 0x00000000004ee29d in ExecNestLoop ()
#12 0x00000000004e0d36 in ExecProcNode ()
#13 0x00000000004ee261 in ExecNestLoop ()   <-------
#14 0x00000000004e0d36 in ExecProcNode ()
#15 0x00000000004ee261 in ExecNestLoop ()
#16 0x00000000004e0d36 in ExecProcNode ()
#17 0x00000000004ee261 in ExecNestLoop ()
#18 0x00000000004e0d36 in ExecProcNode ()
#19 0x00000000004ee261 in ExecNestLoop ()
#20 0x00000000004e0d36 in ExecProcNode ()
#21 0x00000000004ef57c in ExecSort ()
#22 0x00000000004e0d6a in ExecProcNode ()
#23 0x00000000004df73f in ExecEndPlan ()
#24 0x00000000004dec09 in ExecutorRun ()
#25 0x000000000055f87a in PortalRun ()
#26 0x000000000055f5f9 in PortalRun ()
#27 0x000000000055b561 in pg_plan_queries ()
#28 0x000000000055df8c in PostgresMain ()
#29 0x0000000000539b01 in ClosePostmasterPorts ()
#30 0x00000000005395d0 in ClosePostmasterPorts ()
#31 0x0000000000537b4d in PostmasterMain ()
#32 0x0000000000536e59 in PostmasterMain ()
#33 0x00000000004fda0c in main ()

With gdb's ability to execute until the current function (stack frame) retu=
rn,
I found out which function (stack frame) is the up-most in this endless loo=
p.
That frame is marked with the arrow.

Is this bug-report of any use so far ?

best regards,
  Philipp Reisner
--=20
: Dipl-Ing Philipp Reisner                      Tel +43-1-8178292-50 :
: LINBIT Information Technologies GmbH          Fax +43-1-8178292-82 :
: Sch=F6nbrunnerstr 244, 1120 Vienna, Austria    http://www.linbit.com :