Thread: Endless loop in ExecNestLoop
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 :
Philipp Reisner <philipp.reisner@linbit.com> writes:
> Version: 8.0.2
I don't think so ... neither bitmap scans nor slot_getattr exist in 8.0.
> Is this bug-report of any use so far ?
Not a lot. You need to find out what the difference is between the
cases where the query runs quickly and those where it doesn't. I'm
betting that the planner is choosing a very bad plan in the slow cases,
but there's not a lot of evidence here to show what or why.
The explain analyze output shows two levels of hash join underneath
four levels of nestloop join, whereas the stack trace looks like there
are five levels of nestloop and only one hash. So this is some evidence
that a different plan is being used in the slow cases. The stack trace
doesn't provide nearly enough info about what that plan is, though.
Do you have geqo_threshold set to less than its default value? Do you
sometimes execute the query with different sets of parameters? Either
of these might lead to changes of plan.
regards, tom lane
Am Montag, 30. Januar 2006 17:42 schrieb Tom Lane:
> Philipp Reisner <philipp.reisner@linbit.com> writes:
> > Version: 8.0.2
>
> I don't think so ... neither bitmap scans nor slot_getattr exist in 8.0.
>
Sorry, a typo, 8.1.2 of course.
> > Is this bug-report of any use so far ?
>
> Not a lot. You need to find out what the difference is between the
> cases where the query runs quickly and those where it doesn't. I'm
> betting that the planner is choosing a very bad plan in the slow cases,
> but there's not a lot of evidence here to show what or why.
>
> The explain analyze output shows two levels of hash join underneath
> four levels of nestloop join, whereas the stack trace looks like there
> are five levels of nestloop and only one hash. So this is some evidence
> that a different plan is being used in the slow cases. The stack trace
> doesn't provide nearly enough info about what that plan is, though.
>
What reasons are there for the planer to choose a different plan ?=20
> Do you have geqo_threshold set to less than its default value? Do you
> sometimes execute the query with different sets of parameters? Either
> of these might lead to changes of plan.
Since we had very bad experience with the generic query optimizer we
completely disabled it. The non geqo plans perform multitudes better=20
on our data-set and work-load. -- And the time to plan the query is
always negligible compared to the execution time.
We have the endless loop about 10 times a day (but execute about 1.5 millio=
n queries a day) :
Program received signal SIGINT, Interrupt.
0x00002aaaaba687b4 in wcsrtombs () from /lib/libc.so.6
(gdb) bt
#0 0x00002aaaaba687b4 in wcsrtombs () from /lib/libc.so.6
#1 0x00002aaaaba163c8 in wcstombs () from /lib/libc.so.6
#2 0x000000000058dcc4 in text_oid ()
#3 0x000000000058deb9 in upper ()
#4 0x00000000004e216e in ExecMakeFunctionResult ()
#5 0x00000000004e210d in ExecMakeFunctionResult ()
#6 0x00000000004e5063 in ExecQual ()
#7 0x00000000004e554e in ExecScan ()
#8 0x00000000004e0cc8 in ExecProcNode ()
#9 0x00000000004ebeb6 in ExecEndHashJoin ()
#10 0x00000000004eb7fa in ExecHashJoin ()
#11 0x00000000004e0d50 in ExecProcNode ()
#12 0x00000000004ee29d in ExecNestLoop ()
#13 0x00000000004e0d36 in ExecProcNode ()
#14 0x00000000004ee261 in ExecNestLoop () <<-----------
#15 0x00000000004e0d36 in ExecProcNode ()
#16 0x00000000004ee261 in ExecNestLoop ()
#17 0x00000000004e0d36 in ExecProcNode ()
#18 0x00000000004ee261 in ExecNestLoop ()
#19 0x00000000004e0d36 in ExecProcNode ()
#20 0x00000000004ee261 in ExecNestLoop ()
#21 0x00000000004e0d36 in ExecProcNode ()
#22 0x00000000004ef57c in ExecSort ()
#23 0x00000000004e0d6a in ExecProcNode ()
#24 0x00000000004df73f in ExecEndPlan ()
#25 0x00000000004dec09 in ExecutorRun ()
#26 0x000000000055f87a in PortalRun ()
#27 0x000000000055f5f9 in PortalRun ()
#28 0x000000000055b561 in pg_plan_queries ()
#29 0x000000000055df8c in PostgresMain ()
#30 0x0000000000539b01 in ClosePostmasterPorts ()
#31 0x00000000005395d0 in ClosePostmasterPorts ()
#32 0x0000000000537b4d in PostmasterMain ()
#33 0x0000000000536e59 in PostmasterMain ()
#34 0x00000000004fda0c in main ()
After detaching with gdb, I killed it. I configured postgres to dump=20
the statement to the logfile with "log_min_error_statement =3D error".
So I have the exact query that caused the problem.=20
This time the plainer says, only explain:
Sort (cost=3D16257.75..16257.76 rows=3D1 width=3D262)
Sort Key: con.shortname
-> Nested Loop (cost=3D1.18..16257.74 rows=3D1 width=3D262)
-> Nested Loop (cost=3D1.18..16254.57 rows=3D1 width=3D130)
-> Nested Loop (cost=3D1.18..16251.50 rows=3D1 width=3D125)
-> Nested Loop (cost=3D1.18..16248.45 rows=3D1 width=
=3D111)
-> Nested Loop (cost=3D1.18..16245.31 rows=3D1=
width=3D86)
Join Filter: ("outer".cel_objid =3D "inner=
".objid)
-> Seq Scan on devices dev (cost=3D0.00.=
.11984.25 rows=3D1 width=3D63)
Filter: ((upper((COALESCE(isactiv, '=
Y'::character varying))::text) =3D 'Y'::text) AND (upper((COALESCE(iscommit=
tedsp, 'Y'::character varying))::text) =3D 'Y'::text) AND (upper((COALESCE(=
iscommittedcust, 'Y'::character varying))::text) =3D 'Y'::text))
-> Hash Left Join (cost=3D1.18..4256.22 =
rows=3D387 width=3D27)
Hash Cond: ("outer".ser_objid =3D "i=
nner".objid)
-> Seq Scan on contractelements cel=
(cost=3D0.00..4253.10 rows=3D387 width=3D21)
Filter: (upper((isactiv)::text=
) =3D 'Y'::text)
-> Hash (cost=3D1.14..1.14 rows=3D=
14 width=3D14)
-> Seq Scan on servicetypes s=
er (cost=3D0.00..1.14 rows=3D14 width=3D14)
-> Index Scan using contracts_pkey on contracts=
con (cost=3D0.00..3.13 rows=3D1 width=3D33)
Index Cond: ("outer".con_objid =3D con.obj=
id)
Filter: ((ccu_objid =3D 3837149) OR (ccu_o=
bjid =3D 3837320) OR (ccu_objid =3D 3837375) OR (ccu_objid =3D 3974872) OR =
(ccu_objid =3D 5032031) OR (ccu_objid =3D 7220313) OR (ccu_objid =3D 156848=
99) OR (ccu_objid =3D 16052168) OR (ccu_objid =3D 19196573) OR (ccu_objid =
=3D 20095712) OR (ccu_objid =3D 22399813) OR (ccu_objid =3D 42092332) OR (c=
cu_objid =3D 42092454) OR (ccu_objid =3D 42092574) OR (ccu_objid =3D 428869=
47) OR (ccu_objid =3D 43813234))
-> Index Scan using devicetypes_pkey on devicetypes d=
ty (cost=3D0.00..3.04 rows=3D1 width=3D18)
Index Cond: (dty.objid =3D "outer".dty_objid)
-> Index Scan using bpartners_pkey on bpartners man (cost=
=3D0.00..3.06 rows=3D1 width=3D13)
Index Cond: (man.objid =3D "outer".bpa_objid)
-> Index Scan using locations_pkey on locations loc (cost=3D0.00=
..3.12 rows=3D1 width=3D136)
Index Cond: (loc.objid =3D "outer".loc_objid)
Filter: (upper((shortname)::text) =3D '5195'::text)
(26 rows)
Explain and execute does not terminate... even after hours.
This time I _CAN_ _REPRODUCE_ the issue in our staging system !! Would it =
help
to run the database server with debug symbols ? That would give more inform=
ation
in the stack traceback ...
Tom, could you give us an advise for what we should look for ? How we should
continue in tracing the bug down ?
In case you care, here is the query as well:
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 loc.locationsta=
teTo THEN loc.locationstateText
WHEN CURRENT_DATE between loc.locationstate2From and loc.locationsta=
te2To THEN loc.locationstate2Text
ELSE null
END
, CASE
WHEN CURRENT_DATE between loc.locationstateFrom and loc.locationsta=
teTo THEN loc.locationstateColorCode
WHEN CURRENT_DATE between loc.locationstate2From and loc.locationsta=
te2To 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.ccu_objid in
(3837149,3837320,3837375,3974872,5032031,7220313,15684899,16052168,191965=
73,20095712,22399813,42092332,42092454,42092574,42886947,43813234) 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 '5195'
order by 18 ASC
-philipp
--=20
: Dipl-Ing Philipp Reisner Tel +43-1-8178292-50 :
: LINBIT Information Technologies GmbH Fax +43-1-8178292-82 :
: Sch=C3=B6nbrunnerstr 244, 1120 Vienna, Austria http://www.linbit.com :
> > The explain analyze output shows two levels of hash join underneath
> > four levels of nestloop join, whereas the stack trace looks like there
> > are five levels of nestloop and only one hash. So this is some evidence
> > that a different plan is being used in the slow cases. The stack trace
> > doesn't provide nearly enough info about what that plan is, though.
>
> What reasons are there for the planer to choose a different plan ?
>
Well after more research it turned out that sometimes we have a plan=20
that executes in less than 2 seconds, and somethimes we get a plan=20
does not terminate within 1h30 of CPU time.
The only thing that is to mention about the planer configuration is, that
we disabled the geqo.=20
What does influence the decisions of the planer ?
What can we do to make the planers decisions more exact ?
The cost estimation of the two plans shows only a very little difference,
while in real, it difference is very significant.
The good plan:
Sort (cost=3D12862.86..12862.87 rows=3D1 width=3D483)
Sort Key: con.shortname
-> Nested Loop (cost=3D10111.09..12862.85 rows=3D1 width=3D483)
-> Nested Loop (cost=3D10109.09..12859.83 rows=3D1 width=3D478)
-> Nested Loop (cost=3D10109.09..12856.79 rows=3D1 width=
=3D129)
-> Nested Loop (cost=3D10109.09..12853.76 rows=3D1 w=
idth=3D115)
-> Merge Join (cost=3D10109.09..12850.69 rows=
=3D1 width=3D88)
Merge Cond: ("outer".objid =3D "inner".cel=
_objid)
-> Nested Loop Left Join (cost=3D1.15..5=
719.95 rows=3D459 width=3D28)
Join Filter: ("inner".objid =3D "out=
er".ser_objid)
-> Index Scan using contractelement=
s_pkey on contractelements cel (cost=3D0.00..5574.21 rows=3D459 width=3D22)
Filter: (upper((isactiv)::text=
) =3D 'Y'::text)
-> Materialize (cost=3D1.15..1.29 =
rows=3D14 width=3D14)
-> Seq Scan on servicetypes s=
er (cost=3D0.00..1.14 rows=3D14 width=3D14)
-> Sort (cost=3D10107.93..10107.94 rows=
=3D1 width=3D64)
Sort Key: dev.cel_objid
-> Seq Scan on devices dev (cost=
=3D0.00..10107.92 rows=3D1 width=3D64)
Filter: ((upper((COALESCE(isac=
tiv, 'Y'::character varying))::text) =3D 'Y'::text) AND (upper((COALESCE(is=
committedsp, 'Y'::character varying))::text) =3D 'Y'::text) AND (upper((COA=
LESCE(iscommittedcust, 'Y'::character varying))::text) =3D 'Y'::text))
-> Index Scan using contracts_pkey on contracts=
con (cost=3D0.00..3.06 rows=3D1 width=3D35)
Index Cond: ("outer".con_objid =3D con.obj=
id)
Filter: ((ccu_objid =3D 3837149) OR (ccu_o=
bjid =3D 3837320) OR (ccu_objid =3D 3837375) OR (ccu_objid =3D 3974872) OR =
(ccu_objid =3D 5032031) OR (ccu_objid =3D 7220313) OR (ccu_objid =3D 156848=
99) OR (ccu_objid =3D 16052168) OR (ccu_objid =3D 19196573) OR (ccu_objid =
=3D 20095712) OR (ccu_objid =3D 22399813) OR (ccu_objid =3D 42092332) OR (c=
cu_objid =3D 42092454) OR (ccu_objid =3D 42092574) OR (ccu_objid =3D 428869=
47) OR (ccu_objid =3D 43813234))
-> Index Scan using devicetypes_pkey on devicetypes d=
ty (cost=3D0.00..3.02 rows=3D1 width=3D18)
Index Cond: (dty.objid =3D "outer".dty_objid)
-> Index Scan using locations_pkey on locations loc (cost=
=3D0.00..3.03 rows=3D1 width=3D353)
Index Cond: (loc.objid =3D "outer".loc_objid)
Filter: (upper((shortname)::text) =3D '5195'::text)
-> Bitmap Heap Scan on bpartners man (cost=3D2.00..2.97 rows=3D1=
width=3D13)
Recheck Cond: (man.objid =3D "outer".bpa_objid)
-> Bitmap Index Scan on bpartners_pkey (cost=3D0.00..2.00 =
rows=3D1 width=3D0)
Index Cond: (man.objid =3D "outer".bpa_objid)
(30 rows)
The bad plan:
Sort (cost=3D16257.75..16257.76 rows=3D1 width=3D262)
Sort Key: con.shortname
-> Nested Loop (cost=3D1.18..16257.74 rows=3D1 width=3D262)
-> Nested Loop (cost=3D1.18..16254.57 rows=3D1 width=3D130)
-> Nested Loop (cost=3D1.18..16251.50 rows=3D1 width=3D125)
-> Nested Loop (cost=3D1.18..16248.45 rows=3D1 width=
=3D111)
-> Nested Loop (cost=3D1.18..16245.31 rows=3D1=
width=3D86)
Join Filter: ("outer".cel_objid =3D "inner=
".objid)
-> Seq Scan on devices dev (cost=3D0.00.=
.11984.25 rows=3D1 width=3D63)
Filter: ((upper((COALESCE(isactiv, '=
Y'::character varying))::text) =3D 'Y'::text) AND (upper((COALESCE(iscommit=
tedsp, 'Y'::character varying))::text) =3D 'Y'::text) AND (upper((COALESCE(=
iscommittedcust, 'Y'::character varying))::text) =3D 'Y'::text))
-> Hash Left Join (cost=3D1.18..4256.22 =
rows=3D387 width=3D27)
Hash Cond: ("outer".ser_objid =3D "i=
nner".objid)
-> Seq Scan on contractelements cel=
(cost=3D0.00..4253.10 rows=3D387 width=3D21)
Filter: (upper((isactiv)::text=
) =3D 'Y'::text)
-> Hash (cost=3D1.14..1.14 rows=3D=
14 width=3D14)
-> Seq Scan on servicetypes s=
er (cost=3D0.00..1.14 rows=3D14 width=3D14)
-> Index Scan using contracts_pkey on contracts=
con (cost=3D0.00..3.13 rows=3D1 width=3D33)
Index Cond: ("outer".con_objid =3D con.obj=
id)
Filter: ((ccu_objid =3D 3837149) OR (ccu_o=
bjid =3D 3837320) OR (ccu_objid =3D 3837375) OR (ccu_objid =3D 3974872) OR =
(ccu_objid =3D 5032031) OR (ccu_objid =3D 7220313) OR (ccu_objid =3D 156848=
99) OR (ccu_objid =3D 16052168) OR (ccu_objid =3D 19196573) OR (ccu_objid =
=3D 20095712) OR (ccu_objid =3D 22399813) OR (ccu_objid =3D 42092332) OR (c=
cu_objid =3D 42092454) OR (ccu_objid =3D 42092574) OR (ccu_objid =3D 428869=
47) OR (ccu_objid =3D 43813234))
-> Index Scan using devicetypes_pkey on devicetypes d=
ty (cost=3D0.00..3.04 rows=3D1 width=3D18)
Index Cond: (dty.objid =3D "outer".dty_objid)
-> Index Scan using bpartners_pkey on bpartners man (cost=
=3D0.00..3.06 rows=3D1 width=3D13)
Index Cond: (man.objid =3D "outer".bpa_objid)
-> Index Scan using locations_pkey on locations loc (cost=3D0.00=
..3.12 rows=3D1 width=3D136)
Index Cond: (loc.objid =3D "outer".loc_objid)
Filter: (upper((shortname)::text) =3D '5195'::text)
-philipp
--=20
: Dipl-Ing Philipp Reisner Tel +43-1-8178292-50 :
: LINBIT Information Technologies GmbH Fax +43-1-8178292-82 :
: Sch=C3=B6nbrunnerstr 244, 1120 Vienna, Austria http://www.linbit.com :
Hi,
On Monday 30 January 2006 17:42, Tom Lane wrote:
> > Version: 8.0.2
> I don't think so ... neither bitmap scans nor slot_getattr exist in 8.0.
oops. it is 8.1.2 ..
> Not a lot. You need to find out what the difference is between the
> cases where the query runs quickly and those where it doesn't. I'm
> betting that the planner is choosing a very bad plan in the slow cases,
> but there's not a lot of evidence here to show what or why.
it is exactly the same query. I rather think that there is some kind of mem=
ory=20
corruption causing that error, so that the query runs fine in a "fresh"=20
postgres process but fails when e.g. malloc() returns a block which has=20
already old data in it or the stack contains already data from an old stack
fragment. We hunted a bug with simmilar symptomps a while ago:
http://archives.postgresql.org/pgsql-bugs/2003-08/msg00051.php
> Do you have geqo_threshold set to less than its default value?
We have disabled geqo on that system.
> sometimes execute the query with different sets of parameters?
> Either of these might lead to changes of plan.
no. it is exactly the same query that sometimes executes fast and sometimes=
=20
hangs for hours until we kill the process.
yours,
- clifford
--=20
: Clifford Wolf =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0=
=C2=A0 =C2=A0 =C2=A0 =C2=A0Tel +43-1-8178292-00 :
: LINBIT Information Technologies GmbH =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0Fa=
x +43-1-8178292-82 :
: Sch=C3=B6nbrunnerstr 244, 1120 Vienna, Austria =C2=A0 =C2=A0http://www.li=
nbit.com :
Philipp Reisner <philipp.reisner@linbit.com> writes:
> Well after more research it turned out that sometimes we have a plan
> that executes in less than 2 seconds, and somethimes we get a plan
> does not terminate within 1h30 of CPU time.
Could you send EXPLAIN ANALYZE output for this (at least for the fast
case)? Presumably some of the planner's estimates are way off, but
there's no way to know which ones from just EXPLAIN.
>> What reasons are there for the planer to choose a different plan ?
It looks to me like the statistics have changed, because it's showing
different rowcount and width estimates for the same scan:
> -> Index Scan using contractelements_pkey on contractelements cel
(cost=0.00..5574.21rows=459 width=22)
> Filter: (upper((isactiv)::text) = 'Y'::text)
> -> Seq Scan on contractelements cel (cost=0.00..4253.10 rows=387 width=21)
> Filter: (upper((isactiv)::text) = 'Y'::text)
Perhaps you ran VACUUM or ANALYZE in between, or autovacuum did so for
you?
regards, tom lane
---------- Weitergeleitete Nachricht ----------
Subject: Re: [BUGS] Endless loop in ExecNestLoop
Date: Dienstag, 31. Januar 2006 16:39
From: Tom Lane <tgl@sss.pgh.pa.us>
To: Philipp Reisner <philipp.reisner@linbit.com>
Cc: pgsql-bugs@postgresql.org
Philipp Reisner <philipp.reisner@linbit.com> writes:
> Well after more research it turned out that sometimes we have a plan
> that executes in less than 2 seconds, and somethimes we get a plan
> does not terminate within 1h30 of CPU time.
Could you send EXPLAIN ANALYZE output for this (at least for the fast
case)? Presumably some of the planner's estimates are way off, but
there's no way to know which ones from just EXPLAIN.
>> What reasons are there for the planer to choose a different plan ?
It looks to me like the statistics have changed, because it's showing
different rowcount and width estimates for the same scan:
> -> Index Scan using
> contractelements_pkey on contractelements cel (cost=3D0.00..5574.21 rows=
=3D459
> width=3D22) Filter: (upper((isactiv)::text) =3D 'Y'::text)
>
> -> Seq Scan on contractelements c=
el
> (cost=3D0.00..4253.10 rows=3D387 width=3D21) Filter: (upper((isactiv)::t=
ext) =3D
> 'Y'::text)
Perhaps you ran VACUUM or ANALYZE in between, or autovacuum did so for
you?
regards, tom lane
---------------------------(end of broadcast)---------------------------
TIP 4: Have you searched our list archives?
http://archives.postgresql.org
-------------------------------------------------------
--=20
: Dipl-Ing Philipp Reisner Tel +43-1-8178292-50 :
: LINBIT Information Technologies GmbH Fax +43-1-8178292-82 :
: Sch=C3=B6nbrunnerstr 244, 1120 Vienna, Austria http://www.linbit.com :