Re: Endless loop in ExecNestLoop
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
Import Notes
Reply to msg id not found: 200601301745.07031.philipp.reisner@linbit.comReference msg id not found: 200601301745.07031.philipp.reisner@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 memory
corruption causing that error, so that the query runs fine in a "fresh"
postgres process but fails when e.g. malloc() returns a block which has
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
hangs for hours until we kill the process.
yours,
- clifford
--
: Clifford Wolf Tel +43-1-8178292-00 :
: LINBIT Information Technologies GmbH Fax +43-1-8178292-82 :
: Schönbrunnerstr 244, 1120 Vienna, Austria http://www.linbit.com :
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 ?
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
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 million 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
the statement to the logfile with "log_min_error_statement = error".
So I have the exact query that caused the problem.
This time the plainer says, only explain:
Sort (cost=16257.75..16257.76 rows=1 width=262)
Sort Key: con.shortname
-> Nested Loop (cost=1.18..16257.74 rows=1 width=262)
-> Nested Loop (cost=1.18..16254.57 rows=1 width=130)
-> Nested Loop (cost=1.18..16251.50 rows=1 width=125)
-> Nested Loop (cost=1.18..16248.45 rows=1 width=111)
-> Nested Loop (cost=1.18..16245.31 rows=1 width=86)
Join Filter: ("outer".cel_objid = "inner".objid)
-> Seq Scan on devices dev (cost=0.00..11984.25 rows=1 width=63)
Filter: ((upper((COALESCE(isactiv, 'Y'::character varying))::text) = 'Y'::text) AND (upper((COALESCE(iscommittedsp, 'Y'::character varying))::text) = 'Y'::text) AND (upper((COALESCE(iscommittedcust, 'Y'::character varying))::text) = 'Y'::text))
-> Hash Left Join (cost=1.18..4256.22 rows=387 width=27)
Hash Cond: ("outer".ser_objid = "inner".objid)
-> Seq Scan on contractelements cel (cost=0.00..4253.10 rows=387 width=21)
Filter: (upper((isactiv)::text) = 'Y'::text)
-> Hash (cost=1.14..1.14 rows=14 width=14)
-> Seq Scan on servicetypes ser (cost=0.00..1.14 rows=14 width=14)
-> Index Scan using contracts_pkey on contracts con (cost=0.00..3.13 rows=1 width=33)
Index Cond: ("outer".con_objid = con.objid)
Filter: ((ccu_objid = 3837149) OR (ccu_objid = 3837320) OR (ccu_objid = 3837375) OR (ccu_objid = 3974872) OR (ccu_objid = 5032031) OR (ccu_objid = 7220313) OR (ccu_objid = 15684899) OR (ccu_objid = 16052168) OR (ccu_objid = 19196573) OR (ccu_objid = 20095712) OR (ccu_objid = 22399813) OR (ccu_objid = 42092332) OR (ccu_objid = 42092454) OR (ccu_objid = 42092574) OR (ccu_objid = 42886947) OR (ccu_objid = 43813234))
-> Index Scan using devicetypes_pkey on devicetypes dty (cost=0.00..3.04 rows=1 width=18)
Index Cond: (dty.objid = "outer".dty_objid)
-> Index Scan using bpartners_pkey on bpartners man (cost=0.00..3.06 rows=1 width=13)
Index Cond: (man.objid = "outer".bpa_objid)
-> Index Scan using locations_pkey on locations loc (cost=0.00..3.12 rows=1 width=136)
Index Cond: (loc.objid = "outer".loc_objid)
Filter: (upper((shortname)::text) = '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 information
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.locationstateTo THEN loc.locationstateText
WHEN CURRENT_DATE between loc.locationstate2From and loc.locationstate2To THEN loc.locationstate2Text
ELSE null
END
, CASE
WHEN CURRENT_DATE between loc.locationstateFrom and loc.locationstateTo THEN loc.locationstateColorCode
WHEN CURRENT_DATE between loc.locationstate2From and 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 = cel.ser_objid,
devices dev, locations loc, devicetypes dty, bpartners man
where con.ccu_objid in
(3837149,3837320,3837375,3974872,5032031,7220313,15684899,16052168,19196573,20095712,22399813,42092332,42092454,42092574,42886947,43813234) and cel.con_objid = con.objid
and dev.cel_objid = cel.objid
and loc.objid = dev.loc_objid
and dty.objid = dev.dty_objid
and man.objid = dty.bpa_objid
and upper(cel.isActiv) = 'Y'
and upper(coalesce(dev.isActiv,'Y')) = 'Y'
and upper(coalesce(dev.IsCommittedSP,'Y')) = 'Y'
and upper(coalesce(dev.IsCommittedCust,'Y')) = 'Y'
and upper(loc.shortName) = '5195'
order by 18 ASC
-philipp
--
: Dipl-Ing Philipp Reisner Tel +43-1-8178292-50 :
: LINBIT Information Technologies GmbH Fax +43-1-8178292-82 :
: Schönbrunnerstr 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
that executes in less than 2 seconds, and somethimes we get a plan
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.
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=12862.86..12862.87 rows=1 width=483)
Sort Key: con.shortname
-> Nested Loop (cost=10111.09..12862.85 rows=1 width=483)
-> Nested Loop (cost=10109.09..12859.83 rows=1 width=478)
-> Nested Loop (cost=10109.09..12856.79 rows=1 width=129)
-> Nested Loop (cost=10109.09..12853.76 rows=1 width=115)
-> Merge Join (cost=10109.09..12850.69 rows=1 width=88)
Merge Cond: ("outer".objid = "inner".cel_objid)
-> Nested Loop Left Join (cost=1.15..5719.95 rows=459 width=28)
Join Filter: ("inner".objid = "outer".ser_objid)
-> Index Scan using contractelements_pkey on contractelements cel (cost=0.00..5574.21 rows=459 width=22)
Filter: (upper((isactiv)::text) = 'Y'::text)
-> Materialize (cost=1.15..1.29 rows=14 width=14)
-> Seq Scan on servicetypes ser (cost=0.00..1.14 rows=14 width=14)
-> Sort (cost=10107.93..10107.94 rows=1 width=64)
Sort Key: dev.cel_objid
-> Seq Scan on devices dev (cost=0.00..10107.92 rows=1 width=64)
Filter: ((upper((COALESCE(isactiv, 'Y'::character varying))::text) = 'Y'::text) AND (upper((COALESCE(iscommittedsp, 'Y'::character varying))::text) = 'Y'::text) AND (upper((COALESCE(iscommittedcust, 'Y'::character varying))::text) = 'Y'::text))
-> Index Scan using contracts_pkey on contracts con (cost=0.00..3.06 rows=1 width=35)
Index Cond: ("outer".con_objid = con.objid)
Filter: ((ccu_objid = 3837149) OR (ccu_objid = 3837320) OR (ccu_objid = 3837375) OR (ccu_objid = 3974872) OR (ccu_objid = 5032031) OR (ccu_objid = 7220313) OR (ccu_objid = 15684899) OR (ccu_objid = 16052168) OR (ccu_objid = 19196573) OR (ccu_objid = 20095712) OR (ccu_objid = 22399813) OR (ccu_objid = 42092332) OR (ccu_objid = 42092454) OR (ccu_objid = 42092574) OR (ccu_objid = 42886947) OR (ccu_objid = 43813234))
-> Index Scan using devicetypes_pkey on devicetypes dty (cost=0.00..3.02 rows=1 width=18)
Index Cond: (dty.objid = "outer".dty_objid)
-> Index Scan using locations_pkey on locations loc (cost=0.00..3.03 rows=1 width=353)
Index Cond: (loc.objid = "outer".loc_objid)
Filter: (upper((shortname)::text) = '5195'::text)
-> Bitmap Heap Scan on bpartners man (cost=2.00..2.97 rows=1 width=13)
Recheck Cond: (man.objid = "outer".bpa_objid)
-> Bitmap Index Scan on bpartners_pkey (cost=0.00..2.00 rows=1 width=0)
Index Cond: (man.objid = "outer".bpa_objid)
(30 rows)
The bad plan:
Sort (cost=16257.75..16257.76 rows=1 width=262)
Sort Key: con.shortname
-> Nested Loop (cost=1.18..16257.74 rows=1 width=262)
-> Nested Loop (cost=1.18..16254.57 rows=1 width=130)
-> Nested Loop (cost=1.18..16251.50 rows=1 width=125)
-> Nested Loop (cost=1.18..16248.45 rows=1 width=111)
-> Nested Loop (cost=1.18..16245.31 rows=1 width=86)
Join Filter: ("outer".cel_objid = "inner".objid)
-> Seq Scan on devices dev (cost=0.00..11984.25 rows=1 width=63)
Filter: ((upper((COALESCE(isactiv, 'Y'::character varying))::text) = 'Y'::text) AND (upper((COALESCE(iscommittedsp, 'Y'::character varying))::text) = 'Y'::text) AND (upper((COALESCE(iscommittedcust, 'Y'::character varying))::text) = 'Y'::text))
-> Hash Left Join (cost=1.18..4256.22 rows=387 width=27)
Hash Cond: ("outer".ser_objid = "inner".objid)
-> Seq Scan on contractelements cel (cost=0.00..4253.10 rows=387 width=21)
Filter: (upper((isactiv)::text) = 'Y'::text)
-> Hash (cost=1.14..1.14 rows=14 width=14)
-> Seq Scan on servicetypes ser (cost=0.00..1.14 rows=14 width=14)
-> Index Scan using contracts_pkey on contracts con (cost=0.00..3.13 rows=1 width=33)
Index Cond: ("outer".con_objid = con.objid)
Filter: ((ccu_objid = 3837149) OR (ccu_objid = 3837320) OR (ccu_objid = 3837375) OR (ccu_objid = 3974872) OR (ccu_objid = 5032031) OR (ccu_objid = 7220313) OR (ccu_objid = 15684899) OR (ccu_objid = 16052168) OR (ccu_objid = 19196573) OR (ccu_objid = 20095712) OR (ccu_objid = 22399813) OR (ccu_objid = 42092332) OR (ccu_objid = 42092454) OR (ccu_objid = 42092574) OR (ccu_objid = 42886947) OR (ccu_objid = 43813234))
-> Index Scan using devicetypes_pkey on devicetypes dty (cost=0.00..3.04 rows=1 width=18)
Index Cond: (dty.objid = "outer".dty_objid)
-> Index Scan using bpartners_pkey on bpartners man (cost=0.00..3.06 rows=1 width=13)
Index Cond: (man.objid = "outer".bpa_objid)
-> Index Scan using locations_pkey on locations loc (cost=0.00..3.12 rows=1 width=136)
Index Cond: (loc.objid = "outer".loc_objid)
Filter: (upper((shortname)::text) = '5195'::text)
-philipp
--
: Dipl-Ing Philipp Reisner Tel +43-1-8178292-50 :
: LINBIT Information Technologies GmbH Fax +43-1-8178292-82 :
: Schönbrunnerstr 244, 1120 Vienna, Austria http://www.linbit.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.21 rows=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=0.00..5574.21 rows=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
---------------------------(end of broadcast)---------------------------
TIP 4: Have you searched our list archives?
http://archives.postgresql.org
-------------------------------------------------------
--
: Dipl-Ing Philipp Reisner Tel +43-1-8178292-50 :
: LINBIT Information Technologies GmbH Fax +43-1-8178292-82 :
: Schönbrunnerstr 244, 1120 Vienna, Austria http://www.linbit.com :