Thread: BUG #5673: Optimizer creates strange execution plan leading to wrong results
BUG #5673: Optimizer creates strange execution plan leading to wrong results
From
"David Schmitt"
Date:
The following bug has been logged online:
Bug reference: 5673
Logged by: David Schmitt
Email address: david@dasz.at
PostgreSQL version: 8.4.4
Operating system: Windows 7
Description: Optimizer creates strange execution plan leading to
wrong results
Details:
Background: The following statement is a slightly modfied version of a
statement created by the Entity Framework OR-Mapper when doing a specific
query involving the DefaultPropertyValues base class and the three child
classes CurrentDateTimeDefaultValues, NewGuidDefaultValues,
EnumDefaultValues. There are 60 unique rows in DefaultProperty Values, each
of which is referenced by exactly one row in either
CurrentDateTimeDefaultValues(5 rows), NewGuidDefaultValues(54 rows), or
EnumDefaultValues (1 row). All tables have an ID column and appropriate
PK/FK constraints modeling the inheritance.
Analysis: In the first case the optimizer creates a single Append operation
for the three sequential table scans (lines 10-13) and creates an additional
Index Scan on EnumDefaultValues (lines 14,15) which results in 61 rows
returned in 09. Particularily suspicious are the tow references to the
Extent5 alias on lines 13 and 14. In the second run, I dropped the primary
key on EnumDefaultValues. Now the Append on line 09 returns 60 rows and the
execution plan references EnumDefaultValues only once.
select *
from "dbo"."DefaultPropertyValues" AS "Extent1"
INNER JOIN "dbo"."DefaultPropertyValues" AS "Extent2" ON
"Extent1"."ID"="Extent2"."ID"
LEFT JOIN (
SELECT "UnionAll1"."ID" AS "C1","UnionAll1"."C1" AS "C2","UnionAll1"."C2"
AS "C3","UnionAll1"."C3" AS "C4","UnionAll1"."C4" AS "fk_EnumVal" FROM (
SELECT "Extent3"."ID" AS "ID",TRUE AS "C1",FALSE AS "C2",FALSE AS
"C3",CAST (NULL AS int4) AS "C4"
FROM "dbo"."CurrentDateTimeDefaultValues" AS "Extent3"
UNION ALL
SELECT "Extent4"."ID" AS "ID", TRUE AS "C1",FALSE AS "C2",TRUE AS
"C3",CAST (NULL AS int4) AS "C4"
FROM "dbo"."NewGuidDefaultValues" AS "Extent4") AS "UnionAll1"
UNION ALL
SELECT "Extent5"."ID" AS "ID",FALSE AS "C1",TRUE AS "C2",FALSE AS
"C3","Extent5"."fk_EnumValue" AS "fk_EnumValue"
FROM "dbo"."EnumDefaultValues" AS "Extent5") AS "UnionAll2"
ON "Extent2"."ID"="UnionAll2"."C1"
WHERE ("Extent1"."fk_Property" IS NOT NULL ) AND ("Extent1"."fk_Property"=
(((783))))
Result:
60;"2010-09-20 13:22:17.773308";"2010-09-20
13:22:17.773308";"ecbd6901-13e8-4beb-a6a2-0548eba345a8";;;783;60;"2010-09-20
13:22:17.773308";"2010-09-20
13:22:17.773308";"ecbd6901-13e8-4beb-a6a2-0548eba345a8";;;783;60;f;t;f;3
60;"2010-09-20 13:22:17.773308";"2010-09-20
13:22:17.773308";"ecbd6901-13e8-4beb-a6a2-0548eba345a8";;;783;60;"2010-09-20
13:22:17.773308";"2010-09-20
13:22:17.773308";"ecbd6901-13e8-4beb-a6a2-0548eba345a8";;;783;60;f;t;f;3
EXPLAIN ANALYZE:
01 "Nested Loop Left Join (cost=1.76..7.42 rows=1 width=100) (actual
time=0.121..0.134 rows=2 loops=1)"
02 " Join Filter: ("Extent2"."ID" = "Extent3"."ID")"
03 " -> Hash Join (cost=1.76..3.60 rows=1 width=96) (actual
time=0.061..0.061 rows=1 loops=1)"
04 " Hash Cond: ("Extent2"."ID" = "Extent1"."ID")"
05 " -> Seq Scan on "DefaultPropertyValues" "Extent2"
(cost=0.00..1.60 rows=60 width=48) (actual time=0.008..0.013 rows=60
loops=1)"
06 " -> Hash (cost=1.75..1.75 rows=1 width=48) (actual
time=0.025..0.025 rows=1 loops=1)"
07 " -> Seq Scan on "DefaultPropertyValues" "Extent1"
(cost=0.00..1.75 rows=1 width=48) (actual time=0.023..0.024 rows=1
loops=1)"
08 " Filter: (("fk_Property" IS NOT NULL) AND
("fk_Property" = 783))"
09 " -> Append (cost=0.00..4.07 rows=61 width=11) (actual
time=0.005..0.046 rows=61 loops=1)"
10 " -> Append (cost=0.00..3.60 rows=60 width=11) (actual
time=0.004..0.028 rows=60 loops=1)"
11 " -> Seq Scan on "CurrentDateTimeDefaultValues" "Extent3"
(cost=0.00..1.05 rows=5 width=11) (actual time=0.004..0.005 rows=5
loops=1)"
12 " -> Seq Scan on "NewGuidDefaultValues" "Extent4"
(cost=0.00..1.54 rows=54 width=11) (actual time=0.002..0.014 rows=54
loops=1)"
13 " -> Seq Scan on "EnumDefaultValues" "Extent5"
(cost=0.00..1.01 rows=1 width=11) (actual time=0.002..0.002 rows=1
loops=1)"
14 " -> Index Scan using "PK_[zbox].[dbo].[EnumDefaultValues]" on
"EnumDefaultValues" "Extent5" (cost=0.00..0.47 rows=1 width=11) (actual
time=0.009..0.010 rows=1 loops=1)"
15 " Index Cond: ("Extent2"."ID" = "Extent5"."ID")"
16 "Total runtime: 0.258 ms"
Result:
60;"2010-09-20 13:22:17.773308";"2010-09-20
13:22:17.773308";"ecbd6901-13e8-4beb-a6a2-0548eba345a8";;;783;60;"2010-09-20
13:22:17.773308";"2010-09-20
13:22:17.773308";"ecbd6901-13e8-4beb-a6a2-0548eba345a8";;;783;60;f;t;f;3
EXPLAIN ANALYZE:
01 "Nested Loop Left Join (cost=1.76..7.95 rows=1 width=100) (actual
time=0.109..0.111 rows=1 loops=1)"
02 " Join Filter: ("Extent2"."ID" = "Extent3"."ID")"
03 " -> Hash Join (cost=1.76..3.60 rows=1 width=96) (actual
time=0.057..0.058 rows=1 loops=1)"
04 " Hash Cond: ("Extent2"."ID" = "Extent1"."ID")"
05 " -> Seq Scan on "DefaultPropertyValues" "Extent2"
(cost=0.00..1.60 rows=60 width=48) (actual time=0.006..0.011 rows=60
loops=1)"
06 " -> Hash (cost=1.75..1.75 rows=1 width=48) (actual
time=0.024..0.024 rows=1 loops=1)"
07 " -> Seq Scan on "DefaultPropertyValues" "Extent1"
(cost=0.00..1.75 rows=1 width=48) (actual time=0.022..0.023 rows=1
loops=1)"
08 " Filter: (("fk_Property" IS NOT NULL) AND
("fk_Property" = 783))"
09 " -> Append (cost=0.00..3.60 rows=60 width=11) (actual
time=0.004..0.027 rows=60 loops=1)"
10 " -> Seq Scan on "CurrentDateTimeDefaultValues" "Extent3"
(cost=0.00..1.05 rows=5 width=11) (actual time=0.003..0.005 rows=5
loops=1)"
11 " -> Seq Scan on "NewGuidDefaultValues" "Extent4"
(cost=0.00..1.54 rows=54 width=11) (actual time=0.002..0.014 rows=54
loops=1)"
12 " -> Seq Scan on "EnumDefaultValues" "Extent5" (cost=0.00..1.01
rows=1 width=11) (actual time=0.002..0.002 rows=1 loops=1)"
13 "Total runtime: 0.214 ms"
Other versions:
Postgresql 8.3.11-0lenny1 on Debian lenny does not exhibit this problem.
The backported 8.4.4-1~bpo50+1 for lenny does exhibit the problem.
Re: BUG #5673: Optimizer creates strange execution plan leading to wrong results
From
Tom Lane
Date:
"David Schmitt" <david@dasz.at> writes:
> Description: Optimizer creates strange execution plan leading to
> wrong results
Please supply a self-contained example demonstrating the incorrect results.
The information you've provided is completely inadequate for
investigating this problem report. A SQL script that creates some test
tables and executes a query that gives wrong answers would be helpful.
regards, tom lane
Re: BUG #5673: Optimizer creates strange execution plan leading to wrong results
From
David Schmitt
Date:
On 9/23/2010 5:33 PM, Tom Lane wrote:
> "David Schmitt"<david@dasz.at> writes:
>> Description: Optimizer creates strange execution plan leading to
>> wrong results
>
> Please supply a self-contained example demonstrating the incorrect results.
> The information you've provided is completely inadequate for
> investigating this problem report. A SQL script that creates some test
> tables and executes a query that gives wrong answers would be helpful.
Executing the attached example.sql on a fresh database demonstrates the
problem I'm seeing:
> postgres@db:~$ dropdb test; createdb test; psql test < example.sql
[load dump]
[execute query]
> ID | CreatedOn | ChangedOn | ExportGuid | fk_CreatedBy |
fk_ChangedBy| fk_Property | ID | CreatedOn | ChangedOn | ExportGuid
| fk_CreatedBy | fk_ChangedBy | fk_Property | C1 | C2 | C3 | C4 | fk_EnumVal
>
----+----------------------------+----------------------------+--------------------------------------+--------------+--------------+-------------+----+----------------------------+----------------------------+--------------------------------------+--------------+--------------+-------------+----+----+----+----+------------
> 60 | 2010-09-20 13:22:17.773308 | 2010-09-20 13:22:17.773308 | ecbd6901-13e8-4beb-a6a2-0548eba345a8 | |
| 783 | 60 | 2010-09-20 13:22:17.773308 | 2010-09-20 13:22:17.773308 |
ecbd6901-13e8-4beb-a6a2-0548eba345a8| | | 783 | 60 | f | t | f | 3
> 60 | 2010-09-20 13:22:17.773308 | 2010-09-20 13:22:17.773308 | ecbd6901-13e8-4beb-a6a2-0548eba345a8 | |
| 783 | 60 | 2010-09-20 13:22:17.773308 | 2010-09-20 13:22:17.773308 |
ecbd6901-13e8-4beb-a6a2-0548eba345a8| | | 783 | 60 | f | t | f | 3
> (2 rows)
>
[remove pk]
[execute query again]
> ALTER TABLE
> ID | CreatedOn | ChangedOn | ExportGuid | fk_CreatedBy |
fk_ChangedBy| fk_Property | ID | CreatedOn | ChangedOn | ExportGuid
| fk_CreatedBy | fk_ChangedBy | fk_Property | C1 | C2 | C3 | C4 | fk_EnumVal
>
----+----------------------------+----------------------------+--------------------------------------+--------------+--------------+-------------+----+----------------------------+----------------------------+--------------------------------------+--------------+--------------+-------------+----+----+----+----+------------
> 60 | 2010-09-20 13:22:17.773308 | 2010-09-20 13:22:17.773308 | ecbd6901-13e8-4beb-a6a2-0548eba345a8 | |
| 783 | 60 | 2010-09-20 13:22:17.773308 | 2010-09-20 13:22:17.773308 |
ecbd6901-13e8-4beb-a6a2-0548eba345a8| | | 783 | 60 | f | t | f | 3
> (1 row)
Hopefully, this helps you debugging it! Thanks for your time and work on
the otherwise really great PostgreSQL.
Best Regards, David
--
dasz.at OG Tel: +43 (0)664 2602670 Web: http://dasz.at
Klosterneuburg UID: ATU64260999
FB-Nr.: FN 309285 g FB-Gericht: LG Korneuburg
Attachment
Re: BUG #5673: Optimizer creates strange execution plan leading to wrong results
From
Tom Lane
Date:
David Schmitt <david@dasz.at> writes:
> On 9/23/2010 5:33 PM, Tom Lane wrote:
>> Please supply a self-contained example demonstrating the incorrect results.
> Executing the attached example.sql on a fresh database demonstrates the
> problem I'm seeing:
Yup, it sure does. Looking for the cause now. Thanks for the report!
regards, tom lane
Re: BUG #5673: Optimizer creates strange execution plan leading to wrong results
From
Tom Lane
Date:
David Schmitt <david@dasz.at> writes:
> Executing the attached example.sql on a fresh database demonstrates the
> problem I'm seeing:
Found it. If you need a patch right away, it's a one-liner:
diff --git a/src/backend/optimizer/path/allpaths.c b/src/backend/optimizer/path/allpaths.c
index 2d86da3..b7cf0b8 100644
--- a/src/backend/optimizer/path/allpaths.c
+++ b/src/backend/optimizer/path/allpaths.c
@@ -425,7 +425,7 @@ set_append_rel_pathlist(PlannerInfo *root, RelOptInfo *rel,
childpath = childrel->cheapest_total_path;
if (IsA(childpath, AppendPath))
subpaths = list_concat(subpaths,
- ((AppendPath *) childpath)->subpaths);
+ list_copy(((AppendPath *) childpath)->subpaths));
else
subpaths = lappend(subpaths, childpath);
regards, tom lane
Re: BUG #5673: Optimizer creates strange execution plan leading to wrong results
From
David Schmitt
Date:
On 9/23/2010 9:53 PM, Tom Lane wrote: > David Schmitt<david@dasz.at> writes: >> Executing the attached example.sql on a fresh database demonstrates the >> problem I'm seeing: > > Found it. If you need a patch right away, it's a one-liner: > > diff --git a/src/backend/optimizer/path/allpaths.c b/src/backend/optimizer/path/allpaths.c > index 2d86da3..b7cf0b8 100644 > --- a/src/backend/optimizer/path/allpaths.c > +++ b/src/backend/optimizer/path/allpaths.c > @@ -425,7 +425,7 @@ set_append_rel_pathlist(PlannerInfo *root, RelOptInfo *rel, > childpath = childrel->cheapest_total_path; > if (IsA(childpath, AppendPath)) > subpaths = list_concat(subpaths, > - ((AppendPath *) childpath)->subpaths); > + list_copy(((AppendPath *) childpath)->subpaths)); > else > subpaths = lappend(subpaths, childpath); > Thank you very very much, you made my day! *phew* Best Regards, David -- dasz.at OG Tel: +43 (0)664 2602670 Web: http://dasz.at Klosterneuburg UID: ATU64260999 FB-Nr.: FN 309285 g FB-Gericht: LG Korneuburg