You are viewing a plain text version of this content. The canonical link for it is here.
Posted to derby-dev@db.apache.org by "Bergquist, Brett" <BB...@canoga.com> on 2013/03/27 20:16:30 UTC
Why is the optimizer choosing such a bad path
Some background.
I have a customer that is using an earlier release of our system that has
Derby 10.8.2.1 installed. Because of issues like
https://issues.apache.org/jira/browse/DERBY-5680,
it has been running with the indexStat daemon disabled.
We are going to have a new release soon and it will be installing Derby 10.9.1.0 with the indexStat
daemon enabled. I recently got a copy of the customer's database (132Gb) and ran into
a very long query. I manually ran SYS_UTIL.SYSCS_UPDATE_STATISTICS on all of the tables
in the query to ensure that the statistics are up to date.
The tables in the query look like:
// 62,908,433 Rows
CREATE TABLE "CORE_V1"."CONFIGURATIONSET_CONFIGURATIONBUNDLE"
(
CONFIGURATIONBUNDLE_ID int NOT NULL,
CONFIGURATIONSET_ID int NOT NULL,
CONSTRAINT CONFIGURATIONSET_CONFIGURATIONBUNDLE_PK PRIMARY KEY (CONFIGURATIONBUNDLE_ID,CONFIGURATIONSET_ID)
);
ALTER TABLE "CORE_V1"."CONFIGURATIONSET_CONFIGURATIONBUNDLE"
ADD CONSTRAINT CONFIGURATIONSET_CONFIGURATIONBUNDLE_FK_2
FOREIGN KEY (CONFIGURATIONSET_ID)
REFERENCES "CORE_V1"."CONFIGURATION_SET"(ID);
ALTER TABLE "CORE_V1"."CONFIGURATIONSET_CONFIGURATIONBUNDLE"
ADD CONSTRAINT CONFIGURATIONSET_CONFIGURATIONBUNDLE_FK_1
FOREIGN KEY (CONFIGURATIONBUNDLE_ID)
REFERENCES "CORE_V1"."CONFIGURATION_BUNDLE"(ID);
CREATE INDEX SQL100922214558160 ON "CORE_V1"."CONFIGURATIONSET_CONFIGURATIONBUNDLE"(CONFIGURATIONSET_ID);
CREATE INDEX SQL100922215312050 ON "CORE_V1"."CONFIGURATIONSET_CONFIGURATIONBUNDLE"(CONFIGURATIONBUNDLE_ID);
CREATE UNIQUE INDEX SQL081029110254290 ON "CORE_V1"."CONFIGURATIONSET_CONFIGURATIONBUNDLE"
(
CONFIGURATIONBUNDLE_ID,
CONFIGURATIONSET_ID
);
// 4 Rows
CREATE TABLE "PKG_9145E10G"."INGRESS_COS_QUEUE_CONFIG_BUNDLE"
(
ID int PRIMARY KEY NOT NULL,
LLQ_CONFIG_ENTRY_ID int NOT NULL
);
ALTER TABLE "PKG_9145E10G"."INGRESS_COS_QUEUE_CONFIG_BUNDLE"
ADD CONSTRAINT INGRESS_COS_QUEUE_CONFIG_BUNDLE_FK_2
FOREIGN KEY (LLQ_CONFIG_ENTRY_ID)
REFERENCES "PKG_9145E10G"."INGRESS_COS_QUEUE_CONFIG_ENTRY"(ID);
ALTER TABLE "PKG_9145E10G"."INGRESS_COS_QUEUE_CONFIG_BUNDLE"
ADD CONSTRAINT INGRESS_COS_QUEUE_CONFIG_BUNDLE_FK_1
FOREIGN KEY (ID)
REFERENCES "CORE_V1"."CONFIGURATION_BUNDLE"(ID);
CREATE INDEX SQL130327093508050 ON "PKG_9145E10G"."INGRESS_COS_QUEUE_CONFIG_BUNDLE"(ID);
CREATE INDEX SQL130327093508060 ON "PKG_9145E10G"."INGRESS_COS_QUEUE_CONFIG_BUNDLE"(LLQ_CONFIG_ENTRY_ID);
CREATE UNIQUE INDEX SQL130327093437740 ON "PKG_9145E10G"."INGRESS_COS_QUEUE_CONFIG_BUNDLE"(ID);
// 197,363 Rows
CREATE TABLE "PKG_9145E10G"."CONFIGURATION_BUNDLE_9145E10G"
(
ID int PRIMARY KEY NOT NULL
);
ALTER TABLE "PKG_9145E10G"."CONFIGURATION_BUNDLE_9145E10G"
ADD CONSTRAINT CONFIGURATION_BUNDLE_9145E10G_FK_1
FOREIGN KEY (ID)
REFERENCES "CORE_V1"."CONFIGURATION_BUNDLE"(ID);
CREATE UNIQUE INDEX SQL100226025356610 ON "PKG_9145E10G"."CONFIGURATION_BUNDLE_9145E10G"(ID);
CREATE INDEX SQL100922215631540 ON "PKG_9145E10G"."CONFIGURATION_BUNDLE_9145E10G"(ID);
// 6,740,327 Rows
CREATE TABLE "CORE_V1"."CONFIGURATION_BUNDLE"
(
DTYPE varchar(64),
OPLOCK int DEFAULT 0 NOT NULL,
BUNDLE_NAME varchar(64) NOT NULL,
ID int PRIMARY KEY NOT NULL
);
CREATE INDEX CONFIGURATION_BUNDLE_IX_2 ON "CORE_V1"."CONFIGURATION_BUNDLE"(BUNDLE_NAME);
CREATE INDEX CONFIGURATION_BUNDLE_IX_1 ON "CORE_V1"."CONFIGURATION_BUNDLE"(DTYPE);
CREATE UNIQUE INDEX SQL100922215131580 ON "CORE_V1"."CONFIGURATION_BUNDLE"(ID);
For some reason, the optimizer is doing a table scan across the CORE_V1.CONFIGURATIONSET_CONFIGURATIONBUNDLE table
which has 64 million rows and it even goes across this 4 times!.
One issue is that this query is generated by Eclipselink (JPA) and I have no control on the query generation.
So any ideas on why it would chose this path and what I might be able to do about it? In playing
around and trying to find the issue, I notice that if I remove the
t0.DTYPE = 'INGRESS_COS_QUEUE_CONFIG_BUNDLE_9145E10G')
constraint, then the query returns 0 rows (it should even with this constraint as there are no rows
that are acceptable) and returns them in about .05 seconds. Note CORE_V1.CONFIGURATION_BUNDLE does
have a non-unique index on DTYPE.
Ok, just on a whim, I removed the index on DTYPE and the query came back .06 seconds. That column is used
by Eclipselink in determining which of a "derived" object to return so I don't have much control on it.
----
Statement Name:
SQL_CURLH000C1
Statement Text:
SELECT t0.ID, t0.DTYPE, t0.BUNDLE_NAME, t0.OPLOCK, t1.ID, t2.ID, t2.LLQ_CONFIG_ENTRY_ID FROM CORE_V1.CONFIGURATIONSET_CONFIGURATIONBUNDLE t3, PKG_9145E10G.INGRESS_COS_QUEUE_CONFIG_BUNDLE t2, PKG_9145E10G.CONFIGURATION_BUNDLE_9145E10G t1, CORE_V1.CONFIGURATION_BUNDLE t0 WHERE (((t3.CONFIGURATIONSET_ID = 4000) AND (t0.ID = t3.CONFIGURATIONBUNDLE_ID)) AND (((t2.ID = t0.ID) AND (t1.ID = t0.ID)) AND (t0.DTYPE = 'INGRESS_COS_QUEUE_CONFIG_BUNDLE_9145E10G')))
Parse Time: 0
Bind Time: 0
Optimize Time: 0
Generate Time: 0
Compile Time: 0
Execute Time: 0
Begin Compilation Timestamp : null
End Compilation Timestamp : null
Begin Execution Timestamp : null
End Execution Timestamp : null
Statement Execution Plan Text:
Project-Restrict ResultSet (9):
Number of opens = 1
Rows seen = 0
Rows filtered = 0
restriction = false
projection = true
constructor time (milliseconds) = 0
open time (milliseconds) = 0
next time (milliseconds) = 0
close time (milliseconds) = 0
restriction time (milliseconds) = 0
projection time (milliseconds) = 0
optimizer estimated row count: 0.00
optimizer estimated cost: 8.05
Source result set:
Nested Loop Join ResultSet:
Number of opens = 1
Rows seen from the left = 0
Rows seen from the right = 0
Rows filtered = 0
Rows returned = 0
constructor time (milliseconds) = 0
open time (milliseconds) = 0
next time (milliseconds) = 0
close time (milliseconds) = 0
optimizer estimated row count: 0.00
optimizer estimated cost: 8.05
Left result set:
Nested Loop Join ResultSet:
Number of opens = 1
Rows seen from the left = 0
Rows seen from the right = 0
Rows filtered = 0
Rows returned = 0
constructor time (milliseconds) = 0
open time (milliseconds) = 0
next time (milliseconds) = 0
close time (milliseconds) = 0
optimizer estimated row count: 0.00
optimizer estimated cost: 8.05
Left result set:
Nested Loop Join ResultSet:
Number of opens = 1
Rows seen from the left = 4
Rows seen from the right = 0
Rows filtered = 0
Rows returned = 0
constructor time (milliseconds) = 0
open time (milliseconds) = 0
next time (milliseconds) = 0
close time (milliseconds) = 0
optimizer estimated row count: 0.00
optimizer estimated cost: 8.05
Left result set:
Index Row to Base Row ResultSet for CONFIGURATION_BUNDLE:
Number of opens = 1
Rows seen = 4
Columns accessed from heap = {0, 1, 2, 3}
constructor time (milliseconds) = 0
open time (milliseconds) = 0
next time (milliseconds) = 0
close time (milliseconds) = 0
optimizer estimated row count: 0.00
optimizer estimated cost: 8.05
Index Scan ResultSet for CONFIGURATION_BUNDLE using index CONFIGURATION_BUNDLE_IX_1 at read committed isolation level using instantaneous share row locking chosen by the optimizer
Number of opens = 1
Rows seen = 4
Rows filtered = 0
Fetch Size = 16
constructor time (milliseconds) = 0
open time (milliseconds) = 0
next time (milliseconds) = 0
close time (milliseconds) = 0
next time in milliseconds/row = 0
scan information:
Bit set of columns fetched=All
Number of columns fetched=2
Number of deleted rows visited=0
Number of pages visited=5
Number of rows qualified=4
Number of rows visited=5
Scan type=btree
Tree height=5
start position:
>= on first 1 column(s).
Ordered null semantics on the following columns:
stop position:
> on first 1 column(s).
Ordered null semantics on the following columns:
qualifiers:
None
optimizer estimated row count: 0.00
optimizer estimated cost: 8.05
Right result set:
Table Scan ResultSet for CONFIGURATIONSET_CONFIGURATIONBUNDLE at read committed isolation level using instantaneous share row locking chosen by the optimizer
Number of opens = 4
Rows seen = 0
Rows filtered = 0
Fetch Size = 16
constructor time (milliseconds) = 0
open time (milliseconds) = 0
next time (milliseconds) = 0
close time (milliseconds) = 0
scan information:
Bit set of columns fetched=All
Number of columns fetched=2
Number of pages visited=670838
Number of rows qualified=0
Number of rows visited=262429876
Scan type=heap
start position:
null
stop position:
null
qualifiers:
Column[0][0] Id: 0
Operator: =
Ordered nulls: false
Unknown return value: false
Negate comparison result: false
Column[0][1] Id: 1
Operator: =
Ordered nulls: false
Unknown return value: false
Negate comparison result: false
optimizer estimated row count: 0.00
optimizer estimated cost: 0.00
Right result set:
Table Scan ResultSet for INGRESS_COS_QUEUE_CONFIG_BUNDLE at read committed isolation level using instantaneous share row locking chosen by the optimizer
Number of opens = 0
Rows seen = 0
Rows filtered = 0
Fetch Size = 16
constructor time (milliseconds) = 0
open time (milliseconds) = 0
next time (milliseconds) = 0
close time (milliseconds) = 0
scan information:
start position:
null
stop position:
null
qualifiers:
Column[0][0] Id: 0
Operator: =
Ordered nulls: false
Unknown return value: false
Negate comparison result: false
optimizer estimated row count: 0.00
optimizer estimated cost: 0.00
Right result set:
Table Scan ResultSet for CONFIGURATION_BUNDLE_9145E10G at read committed isolation level using instantaneous share row locking chosen by the optimizer
Number of opens = 0
Rows seen = 0
Rows filtered = 0
Fetch Size = 16
constructor time (milliseconds) = 0
open time (milliseconds) = 0
next time (milliseconds) = 0
close time (milliseconds) = 0
scan information:
start position:
null
stop position:
null
qualifiers:
Column[0][0] Id: 0
Operator: =
Ordered nulls: false
Unknown return value: false
Negate comparison result: false
optimizer estimated row count: 0.00
optimizer estimated cost: 0.00
Re: Why is the optimizer choosing such a bad path
Posted by Mike Matrigali <mi...@sbcglobal.net>.
On 3/29/2013 9:30 AM, Mike Matrigali wrote:
> On 3/29/2013 5:28 AM, Bergquist, Brett wrote:
>> Mike I have a reproducible case but the database is 132GB so it is not
>> practical. I am willing to dig in and try to help debug this. On
Some bugs can cause problems in the past in a table that was built using
a version of the old software when has later been fixed, so we
like to have a case where the problem can be reproduced starting from
an empty database. But it is valid to try and figure out why an
existing db is having problem. And in this case I would say that if
a problem exists in the table it is likely a bug that running
update statistics on the table does not fix it. Especially when
running update statistics with the keepDisposableStats flag to avoid
at least the one known issue and possibly others.
>> the issue that was pointed to, Mamta seemed to have used a debug
>> procedure that would print out more information on why the optimizer
>> is choosing what it does. This might be useful in this case as well.
>>
>> So if someone can point me in the right area of the code to start
>> looking and adding some debug that would be helpful. I have done some
>> fixes for Derby in the past so I am able to build and debug Derby.
>>
I assume your real application is a java program and not ij. be careful
with using ij to simulate your actual application. The biggest thing
to watch out for is parameterized queries, the following 2 queries
most likely get very different code paths in the optmizer, but often
people are suprised that the optimizer treats them different:
jdbc set field1 to 100
jdbc execute select * from t where field1 = ?
jdbc execute select * from t where field1 = 100
We recommend the 1st if you are going to execute the query more than
once as we only have to compile it once. But the downside is that
at compile time we have to guess at the selectivity of the possible
values of ?. If a unique index exists on the field then guessing
is easy, otherwise stats come into play. And the more complicated
the query the more one guess builds on another, ...
For the second version at compile time if an index exists such that
field1 is the first column then we use the index itself to estimate
number of rows.
Re: Why is the optimizer choosing such a bad path
Posted by Dag Wanvik <da...@oracle.com>.
Hi,
On 02.04.2013 05:21, Mamta Satoor wrote:
> Also, I am thinking of updating the wiki page on optimizer
> tracing(http://wiki.apache.org/db-derby/OptimizerTracing) with
> following additional information for releases prior to 10.10. I will
> go ahead and add following changes if there are no comments on the
> content/wording of the text below. Also, I hope that it is ok to share
> this undocumented behavior on the wiki.
+1
Dag
Re: Why is the optimizer choosing such a bad path
Posted by Mamta Satoor <ms...@gmail.com>.
Also, I am thinking of updating the wiki page on optimizer
tracing(http://wiki.apache.org/db-derby/OptimizerTracing) with
following additional information for releases prior to 10.10. I will
go ahead and add following changes if there are no comments on the
content/wording of the text below. Also, I hope that it is ok to share
this undocumented behavior on the wiki.
*************************************************
The tracing option explained above is available in 10.10 release.
Prior to 10.10 release, one can use following undocumented way to
enable optimizer tracing.
Define two stored procedures in the user application.
public static void trace() {
org.apache.derby.iapi.db.OptimizerTrace.setOptimizerTrace(true);
}
public static void printTrace() {
System.out.println(org.apache.derby.iapi.db.OptimizerTrace.getOptimizerTraceOutput());
}
s.execute("create procedure trace() language java parameter style
java external name '" + getClass().getName() + ".trace'");
s.execute("create procedure print_trace() language java parameter
style java external name '" + getClass().getName() + ".printTrace'");
And then surround the sql statement that needs to be traced with call
trace() before the statement to trace, and printTrace() after the
statement to trace as shown below:
s.execute("call trace()");
s.execute("select 1 from sys.sysschemas natural join sys.systables");
s.execute("call print_trace()");
*************************************************
On Mon, Apr 1, 2013 at 11:55 AM, Mamta Satoor <ms...@gmail.com> wrote:
> Hi,
>
> I was on vacation last week and hence could't participate in this
> conversation earlier.
>
> As Rick pointed out, DERBY-6022 has gone in as part of 10.10. But if
> you are in need of doing optimizer tracing in a release prior to
> 10.10, you can try the suggestion postd by Knut in email thread("Is
> there a way to dump all the plans considered by optimizer into log?")
> at http://www.mailinglistarchive.com/html/derby-dev@db.apache.org/2013-02/msg00635.html.
> I am copying Knut's suggestion below. I tried this on 10.9 and was
> able to get all the optimizer plans considered by the optimzer for a
> given query. You can then look at the details of each individual plan
> to understand why optimizer picked a given plan.
>
> **************************************************************
> define two stored procedures:
>
> public static void trace() {
> org.apache.derby.iapi.db.OptimizerTrace.setOptimizerTrace(true);
> }
>
> public static void printTrace() {
> System.out.println(org.apache.derby.iapi.db.OptimizerTrace.getOptimizerTraceOutput());
> }
>
> s.execute("create procedure trace() language java parameter style
> java external name '" + getClass().getName() + ".trace'");
> s.execute("create procedure print_trace() language java parameter
> style java external name '" + getClass().getName() + ".printTrace'");
>
> And then call trace() before the statement to trace, and printTrace()
> after:
>
> s.execute("call trace()");
> s.execute("select 1 from sys.sysschemas natural join sys.systables");
> s.execute("call print_trace()");
> **************************************************************
>
>
> On Mon, Apr 1, 2013 at 6:55 AM, Bergquist, Brett <BB...@canoga.com> wrote:
>> I will be looking at this later in the week as of course my real work has interrupted :) Thanks for all of the valuable input!
>>
>> Brrett
>> ________________________________________
>> From: Rick Hillegas [rick.hillegas@oracle.com]
>> Sent: Friday, March 29, 2013 2:10 PM
>> To: derby-dev@db.apache.org
>> Subject: Re: Why is the optimizer choosing such a bad path
>>
>> On 3/29/13 9:30 AM, Mike Matrigali wrote:
>>> On 3/29/2013 5:28 AM, Bergquist, Brett wrote:
>>>> Mike I have a reproducible case but the database is 132GB so it is
>>>> not practical. I am willing to dig in and try to help debug this.
>>>> On the issue that was pointed to, Mamta seemed to have used a debug
>>>> procedure that would print out more information on why the optimizer
>>>> is choosing what it does. This might be useful in this case as well.
>>>>
>>>> So if someone can point me in the right area of the code to start
>>>> looking and adding some debug that would be helpful. I have done
>>>> some fixes for Derby in the past so I am able to build and debug Derby.
>>>>
>>> That's great. I am out of my depth debugging optimizer problems,
>>> hopefully rick and/or mamta can help with that tool they were working
>>> on. I think rick did some work to make it easier to turn on/off using
>>> optional tools.
>>>
>> The simpler api to optimizer tracing is part of the 10.10.1 release
>> candidate which we're testing now. Instructions on how to use it can be
>> found in my 2013-03-14 comment on
>> https://issues.apache.org/jira/browse/DERBY-6022
>>
>> Hope this helps,
>> -Rick
>>
>>
Re: Why is the optimizer choosing such a bad path
Posted by Mamta Satoor <ms...@gmail.com>.
Hi,
I was on vacation last week and hence could't participate in this
conversation earlier.
As Rick pointed out, DERBY-6022 has gone in as part of 10.10. But if
you are in need of doing optimizer tracing in a release prior to
10.10, you can try the suggestion postd by Knut in email thread("Is
there a way to dump all the plans considered by optimizer into log?")
at http://www.mailinglistarchive.com/html/derby-dev@db.apache.org/2013-02/msg00635.html.
I am copying Knut's suggestion below. I tried this on 10.9 and was
able to get all the optimizer plans considered by the optimzer for a
given query. You can then look at the details of each individual plan
to understand why optimizer picked a given plan.
**************************************************************
define two stored procedures:
public static void trace() {
org.apache.derby.iapi.db.OptimizerTrace.setOptimizerTrace(true);
}
public static void printTrace() {
System.out.println(org.apache.derby.iapi.db.OptimizerTrace.getOptimizerTraceOutput());
}
s.execute("create procedure trace() language java parameter style
java external name '" + getClass().getName() + ".trace'");
s.execute("create procedure print_trace() language java parameter
style java external name '" + getClass().getName() + ".printTrace'");
And then call trace() before the statement to trace, and printTrace()
after:
s.execute("call trace()");
s.execute("select 1 from sys.sysschemas natural join sys.systables");
s.execute("call print_trace()");
**************************************************************
On Mon, Apr 1, 2013 at 6:55 AM, Bergquist, Brett <BB...@canoga.com> wrote:
> I will be looking at this later in the week as of course my real work has interrupted :) Thanks for all of the valuable input!
>
> Brrett
> ________________________________________
> From: Rick Hillegas [rick.hillegas@oracle.com]
> Sent: Friday, March 29, 2013 2:10 PM
> To: derby-dev@db.apache.org
> Subject: Re: Why is the optimizer choosing such a bad path
>
> On 3/29/13 9:30 AM, Mike Matrigali wrote:
>> On 3/29/2013 5:28 AM, Bergquist, Brett wrote:
>>> Mike I have a reproducible case but the database is 132GB so it is
>>> not practical. I am willing to dig in and try to help debug this.
>>> On the issue that was pointed to, Mamta seemed to have used a debug
>>> procedure that would print out more information on why the optimizer
>>> is choosing what it does. This might be useful in this case as well.
>>>
>>> So if someone can point me in the right area of the code to start
>>> looking and adding some debug that would be helpful. I have done
>>> some fixes for Derby in the past so I am able to build and debug Derby.
>>>
>> That's great. I am out of my depth debugging optimizer problems,
>> hopefully rick and/or mamta can help with that tool they were working
>> on. I think rick did some work to make it easier to turn on/off using
>> optional tools.
>>
> The simpler api to optimizer tracing is part of the 10.10.1 release
> candidate which we're testing now. Instructions on how to use it can be
> found in my 2013-03-14 comment on
> https://issues.apache.org/jira/browse/DERBY-6022
>
> Hope this helps,
> -Rick
>
>
RE: Why is the optimizer choosing such a bad path
Posted by "Bergquist, Brett" <BB...@canoga.com>.
I will be looking at this later in the week as of course my real work has interrupted :) Thanks for all of the valuable input!
Brrett
________________________________________
From: Rick Hillegas [rick.hillegas@oracle.com]
Sent: Friday, March 29, 2013 2:10 PM
To: derby-dev@db.apache.org
Subject: Re: Why is the optimizer choosing such a bad path
On 3/29/13 9:30 AM, Mike Matrigali wrote:
> On 3/29/2013 5:28 AM, Bergquist, Brett wrote:
>> Mike I have a reproducible case but the database is 132GB so it is
>> not practical. I am willing to dig in and try to help debug this.
>> On the issue that was pointed to, Mamta seemed to have used a debug
>> procedure that would print out more information on why the optimizer
>> is choosing what it does. This might be useful in this case as well.
>>
>> So if someone can point me in the right area of the code to start
>> looking and adding some debug that would be helpful. I have done
>> some fixes for Derby in the past so I am able to build and debug Derby.
>>
> That's great. I am out of my depth debugging optimizer problems,
> hopefully rick and/or mamta can help with that tool they were working
> on. I think rick did some work to make it easier to turn on/off using
> optional tools.
>
The simpler api to optimizer tracing is part of the 10.10.1 release
candidate which we're testing now. Instructions on how to use it can be
found in my 2013-03-14 comment on
https://issues.apache.org/jira/browse/DERBY-6022
Hope this helps,
-Rick
Re: Why is the optimizer choosing such a bad path
Posted by Rick Hillegas <ri...@oracle.com>.
On 3/29/13 9:30 AM, Mike Matrigali wrote:
> On 3/29/2013 5:28 AM, Bergquist, Brett wrote:
>> Mike I have a reproducible case but the database is 132GB so it is
>> not practical. I am willing to dig in and try to help debug this.
>> On the issue that was pointed to, Mamta seemed to have used a debug
>> procedure that would print out more information on why the optimizer
>> is choosing what it does. This might be useful in this case as well.
>>
>> So if someone can point me in the right area of the code to start
>> looking and adding some debug that would be helpful. I have done
>> some fixes for Derby in the past so I am able to build and debug Derby.
>>
> That's great. I am out of my depth debugging optimizer problems,
> hopefully rick and/or mamta can help with that tool they were working
> on. I think rick did some work to make it easier to turn on/off using
> optional tools.
>
The simpler api to optimizer tracing is part of the 10.10.1 release
candidate which we're testing now. Instructions on how to use it can be
found in my 2013-03-14 comment on
https://issues.apache.org/jira/browse/DERBY-6022
Hope this helps,
-Rick
Re: Why is the optimizer choosing such a bad path
Posted by Mike Matrigali <mi...@sbcglobal.net>.
On 3/29/2013 5:28 AM, Bergquist, Brett wrote:
> Mike I have a reproducible case but the database is 132GB so it is not practical. I am willing to dig in and try to help debug this. On the issue that was pointed to, Mamta seemed to have used a debug procedure that would print out more information on why the optimizer is choosing what it does. This might be useful in this case as well.
>
> So if someone can point me in the right area of the code to start looking and adding some debug that would be helpful. I have done some fixes for Derby in the past so I am able to build and debug Derby.
>
That's great. I am out of my depth debugging optimizer problems,
hopefully rick and/or mamta can help with that tool they were working
on. I think rick did some work to make it easier to turn on/off using
optional tools.
From what you have described so far seems key to understand what is
the difference in estimates in your original database after running
update stats on all tables and when you drop/recreate that index that
leads to the behavior change.
starting bottom up I can point you at the routines I would expect the
optimizer to call to get the number of rows in a table. Making sure
these routines are returning reasonable numbers would be a good start.
You are looking for getEstimatedRowCount() interfaces. The 2 most
interesting implementations are:
this one should be called for indexes:
java/engine/org/apache/derby/impl/store/access/btre/OpenBTree.java:200:
public long getEstimatedRowCount()
this one should be called for base tables:
java/engine/org/apache/derby/impl/store/access/conglomerate/GenericController.java:180:
public long getEstimatedRowCount()
RE: Why is the optimizer choosing such a bad path
Posted by "Bergquist, Brett" <BB...@canoga.com>.
Mike I have a reproducible case but the database is 132GB so it is not practical. I am willing to dig in and try to help debug this. On the issue that was pointed to, Mamta seemed to have used a debug procedure that would print out more information on why the optimizer is choosing what it does. This might be useful in this case as well.
So if someone can point me in the right area of the code to start looking and adding some debug that would be helpful. I have done some fixes for Derby in the past so I am able to build and debug Derby.
-----Original Message-----
From: Mike Matrigali [mailto:mikem_app@sbcglobal.net]
Sent: Thursday, March 28, 2013 5:11 PM
To: derby-dev@db.apache.org
Subject: Re: Why is the optimizer choosing such a bad path
On 3/28/2013 6:38 AM, Bergquist, Brett wrote:
> I tried adding:
>
> derby.storage.indexStats.debug.keepDisposableStats=true
>
> to derby.properties *and* regenerating statistics for the tables. There is no change in the query plan.
>
> Does this mean that applying the patches suggested will probably have no effect either?
I think this is correct. The patch should only fix problems where update statistics is run and a bad query plan shows up in base system 10.9, but a good plan results when that flag is enabled and update statistics is run.
I think you have always been doing this but always best to run update statistics after data is loaded.
At this point hard to say where the problem is. It seems very strange for optimizer to come up with 0 rows for a 62 million row table (or for any table with more than a few rows - lets say 10,000 to be safe). The system has a separate call for the optmizer to get the number of rows that is separate from anything the stats generated by update stats. But it is an estimate maintained by the storage system and the estimate is updated as a by product of running update statistics (or any table scan of the table/index). But it should also be maintained continuously as part of inserts.
Best next step would be to somehow get a reproducible case where the optimizer returns 0 row estimate for that big table and track down the call that is giving the bad data.
>
> -----Original Message-----
> From: Bergquist, Brett [mailto:BBergquist@canoga.com]
> Sent: Thursday, March 28, 2013 8:52 AM
> To: derby-dev@db.apache.org
> Subject: RE: Why is the optimizer choosing such a bad path
>
> After dropping and recreating on index:
>
> DROP INDEX CORE_V1.CONFIGURATION_BUNDLE_IX_1;
> CREATE INDEX CONFIGURATION_BUNDLE_IX_1 ON
> "CORE_V1"."CONFIGURATION_BUNDLE"(DTYPE);
>
> And rerunning the query, the optimizer chose that index and the optimizer row count estimates are no longer 0.
>
> So it appears that there is something bad with that index that SYSCS_UTIL.SYSCS_CHECK_TABLE does not see and even SYSCS_UTIL.SYSCS_DROP_STATISTICS and SYSCS_UTIL.SYSCS_UPDATE_STATISTICS cannot fix.
>
> Statement Name:
> SQL_CURLH000C2
> Statement Text:
> SELECT t0.ID, t0.DTYPE, t0.BUNDLE_NAME, t0.OPLOCK, t1.ID,
> t2.ID, t2.LLQ_CONFIG_ENTRY_ID FROM
> CORE_V1.CONFIGURATIONSET_CONFIGURATIONBUNDLE t3,
> PKG_9145E10G.INGRESS_COS_QUEUE_CONFIG_BUNDLE t2,
> PKG_9145E10G.CONFIGURATION_BUNDLE_9145E10G t1,
> CORE_V1.CONFIGURATION_BUNDLE t0 WHERE (((t3.CONFIGURATIONSET_ID =
> 4000) AND (t0.ID = t3.CONFIGURATIONBUNDLE_ID)) AND (((t2.ID = t0.ID)
> AND (t1.ID = t0.ID)) AND (t0.DTYPE =
> 'INGRESS_COS_QUEUE_CONFIG_BUNDLE_9145E10G')))
> Parse Time: 5
> Bind Time: 9
> Optimize Time: 133
> Generate Time: 6
> Compile Time: 153
> Execute Time: 35
> Begin Compilation Timestamp : 2013-03-28 08:44:40.901 End Compilation Timestamp : 2013-03-28 08:44:41.054 Begin Execution Timestamp : 2013-03-28 08:44:41.058 End Execution Timestamp : 2013-03-28 08:44:41.094 Statement Execution Plan Text:
> Project-Restrict ResultSet (10):
> Number of opens = 1
> Rows seen = 0
> Rows filtered = 0
> restriction = false
> projection = true
> constructor time (milliseconds) = 0
> open time (milliseconds) = 35
> next time (milliseconds) = 0
> close time (milliseconds) = 0
> restriction time (milliseconds) = 0
> projection time (milliseconds) = 0
> optimizer estimated row count: 2.00
> optimizer estimated cost: 51.52 Source result set:
> Nested Loop Exists Join ResultSet:
> Number of opens = 1
> Rows seen from the left = 0
> Rows seen from the right = 0
> Rows filtered = 0
> Rows returned = 0
> constructor time (milliseconds) = 0
> open time (milliseconds) = 35
> next time (milliseconds) = 0
> close time (milliseconds) = 1
> optimizer estimated row count: 2.00
> optimizer estimated cost: 51.52
> Left result set:
> Nested Loop Exists Join ResultSet:
> Number of opens = 1
> Rows seen from the left = 0
> Rows seen from the right = 0
> Rows filtered = 0
> Rows returned = 0
> constructor time (milliseconds) = 0
> open time (milliseconds) = 35
> next time (milliseconds) = 0
> close time (milliseconds) = 1
> optimizer estimated row count: 2.00
> optimizer estimated cost: 37.18
> Left result set:
> Nested Loop Exists Join ResultSet:
> Number of opens = 1
> Rows seen from the left = 4
> Rows seen from the right = 0
> Rows filtered = 0
> Rows returned = 0
> constructor time (milliseconds) = 0
> open time (milliseconds) = 1
> next time (milliseconds) = 34
> close time (milliseconds) = 1
> optimizer estimated row count: 2.00
> optimizer estimated cost: 27.75
> Left result set:
> Index Row to Base Row ResultSet for CONFIGURATION_BUNDLE:
> Number of opens = 1
> Rows seen = 4
> Columns accessed from heap = {0, 1, 2, 3}
> constructor time (milliseconds) = 1
> open time (milliseconds) = 0
> next time (milliseconds) = 0
> close time (milliseconds) = 1
> optimizer estimated row count: 2.00
> optimizer estimated cost: 12.04
> Index Scan ResultSet for CONFIGURATION_BUNDLE using index CONFIGURATION_BUNDLE_IX_1 at read committed isolation level using instantaneous share row locking chosen by the optimizer
> Number of opens = 1
> Rows seen = 4
> Rows filtered = 0
> Fetch Size = 16
> constructor time (milliseconds) = 0
> open time (milliseconds) = 1
> next time (milliseconds) = 0
> close time (milliseconds) = 1
> next time in
> milliseconds/row = 0
>
> scan information:
> Bit set of columns fetched=All
> Number of columns fetched=2
> Number of deleted rows visited=0
> Number of pages visited=4
> Number of rows qualified=4
> Number of rows visited=5
> Scan type=btree
> Tree height=4
> start position:
> >= on first 1 column(s).
> Ordered null semantics on the following columns:
> stop position:
> > on first 1 column(s).
> Ordered null semantics on the following columns:
> qualifiers:
> None
> optimizer estimated row count: 2.00
> optimizer estimated
> cost: 12.04
>
> Right result set:
> Index Scan ResultSet for CONFIGURATIONSET_CONFIGURATIONBUNDLE using constraint CONFIGURATIONSET_CONFIGURATIONBUNDLE_PK at read committed isolation level using share row locking chosen by the optimizer
> Number of opens = 4
> Rows seen = 0
> Rows filtered = 0
> Fetch Size = 1
> constructor time (milliseconds) = 0
> open time (milliseconds) = 1
> next time (milliseconds) = 33
> close time (milliseconds) = 1
>
> scan information:
> Bit set of columns fetched={0, 1}
> Number of columns fetched=2
> Number of deleted rows visited=0
> Number of pages visited=20
> Number of rows qualified=0
> Number of rows visited=4
> Scan type=btree
> Tree height=5
> start position:
> >= on first 2 column(s).
> Ordered null semantics on the following columns:
> 0 1
> stop position:
> > on first 2 column(s).
> Ordered null semantics on the following columns:
> 0 1
> qualifiers:
> None
> optimizer estimated row count: 2.00
> optimizer estimated cost:
> 15.72
>
> Right result set:
> Index Scan ResultSet for CONFIGURATION_BUNDLE_9145E10G using constraint SQL100226025356610 at read committed isolation level using share row locking chosen by the optimizer
> Number of opens = 0
> Rows seen = 0
> Rows filtered = 0
> Fetch Size = 1
> constructor time (milliseconds) = 0
> open time (milliseconds) = 0
> next time (milliseconds) = 0
> close time (milliseconds) = 0
>
> scan information:
> start position:
> Positioning information not available because this ResultSet was never opened.
> stop position:
> Positioning information not available because this ResultSet was never opened.
> qualifiers:
> Column[0][0] Id: 0
> Operator: =
> Ordered nulls: false
> Unknown return value: false
> Negate comparison result: false
> optimizer estimated row count: 2.00
> optimizer estimated cost: 9.43
>
> Right result set:
> Index Row to Base Row ResultSet for INGRESS_COS_QUEUE_CONFIG_BUNDLE:
> Number of opens = 0
> Rows seen = 0
> Columns accessed from heap = {1}
> constructor time (milliseconds) = 0
> open time (milliseconds) = 0
> next time (milliseconds) = 0
> close time (milliseconds) = 0
> optimizer estimated row count: 2.00
> optimizer estimated cost: 14.34
> Index Scan ResultSet for INGRESS_COS_QUEUE_CONFIG_BUNDLE using constraint SQL130327093437740 at read committed isolation level using share row locking chosen by the optimizer
> Number of opens = 0
> Rows seen = 0
> Rows filtered = 0
> Fetch Size = 1
> constructor time (milliseconds) = 0
> open time (milliseconds) = 0
> next time (milliseconds) = 0
> close time (milliseconds) = 0
>
> scan information:
> start position:
> Positioning information not available because this ResultSet was never opened.
> stop position:
> Positioning information not available because this ResultSet was never opened.
> qualifiers:
> Column[0][0] Id: 0
> Operator: =
> Ordered nulls: false
> Unknown return value: false
> Negate comparison result: false
> optimizer estimated row count: 2.00
> optimizer estimated cost: 14.34
>
>
>
> -----Original Message-----
> From: Bergquist, Brett [mailto:BBergquist@canoga.com]
> Sent: Thursday, March 28, 2013 8:33 AM
> To: derby-dev@db.apache.org
> Subject: RE: Why is the optimizer choosing such a bad path
>
> Okay, I finally figured out that " CALL SYSCS_UTIL.SYSCS_SET_STATISTICS_TIMING(1);" is required. Now from the name which has "timing" in it, one (or at least I) would not think that this would affect the returning of the optimizer estimates. I guess I naively assumed this would affect the reporting of the compile and execution times. Maybe the documentation needs to be fixed here.
>
> In any case, below is the query plan with this turned on. Note that optimizer is estimating a row count of 0 for the table with 64 million rows and does a table scan.
>
> Statement Name:
> SQL_CURLH000C1
> Statement Text:
> SELECT t0.ID, t0.DTYPE, t0.BUNDLE_NAME, t0.OPLOCK, t1.ID,
> t2.ID, t2.LLQ_CONFIG_ENTRY_ID FROM
> CORE_V1.CONFIGURATIONSET_CONFIGURATIONBUNDLE t3,
> PKG_9145E10G.INGRESS_COS_QUEUE_CONFIG_BUNDLE t2,
> PKG_9145E10G.CONFIGURATION_BUNDLE_9145E10G t1,
> CORE_V1.CONFIGURATION_BUNDLE t0 WHERE (((t3.CONFIGURATIONSET_ID =
> 4000) AND (t0.ID = t3.CONFIGURATIONBUNDLE_ID)) AND (((t2.ID = t0.ID)
> AND (t1.ID = t0.ID)) AND (t0.DTYPE =
> 'INGRESS_COS_QUEUE_CONFIG_BUNDLE_9145E10G')))
> Parse Time: 8
> Bind Time: 66
> Optimize Time: 3935
> Generate Time: 7
> Compile Time: 4016
> Execute Time: 220556
> Begin Compilation Timestamp : 2013-03-28 08:27:13.028 End Compilation Timestamp : 2013-03-28 08:27:17.044 Begin Execution Timestamp : 2013-03-28 08:27:17.053 End Execution Timestamp : 2013-03-28 08:30:57.615 Statement Execution Plan Text:
> Project-Restrict ResultSet (9):
> Number of opens = 1
> Rows seen = 0
> Rows filtered = 0
> restriction = false
> projection = true
> constructor time (milliseconds) = 0
> open time (milliseconds) = 220556
> next time (milliseconds) = 0
> close time (milliseconds) = 0
> restriction time (milliseconds) = 0
> projection time (milliseconds) = 0
> optimizer estimated row count: 0.00
> optimizer estimated cost: 8.05 Source result set:
> Nested Loop Join ResultSet:
> Number of opens = 1
> Rows seen from the left = 0
> Rows seen from the right = 0
> Rows filtered = 0
> Rows returned = 0
> constructor time (milliseconds) = 0
> open time (milliseconds) = 220556
> next time (milliseconds) = 0
> close time (milliseconds) = 6
> optimizer estimated row count: 0.00
> optimizer estimated cost: 8.05
> Left result set:
> Nested Loop Join ResultSet:
> Number of opens = 1
> Rows seen from the left = 0
> Rows seen from the right = 0
> Rows filtered = 0
> Rows returned = 0
> constructor time (milliseconds) = 0
> open time (milliseconds) = 220556
> next time (milliseconds) = 0
> close time (milliseconds) = 6
> optimizer estimated row count: 0.00
> optimizer estimated cost: 8.05
> Left result set:
> Nested Loop Join ResultSet:
> Number of opens = 1
> Rows seen from the left = 4
> Rows seen from the right = 0
> Rows filtered = 0
> Rows returned = 0
> constructor time (milliseconds) = 0
> open time (milliseconds) = 63
> next time (milliseconds) = 220493
> close time (milliseconds) = 6
> optimizer estimated row count: 0.00
> optimizer estimated cost: 8.05
> Left result set:
> Index Row to Base Row ResultSet for CONFIGURATION_BUNDLE:
> Number of opens = 1
> Rows seen = 4
> Columns accessed from heap = {0, 1, 2, 3}
> constructor time (milliseconds) = 0
> open time (milliseconds) = 0
> next time (milliseconds) = 64
> close time (milliseconds) = 6
> optimizer estimated row count: 0.00
> optimizer estimated cost: 8.05
> Index Scan ResultSet for CONFIGURATION_BUNDLE using index CONFIGURATION_BUNDLE_IX_1 at read committed isolation level using instantaneous share row locking chosen by the optimizer
> Number of opens = 1
> Rows seen = 4
> Rows filtered = 0
> Fetch Size = 16
> constructor time (milliseconds) = 0
> open time (milliseconds) = 2
> next time (milliseconds) = 1
> close time (milliseconds) = 6
> next time in
> milliseconds/row = 0
>
> scan information:
> Bit set of columns fetched=All
> Number of columns fetched=2
> Number of deleted rows visited=0
> Number of pages visited=5
> Number of rows qualified=4
> Number of rows visited=5
> Scan type=btree
> Tree height=5
> start position:
> >= on first 1 column(s).
> Ordered null semantics on the following columns:
> stop position:
> > on first 1 column(s).
> Ordered null semantics on the following columns:
> qualifiers:
> None
> optimizer estimated row count: 0.00
> optimizer estimated
> cost: 8.05
>
> Right result set:
> Table Scan ResultSet for CONFIGURATIONSET_CONFIGURATIONBUNDLE at read committed isolation level using instantaneous share row locking chosen by the optimizer
> Number of opens = 4
> Rows seen = 0
> Rows filtered = 0
> Fetch Size = 16
> constructor time (milliseconds) = 0
> open time (milliseconds) = 64
> next time (milliseconds) = 0
> close time (milliseconds) =
> 11
>
> scan information:
> Bit set of columns fetched=All
> Number of columns fetched=2
> Number of pages visited=670832
> Number of rows qualified=0
> Number of rows visited=262428000
> Scan type=heap
> start position:
> null
> stop position:
> null
> qualifiers:
> Column[0][0] Id: 0
> Operator: =
> Ordered nulls: false
> Unknown return value: false
> Negate comparison result: false
> Column[0][1] Id: 1
> Operator: =
> Ordered nulls: false
> Unknown return value: false
> Negate comparison result: false
> optimizer estimated row count: 0.00
> optimizer estimated cost:
> 0.00
>
> Right result set:
> Table Scan ResultSet for INGRESS_COS_QUEUE_CONFIG_BUNDLE at read committed isolation level using instantaneous share row locking chosen by the optimizer
> Number of opens = 0
> Rows seen = 0
> Rows filtered = 0
> Fetch Size = 16
> constructor time (milliseconds) = 0
> open time (milliseconds) = 0
> next time (milliseconds) = 0
> close time (milliseconds) = 0
>
> scan information:
> start position:
> null
> stop position:
> null
> qualifiers:
> Column[0][0] Id: 0
> Operator: =
> Ordered nulls: false
> Unknown return value: false
> Negate comparison result: false
> optimizer estimated row count: 0.00
> optimizer estimated cost: 0.00
>
> Right result set:
> Table Scan ResultSet for CONFIGURATION_BUNDLE_9145E10G at read committed isolation level using instantaneous share row locking chosen by the optimizer
> Number of opens = 0
> Rows seen = 0
> Rows filtered = 0
> Fetch Size = 16
> constructor time (milliseconds) = 0
> open time (milliseconds) = 0
> next time (milliseconds) = 0
> close time (milliseconds) = 0
>
> scan information:
> start position:
> null
> stop position:
> null
> qualifiers:
> Column[0][0] Id: 0
> Operator: =
> Ordered nulls: false
> Unknown return value: false
> Negate comparison result: false
> optimizer estimated row count: 0.00
> optimizer estimated cost: 0.00
>
> -----Original Message-----
> From: Bergquist, Brett [mailto:BBergquist@canoga.com]
> Sent: Wednesday, March 27, 2013 8:42 PM
> To: derby-dev@db.apache.org
> Subject: RE: Why is the optimizer choosing such a bad path
>
> I am able to build Derby so I can try a patch. On DERBY-6045, there are two attached patches. Two questions:
>
> 1. Are the patches against the trunk or can they be applied to 10.9.1.0 (I already have been building the equivalent of that release anyways myself).
> 2. Apply both patches?
>
>
> ________________________________________
> From: Mike Matrigali [mikem_app@sbcglobal.net]
> Sent: Wednesday, March 27, 2013 6:22 PM
> To: derby-dev@db.apache.org
> Subject: Re: Why is the optimizer choosing such a bad path
>
> I would suggest seeing if this is related to DERBY-6045 or not. I
> don't think this query goes through the in-list path but I am not sure, so if you are set up you could apply the patch and see if it makes a difference.
> There is a patch available and I believe it will be going into trunk soon.
>
> I have been waiting for that patch to go in, and then look to see if the underlying problem exists in other parts of the code. The problem is that we changed update statistics to not create a statistic on a unique single column index, and that the code above then did not do the right thing when that stat did not exist. To see if you are running into a similar problem you can use the workaround that Kristian suggested in that issue:
>
> I think specifying
> derby.storage.indexStats.debug.keepDisposableStats=true *and* regenerating statistics for the relevant tables will suffice as a work-around for this issue.
>
> Given that we agree the statistics for single-column unique indexes aren't needed, do we know what puts off the optimizer?
> The lack of statistics, or stale row estimates?
> (I don't have time to dig into that, and I don't know what the
> optimizer does in this case.)
>
> If you set the property on your db and rerun all the statistics and see a different result then it will point to another place in the code that needs to change to handle a stat not existing in the catalog.
>
> On 3/27/2013 12:16 PM, Bergquist, Brett wrote:
>> Some background.
>>
>> I have a customer that is using an earlier release of our system that has
>> Derby 10.8.2.1 installed. Because of issues like
>> https://issues.apache.org/jira/browse/DERBY-5680,
>> it has been running with the indexStat daemon disabled.
>>
>> We are going to have a new release soon and it will be installing Derby 10.9.1.0 with the indexStat
>> daemon enabled. I recently got a copy of the customer's database (132Gb) and ran into
>> a very long query. I manually ran SYS_UTIL.SYSCS_UPDATE_STATISTICS on all of the tables
>> in the query to ensure that the statistics are up to date.
>>
>> The tables in the query look like:
>>
>> // 62,908,433 Rows
>> CREATE TABLE "CORE_V1"."CONFIGURATIONSET_CONFIGURATIONBUNDLE"
>> (
>> CONFIGURATIONBUNDLE_ID int NOT NULL,
>> CONFIGURATIONSET_ID int NOT NULL,
>> CONSTRAINT CONFIGURATIONSET_CONFIGURATIONBUNDLE_PK PRIMARY KEY
>> (CONFIGURATIONBUNDLE_ID,CONFIGURATIONSET_ID)
>> );
>> ALTER TABLE "CORE_V1"."CONFIGURATIONSET_CONFIGURATIONBUNDLE"
>> ADD CONSTRAINT CONFIGURATIONSET_CONFIGURATIONBUNDLE_FK_2
>> FOREIGN KEY (CONFIGURATIONSET_ID)
>> REFERENCES "CORE_V1"."CONFIGURATION_SET"(ID);
>> ALTER TABLE "CORE_V1"."CONFIGURATIONSET_CONFIGURATIONBUNDLE"
>> ADD CONSTRAINT CONFIGURATIONSET_CONFIGURATIONBUNDLE_FK_1
>> FOREIGN KEY (CONFIGURATIONBUNDLE_ID)
>> REFERENCES "CORE_V1"."CONFIGURATION_BUNDLE"(ID);
>> CREATE INDEX SQL100922214558160 ON
>> "CORE_V1"."CONFIGURATIONSET_CONFIGURATIONBUNDLE"(CONFIGURATIONSET_ID)
>> ;
>> CREATE INDEX SQL100922215312050 ON
>> "CORE_V1"."CONFIGURATIONSET_CONFIGURATIONBUNDLE"(CONFIGURATIONBUNDLE_
>> I D); CREATE UNIQUE INDEX SQL081029110254290 ON
>> "CORE_V1"."CONFIGURATIONSET_CONFIGURATIONBUNDLE"
>> (
>> CONFIGURATIONBUNDLE_ID,
>> CONFIGURATIONSET_ID
>> );
>>
>> // 4 Rows
>> CREATE TABLE "PKG_9145E10G"."INGRESS_COS_QUEUE_CONFIG_BUNDLE"
>> (
>> ID int PRIMARY KEY NOT NULL,
>> LLQ_CONFIG_ENTRY_ID int NOT NULL ); ALTER TABLE
>> "PKG_9145E10G"."INGRESS_COS_QUEUE_CONFIG_BUNDLE"
>> ADD CONSTRAINT INGRESS_COS_QUEUE_CONFIG_BUNDLE_FK_2
>> FOREIGN KEY (LLQ_CONFIG_ENTRY_ID)
>> REFERENCES "PKG_9145E10G"."INGRESS_COS_QUEUE_CONFIG_ENTRY"(ID);
>> ALTER TABLE "PKG_9145E10G"."INGRESS_COS_QUEUE_CONFIG_BUNDLE"
>> ADD CONSTRAINT INGRESS_COS_QUEUE_CONFIG_BUNDLE_FK_1
>> FOREIGN KEY (ID)
>> REFERENCES "CORE_V1"."CONFIGURATION_BUNDLE"(ID);
>> CREATE INDEX SQL130327093508050 ON
>> "PKG_9145E10G"."INGRESS_COS_QUEUE_CONFIG_BUNDLE"(ID);
>> CREATE INDEX SQL130327093508060 ON
>> "PKG_9145E10G"."INGRESS_COS_QUEUE_CONFIG_BUNDLE"(LLQ_CONFIG_ENTRY_ID)
>> ; CREATE UNIQUE INDEX SQL130327093437740 ON
>> "PKG_9145E10G"."INGRESS_COS_QUEUE_CONFIG_BUNDLE"(ID);
>>
>> // 197,363 Rows
>> CREATE TABLE "PKG_9145E10G"."CONFIGURATION_BUNDLE_9145E10G"
>> (
>> ID int PRIMARY KEY NOT NULL
>> );
>> ALTER TABLE "PKG_9145E10G"."CONFIGURATION_BUNDLE_9145E10G"
>> ADD CONSTRAINT CONFIGURATION_BUNDLE_9145E10G_FK_1
>> FOREIGN KEY (ID)
>> REFERENCES "CORE_V1"."CONFIGURATION_BUNDLE"(ID);
>> CREATE UNIQUE INDEX SQL100226025356610 ON
>> "PKG_9145E10G"."CONFIGURATION_BUNDLE_9145E10G"(ID);
>> CREATE INDEX SQL100922215631540 ON
>> "PKG_9145E10G"."CONFIGURATION_BUNDLE_9145E10G"(ID);
>>
>> // 6,740,327 Rows
>> CREATE TABLE "CORE_V1"."CONFIGURATION_BUNDLE"
>> (
>> DTYPE varchar(64),
>> OPLOCK int DEFAULT 0 NOT NULL,
>> BUNDLE_NAME varchar(64) NOT NULL,
>> ID int PRIMARY KEY NOT NULL
>> );
>> CREATE INDEX CONFIGURATION_BUNDLE_IX_2 ON
>> "CORE_V1"."CONFIGURATION_BUNDLE"(BUNDLE_NAME);
>> CREATE INDEX CONFIGURATION_BUNDLE_IX_1 ON
>> "CORE_V1"."CONFIGURATION_BUNDLE"(DTYPE);
>> CREATE UNIQUE INDEX SQL100922215131580 ON
>> "CORE_V1"."CONFIGURATION_BUNDLE"(ID);
>>
>>
>> For some reason, the optimizer is doing a table scan across the
>> CORE_V1.CONFIGURATIONSET_CONFIGURATIONBUNDLE table which has 64 million rows and it even goes across this 4 times!.
>>
>> One issue is that this query is generated by Eclipselink (JPA) and I have no control on the query generation.
>>
>> So any ideas on why it would chose this path and what I might be able to do about it? In playing
>> around and trying to find the issue, I notice that if I remove the
>>
>> t0.DTYPE = 'INGRESS_COS_QUEUE_CONFIG_BUNDLE_9145E10G')
>>
>> constraint, then the query returns 0 rows (it should even with this constraint as there are no rows
>> that are acceptable) and returns them in about .05 seconds. Note CORE_V1.CONFIGURATION_BUNDLE does
>> have a non-unique index on DTYPE.
>>
>> Ok, just on a whim, I removed the index on DTYPE and the query came
>> back .06 seconds. That column is used by Eclipselink in determining which of a "derived" object to return so I don't have much control on it.
>>
>> ----
>> Statement Name:
>> SQL_CURLH000C1
>> Statement Text:
>> SELECT t0.ID, t0.DTYPE, t0.BUNDLE_NAME, t0.OPLOCK, t1.ID,
>> t2.ID, t2.LLQ_CONFIG_ENTRY_ID FROM
>> CORE_V1.CONFIGURATIONSET_CONFIGURATIONBUNDLE t3,
>> PKG_9145E10G.INGRESS_COS_QUEUE_CONFIG_BUNDLE t2,
>> PKG_9145E10G.CONFIGURATION_BUNDLE_9145E10G t1,
>> CORE_V1.CONFIGURATION_BUNDLE t0 WHERE (((t3.CONFIGURATIONSET_ID =
>> 4000) AND (t0.ID = t3.CONFIGURATIONBUNDLE_ID)) AND (((t2.ID = t0.ID)
>> AND (t1.ID = t0.ID)) AND (t0.DTYPE =
>> 'INGRESS_COS_QUEUE_CONFIG_BUNDLE_9145E10G')))
>> Parse Time: 0
>> Bind Time: 0
>> Optimize Time: 0
>> Generate Time: 0
>> Compile Time: 0
>> Execute Time: 0
>> Begin Compilation Timestamp : null
>> End Compilation Timestamp : null
>> Begin Execution Timestamp : null
>> End Execution Timestamp : null
>> Statement Execution Plan Text:
>> Project-Restrict ResultSet (9):
>> Number of opens = 1
>> Rows seen = 0
>> Rows filtered = 0
>> restriction = false
>> projection = true
>> constructor time (milliseconds) = 0
>> open time (milliseconds) = 0
>> next time (milliseconds) = 0
>> close time (milliseconds) = 0
>> restriction time (milliseconds) = 0
>> projection time (milliseconds) = 0
>> optimizer estimated row count: 0.00
>> optimizer estimated cost: 8.05 Source result set:
>> Nested Loop Join ResultSet:
>> Number of opens = 1
>> Rows seen from the left = 0
>> Rows seen from the right = 0
>> Rows filtered = 0
>> Rows returned = 0
>> constructor time (milliseconds) = 0
>> open time (milliseconds) = 0
>> next time (milliseconds) = 0
>> close time (milliseconds) = 0
>> optimizer estimated row count: 0.00
>> optimizer estimated cost: 8.05
>> Left result set:
>> Nested Loop Join ResultSet:
>> Number of opens = 1
>> Rows seen from the left = 0
>> Rows seen from the right = 0
>> Rows filtered = 0
>> Rows returned = 0
>> constructor time (milliseconds) = 0
>> open time (milliseconds) = 0
>> next time (milliseconds) = 0
>> close time (milliseconds) = 0
>> optimizer estimated row count: 0.00
>> optimizer estimated cost: 8.05
>> Left result set:
>> Nested Loop Join ResultSet:
>> Number of opens = 1
>> Rows seen from the left = 4
>> Rows seen from the right = 0
>> Rows filtered = 0
>> Rows returned = 0
>> constructor time (milliseconds) = 0
>> open time (milliseconds) = 0
>> next time (milliseconds) = 0
>> close time (milliseconds) = 0
>> optimizer estimated row count: 0.00
>> optimizer estimated cost: 8.05
>> Left result set:
>> Index Row to Base Row ResultSet for CONFIGURATION_BUNDLE:
>> Number of opens = 1
>> Rows seen = 4
>> Columns accessed from heap = {0, 1, 2, 3}
>> constructor time (milliseconds) = 0
>> open time (milliseconds) = 0
>> next time (milliseconds) = 0
>> close time (milliseconds) = 0
>> optimizer estimated row count: 0.00
>> optimizer estimated cost: 8.05
>> Index Scan ResultSet for CONFIGURATION_BUNDLE using index CONFIGURATION_BUNDLE_IX_1 at read committed isolation level using instantaneous share row locking chosen by the optimizer
>> Number of opens = 1
>> Rows seen = 4
>> Rows filtered = 0
>> Fetch Size = 16
>> constructor time (milliseconds) = 0
>> open time (milliseconds) = 0
>> next time (milliseconds) = 0
>> close time (milliseconds) = 0
>> next time in
>> milliseconds/row = 0
>>
>> scan information:
>> Bit set of columns fetched=All
>> Number of columns fetched=2
>> Number of deleted rows visited=0
>> Number of pages visited=5
>> Number of rows qualified=4
>> Number of rows visited=5
>> Scan type=btree
>> Tree height=5
>> start position:
>> >= on first 1 column(s).
>> Ordered null semantics on the following columns:
>> stop position:
>> > on first 1 column(s).
>> Ordered null semantics on the following columns:
>> qualifiers:
>> None
>> optimizer estimated row count: 0.00
>> optimizer estimated
>> cost: 8.05
>>
>> Right result set:
>> Table Scan ResultSet for CONFIGURATIONSET_CONFIGURATIONBUNDLE at read committed isolation level using instantaneous share row locking chosen by the optimizer
>> Number of opens = 4
>> Rows seen = 0
>> Rows filtered = 0
>> Fetch Size = 16
>> constructor time (milliseconds) = 0
>> open time (milliseconds) = 0
>> next time (milliseconds) = 0
>> close time (milliseconds) = 0
>>
>> scan information:
>> Bit set of columns fetched=All
>> Number of columns fetched=2
>> Number of pages visited=670838
>> Number of rows qualified=0
>> Number of rows visited=262429876
>> Scan type=heap
>> start position:
>> null
>> stop position:
>> null
>> qualifiers:
>> Column[0][0] Id: 0
>> Operator: =
>> Ordered nulls: false
>> Unknown return value: false
>> Negate comparison result: false
>> Column[0][1] Id: 1
>> Operator: =
>> Ordered nulls: false
>> Unknown return value: false
>> Negate comparison result: false
>> optimizer estimated row count: 0.00
>> optimizer estimated cost: 0.00
>>
>> Right result set:
>> Table Scan ResultSet for INGRESS_COS_QUEUE_CONFIG_BUNDLE at read committed isolation level using instantaneous share row locking chosen by the optimizer
>> Number of opens = 0
>> Rows seen = 0
>> Rows filtered = 0
>> Fetch Size = 16
>> constructor time (milliseconds) = 0
>> open time (milliseconds) = 0
>> next time (milliseconds) = 0
>> close time (milliseconds) = 0
>>
>> scan information:
>> start position:
>> null
>> stop position:
>> null
>> qualifiers:
>> Column[0][0] Id: 0
>> Operator: =
>> Ordered nulls: false
>> Unknown return value: false
>> Negate comparison result: false
>> optimizer estimated row count: 0.00
>> optimizer estimated cost: 0.00
>>
>> Right result set:
>> Table Scan ResultSet for CONFIGURATION_BUNDLE_9145E10G at read committed isolation level using instantaneous share row locking chosen by the optimizer
>> Number of opens = 0
>> Rows seen = 0
>> Rows filtered = 0
>> Fetch Size = 16
>> constructor time (milliseconds) = 0
>> open time (milliseconds) = 0
>> next time (milliseconds) = 0
>> close time (milliseconds) = 0
>>
>> scan information:
>> start position:
>> null
>> stop position:
>> null
>> qualifiers:
>> Column[0][0] Id: 0
>> Operator: =
>> Ordered nulls: false
>> Unknown return value: false
>> Negate comparison result: false
>> optimizer estimated row count: 0.00
>> optimizer estimated cost: 0.00
>>
>>
>>
>
>
>
>
>
>
>
>
>
Re: Why is the optimizer choosing such a bad path
Posted by Mike Matrigali <mi...@sbcglobal.net>.
On 3/28/2013 6:38 AM, Bergquist, Brett wrote:
> I tried adding:
>
> derby.storage.indexStats.debug.keepDisposableStats=true
>
> to derby.properties *and* regenerating statistics for the tables. There is no change in the query plan.
>
> Does this mean that applying the patches suggested will probably have no effect either?
I think this is correct. The patch should only fix problems where
update statistics is run and a bad query plan shows up in base system
10.9, but a good plan results when that flag is enabled and update
statistics is run.
I think you have always been doing this but always best to run update
statistics after data is loaded.
At this point hard to say where the problem is. It seems very strange
for optimizer to come up with 0 rows for a 62 million row table (or for
any table with more than a few rows - lets say 10,000 to be safe). The
system has a separate call for the optmizer to get the number of rows
that is separate from anything the stats generated by update stats. But
it is an estimate maintained by the storage system and the estimate is
updated as a by product of running
update statistics (or any table scan of the table/index). But it should
also be maintained continuously as
part of inserts.
Best next step would be to somehow get a reproducible case where the
optimizer returns 0 row estimate for that big table and track down
the call that is giving the bad data.
>
> -----Original Message-----
> From: Bergquist, Brett [mailto:BBergquist@canoga.com]
> Sent: Thursday, March 28, 2013 8:52 AM
> To: derby-dev@db.apache.org
> Subject: RE: Why is the optimizer choosing such a bad path
>
> After dropping and recreating on index:
>
> DROP INDEX CORE_V1.CONFIGURATION_BUNDLE_IX_1;
> CREATE INDEX CONFIGURATION_BUNDLE_IX_1 ON "CORE_V1"."CONFIGURATION_BUNDLE"(DTYPE);
>
> And rerunning the query, the optimizer chose that index and the optimizer row count estimates are no longer 0.
>
> So it appears that there is something bad with that index that SYSCS_UTIL.SYSCS_CHECK_TABLE does not see and even SYSCS_UTIL.SYSCS_DROP_STATISTICS and SYSCS_UTIL.SYSCS_UPDATE_STATISTICS cannot fix.
>
> Statement Name:
> SQL_CURLH000C2
> Statement Text:
> SELECT t0.ID, t0.DTYPE, t0.BUNDLE_NAME, t0.OPLOCK, t1.ID, t2.ID, t2.LLQ_CONFIG_ENTRY_ID FROM CORE_V1.CONFIGURATIONSET_CONFIGURATIONBUNDLE t3, PKG_9145E10G.INGRESS_COS_QUEUE_CONFIG_BUNDLE t2, PKG_9145E10G.CONFIGURATION_BUNDLE_9145E10G t1, CORE_V1.CONFIGURATION_BUNDLE t0 WHERE (((t3.CONFIGURATIONSET_ID = 4000) AND (t0.ID = t3.CONFIGURATIONBUNDLE_ID)) AND (((t2.ID = t0.ID) AND (t1.ID = t0.ID)) AND (t0.DTYPE = 'INGRESS_COS_QUEUE_CONFIG_BUNDLE_9145E10G')))
> Parse Time: 5
> Bind Time: 9
> Optimize Time: 133
> Generate Time: 6
> Compile Time: 153
> Execute Time: 35
> Begin Compilation Timestamp : 2013-03-28 08:44:40.901 End Compilation Timestamp : 2013-03-28 08:44:41.054 Begin Execution Timestamp : 2013-03-28 08:44:41.058 End Execution Timestamp : 2013-03-28 08:44:41.094 Statement Execution Plan Text:
> Project-Restrict ResultSet (10):
> Number of opens = 1
> Rows seen = 0
> Rows filtered = 0
> restriction = false
> projection = true
> constructor time (milliseconds) = 0
> open time (milliseconds) = 35
> next time (milliseconds) = 0
> close time (milliseconds) = 0
> restriction time (milliseconds) = 0
> projection time (milliseconds) = 0
> optimizer estimated row count: 2.00
> optimizer estimated cost: 51.52
> Source result set:
> Nested Loop Exists Join ResultSet:
> Number of opens = 1
> Rows seen from the left = 0
> Rows seen from the right = 0
> Rows filtered = 0
> Rows returned = 0
> constructor time (milliseconds) = 0
> open time (milliseconds) = 35
> next time (milliseconds) = 0
> close time (milliseconds) = 1
> optimizer estimated row count: 2.00
> optimizer estimated cost: 51.52
> Left result set:
> Nested Loop Exists Join ResultSet:
> Number of opens = 1
> Rows seen from the left = 0
> Rows seen from the right = 0
> Rows filtered = 0
> Rows returned = 0
> constructor time (milliseconds) = 0
> open time (milliseconds) = 35
> next time (milliseconds) = 0
> close time (milliseconds) = 1
> optimizer estimated row count: 2.00
> optimizer estimated cost: 37.18
> Left result set:
> Nested Loop Exists Join ResultSet:
> Number of opens = 1
> Rows seen from the left = 4
> Rows seen from the right = 0
> Rows filtered = 0
> Rows returned = 0
> constructor time (milliseconds) = 0
> open time (milliseconds) = 1
> next time (milliseconds) = 34
> close time (milliseconds) = 1
> optimizer estimated row count: 2.00
> optimizer estimated cost: 27.75
> Left result set:
> Index Row to Base Row ResultSet for CONFIGURATION_BUNDLE:
> Number of opens = 1
> Rows seen = 4
> Columns accessed from heap = {0, 1, 2, 3}
> constructor time (milliseconds) = 1
> open time (milliseconds) = 0
> next time (milliseconds) = 0
> close time (milliseconds) = 1
> optimizer estimated row count: 2.00
> optimizer estimated cost: 12.04
> Index Scan ResultSet for CONFIGURATION_BUNDLE using index CONFIGURATION_BUNDLE_IX_1 at read committed isolation level using instantaneous share row locking chosen by the optimizer
> Number of opens = 1
> Rows seen = 4
> Rows filtered = 0
> Fetch Size = 16
> constructor time (milliseconds) = 0
> open time (milliseconds) = 1
> next time (milliseconds) = 0
> close time (milliseconds) = 1
> next time in milliseconds/row = 0
>
> scan information:
> Bit set of columns fetched=All
> Number of columns fetched=2
> Number of deleted rows visited=0
> Number of pages visited=4
> Number of rows qualified=4
> Number of rows visited=5
> Scan type=btree
> Tree height=4
> start position:
> >= on first 1 column(s).
> Ordered null semantics on the following columns:
> stop position:
> > on first 1 column(s).
> Ordered null semantics on the following columns:
> qualifiers:
> None
> optimizer estimated row count: 2.00
> optimizer estimated cost: 12.04
>
> Right result set:
> Index Scan ResultSet for CONFIGURATIONSET_CONFIGURATIONBUNDLE using constraint CONFIGURATIONSET_CONFIGURATIONBUNDLE_PK at read committed isolation level using share row locking chosen by the optimizer
> Number of opens = 4
> Rows seen = 0
> Rows filtered = 0
> Fetch Size = 1
> constructor time (milliseconds) = 0
> open time (milliseconds) = 1
> next time (milliseconds) = 33
> close time (milliseconds) = 1
>
> scan information:
> Bit set of columns fetched={0, 1}
> Number of columns fetched=2
> Number of deleted rows visited=0
> Number of pages visited=20
> Number of rows qualified=0
> Number of rows visited=4
> Scan type=btree
> Tree height=5
> start position:
> >= on first 2 column(s).
> Ordered null semantics on the following columns:
> 0 1
> stop position:
> > on first 2 column(s).
> Ordered null semantics on the following columns:
> 0 1
> qualifiers:
> None
> optimizer estimated row count: 2.00
> optimizer estimated cost: 15.72
>
> Right result set:
> Index Scan ResultSet for CONFIGURATION_BUNDLE_9145E10G using constraint SQL100226025356610 at read committed isolation level using share row locking chosen by the optimizer
> Number of opens = 0
> Rows seen = 0
> Rows filtered = 0
> Fetch Size = 1
> constructor time (milliseconds) = 0
> open time (milliseconds) = 0
> next time (milliseconds) = 0
> close time (milliseconds) = 0
>
> scan information:
> start position:
> Positioning information not available because this ResultSet was never opened.
> stop position:
> Positioning information not available because this ResultSet was never opened.
> qualifiers:
> Column[0][0] Id: 0
> Operator: =
> Ordered nulls: false
> Unknown return value: false
> Negate comparison result: false
> optimizer estimated row count: 2.00
> optimizer estimated cost: 9.43
>
> Right result set:
> Index Row to Base Row ResultSet for INGRESS_COS_QUEUE_CONFIG_BUNDLE:
> Number of opens = 0
> Rows seen = 0
> Columns accessed from heap = {1}
> constructor time (milliseconds) = 0
> open time (milliseconds) = 0
> next time (milliseconds) = 0
> close time (milliseconds) = 0
> optimizer estimated row count: 2.00
> optimizer estimated cost: 14.34
> Index Scan ResultSet for INGRESS_COS_QUEUE_CONFIG_BUNDLE using constraint SQL130327093437740 at read committed isolation level using share row locking chosen by the optimizer
> Number of opens = 0
> Rows seen = 0
> Rows filtered = 0
> Fetch Size = 1
> constructor time (milliseconds) = 0
> open time (milliseconds) = 0
> next time (milliseconds) = 0
> close time (milliseconds) = 0
>
> scan information:
> start position:
> Positioning information not available because this ResultSet was never opened.
> stop position:
> Positioning information not available because this ResultSet was never opened.
> qualifiers:
> Column[0][0] Id: 0
> Operator: =
> Ordered nulls: false
> Unknown return value: false
> Negate comparison result: false
> optimizer estimated row count: 2.00
> optimizer estimated cost: 14.34
>
>
>
> -----Original Message-----
> From: Bergquist, Brett [mailto:BBergquist@canoga.com]
> Sent: Thursday, March 28, 2013 8:33 AM
> To: derby-dev@db.apache.org
> Subject: RE: Why is the optimizer choosing such a bad path
>
> Okay, I finally figured out that " CALL SYSCS_UTIL.SYSCS_SET_STATISTICS_TIMING(1);" is required. Now from the name which has "timing" in it, one (or at least I) would not think that this would affect the returning of the optimizer estimates. I guess I naively assumed this would affect the reporting of the compile and execution times. Maybe the documentation needs to be fixed here.
>
> In any case, below is the query plan with this turned on. Note that optimizer is estimating a row count of 0 for the table with 64 million rows and does a table scan.
>
> Statement Name:
> SQL_CURLH000C1
> Statement Text:
> SELECT t0.ID, t0.DTYPE, t0.BUNDLE_NAME, t0.OPLOCK, t1.ID, t2.ID, t2.LLQ_CONFIG_ENTRY_ID FROM CORE_V1.CONFIGURATIONSET_CONFIGURATIONBUNDLE t3, PKG_9145E10G.INGRESS_COS_QUEUE_CONFIG_BUNDLE t2, PKG_9145E10G.CONFIGURATION_BUNDLE_9145E10G t1, CORE_V1.CONFIGURATION_BUNDLE t0 WHERE (((t3.CONFIGURATIONSET_ID = 4000) AND (t0.ID = t3.CONFIGURATIONBUNDLE_ID)) AND (((t2.ID = t0.ID) AND (t1.ID = t0.ID)) AND (t0.DTYPE = 'INGRESS_COS_QUEUE_CONFIG_BUNDLE_9145E10G')))
> Parse Time: 8
> Bind Time: 66
> Optimize Time: 3935
> Generate Time: 7
> Compile Time: 4016
> Execute Time: 220556
> Begin Compilation Timestamp : 2013-03-28 08:27:13.028 End Compilation Timestamp : 2013-03-28 08:27:17.044 Begin Execution Timestamp : 2013-03-28 08:27:17.053 End Execution Timestamp : 2013-03-28 08:30:57.615 Statement Execution Plan Text:
> Project-Restrict ResultSet (9):
> Number of opens = 1
> Rows seen = 0
> Rows filtered = 0
> restriction = false
> projection = true
> constructor time (milliseconds) = 0
> open time (milliseconds) = 220556
> next time (milliseconds) = 0
> close time (milliseconds) = 0
> restriction time (milliseconds) = 0
> projection time (milliseconds) = 0
> optimizer estimated row count: 0.00
> optimizer estimated cost: 8.05
> Source result set:
> Nested Loop Join ResultSet:
> Number of opens = 1
> Rows seen from the left = 0
> Rows seen from the right = 0
> Rows filtered = 0
> Rows returned = 0
> constructor time (milliseconds) = 0
> open time (milliseconds) = 220556
> next time (milliseconds) = 0
> close time (milliseconds) = 6
> optimizer estimated row count: 0.00
> optimizer estimated cost: 8.05
> Left result set:
> Nested Loop Join ResultSet:
> Number of opens = 1
> Rows seen from the left = 0
> Rows seen from the right = 0
> Rows filtered = 0
> Rows returned = 0
> constructor time (milliseconds) = 0
> open time (milliseconds) = 220556
> next time (milliseconds) = 0
> close time (milliseconds) = 6
> optimizer estimated row count: 0.00
> optimizer estimated cost: 8.05
> Left result set:
> Nested Loop Join ResultSet:
> Number of opens = 1
> Rows seen from the left = 4
> Rows seen from the right = 0
> Rows filtered = 0
> Rows returned = 0
> constructor time (milliseconds) = 0
> open time (milliseconds) = 63
> next time (milliseconds) = 220493
> close time (milliseconds) = 6
> optimizer estimated row count: 0.00
> optimizer estimated cost: 8.05
> Left result set:
> Index Row to Base Row ResultSet for CONFIGURATION_BUNDLE:
> Number of opens = 1
> Rows seen = 4
> Columns accessed from heap = {0, 1, 2, 3}
> constructor time (milliseconds) = 0
> open time (milliseconds) = 0
> next time (milliseconds) = 64
> close time (milliseconds) = 6
> optimizer estimated row count: 0.00
> optimizer estimated cost: 8.05
> Index Scan ResultSet for CONFIGURATION_BUNDLE using index CONFIGURATION_BUNDLE_IX_1 at read committed isolation level using instantaneous share row locking chosen by the optimizer
> Number of opens = 1
> Rows seen = 4
> Rows filtered = 0
> Fetch Size = 16
> constructor time (milliseconds) = 0
> open time (milliseconds) = 2
> next time (milliseconds) = 1
> close time (milliseconds) = 6
> next time in milliseconds/row = 0
>
> scan information:
> Bit set of columns fetched=All
> Number of columns fetched=2
> Number of deleted rows visited=0
> Number of pages visited=5
> Number of rows qualified=4
> Number of rows visited=5
> Scan type=btree
> Tree height=5
> start position:
> >= on first 1 column(s).
> Ordered null semantics on the following columns:
> stop position:
> > on first 1 column(s).
> Ordered null semantics on the following columns:
> qualifiers:
> None
> optimizer estimated row count: 0.00
> optimizer estimated cost: 8.05
>
> Right result set:
> Table Scan ResultSet for CONFIGURATIONSET_CONFIGURATIONBUNDLE at read committed isolation level using instantaneous share row locking chosen by the optimizer
> Number of opens = 4
> Rows seen = 0
> Rows filtered = 0
> Fetch Size = 16
> constructor time (milliseconds) = 0
> open time (milliseconds) = 64
> next time (milliseconds) = 0
> close time (milliseconds) = 11
>
> scan information:
> Bit set of columns fetched=All
> Number of columns fetched=2
> Number of pages visited=670832
> Number of rows qualified=0
> Number of rows visited=262428000
> Scan type=heap
> start position:
> null
> stop position:
> null
> qualifiers:
> Column[0][0] Id: 0
> Operator: =
> Ordered nulls: false
> Unknown return value: false
> Negate comparison result: false
> Column[0][1] Id: 1
> Operator: =
> Ordered nulls: false
> Unknown return value: false
> Negate comparison result: false
> optimizer estimated row count: 0.00
> optimizer estimated cost: 0.00
>
> Right result set:
> Table Scan ResultSet for INGRESS_COS_QUEUE_CONFIG_BUNDLE at read committed isolation level using instantaneous share row locking chosen by the optimizer
> Number of opens = 0
> Rows seen = 0
> Rows filtered = 0
> Fetch Size = 16
> constructor time (milliseconds) = 0
> open time (milliseconds) = 0
> next time (milliseconds) = 0
> close time (milliseconds) = 0
>
> scan information:
> start position:
> null
> stop position:
> null
> qualifiers:
> Column[0][0] Id: 0
> Operator: =
> Ordered nulls: false
> Unknown return value: false
> Negate comparison result: false
> optimizer estimated row count: 0.00
> optimizer estimated cost: 0.00
>
> Right result set:
> Table Scan ResultSet for CONFIGURATION_BUNDLE_9145E10G at read committed isolation level using instantaneous share row locking chosen by the optimizer
> Number of opens = 0
> Rows seen = 0
> Rows filtered = 0
> Fetch Size = 16
> constructor time (milliseconds) = 0
> open time (milliseconds) = 0
> next time (milliseconds) = 0
> close time (milliseconds) = 0
>
> scan information:
> start position:
> null
> stop position:
> null
> qualifiers:
> Column[0][0] Id: 0
> Operator: =
> Ordered nulls: false
> Unknown return value: false
> Negate comparison result: false
> optimizer estimated row count: 0.00
> optimizer estimated cost: 0.00
>
> -----Original Message-----
> From: Bergquist, Brett [mailto:BBergquist@canoga.com]
> Sent: Wednesday, March 27, 2013 8:42 PM
> To: derby-dev@db.apache.org
> Subject: RE: Why is the optimizer choosing such a bad path
>
> I am able to build Derby so I can try a patch. On DERBY-6045, there are two attached patches. Two questions:
>
> 1. Are the patches against the trunk or can they be applied to 10.9.1.0 (I already have been building the equivalent of that release anyways myself).
> 2. Apply both patches?
>
>
> ________________________________________
> From: Mike Matrigali [mikem_app@sbcglobal.net]
> Sent: Wednesday, March 27, 2013 6:22 PM
> To: derby-dev@db.apache.org
> Subject: Re: Why is the optimizer choosing such a bad path
>
> I would suggest seeing if this is related to DERBY-6045 or not. I
> don't think this query goes through the in-list path but I am not sure, so if you are set up you could apply the patch and see if it makes a difference.
> There is a patch available and I believe it will be going into trunk soon.
>
> I have been waiting for that patch to go in, and then look to see if the underlying problem exists in other parts of the code. The problem is that we changed update statistics to not create a statistic on a unique single column index, and that the code above then did not do the right thing when that stat did not exist. To see if you are running into a similar problem you can use the workaround that Kristian suggested in that issue:
>
> I think specifying
> derby.storage.indexStats.debug.keepDisposableStats=true *and* regenerating statistics for the relevant tables will suffice as a work-around for this issue.
>
> Given that we agree the statistics for single-column unique indexes aren't needed, do we know what puts off the optimizer?
> The lack of statistics, or stale row estimates?
> (I don't have time to dig into that, and I don't know what the optimizer does in this case.)
>
> If you set the property on your db and rerun all the statistics and see a different result then it will point to another place in the code that needs to change to handle a stat not existing in the catalog.
>
> On 3/27/2013 12:16 PM, Bergquist, Brett wrote:
>> Some background.
>>
>> I have a customer that is using an earlier release of our system that has
>> Derby 10.8.2.1 installed. Because of issues like
>> https://issues.apache.org/jira/browse/DERBY-5680,
>> it has been running with the indexStat daemon disabled.
>>
>> We are going to have a new release soon and it will be installing Derby 10.9.1.0 with the indexStat
>> daemon enabled. I recently got a copy of the customer's database (132Gb) and ran into
>> a very long query. I manually ran SYS_UTIL.SYSCS_UPDATE_STATISTICS on all of the tables
>> in the query to ensure that the statistics are up to date.
>>
>> The tables in the query look like:
>>
>> // 62,908,433 Rows
>> CREATE TABLE "CORE_V1"."CONFIGURATIONSET_CONFIGURATIONBUNDLE"
>> (
>> CONFIGURATIONBUNDLE_ID int NOT NULL,
>> CONFIGURATIONSET_ID int NOT NULL,
>> CONSTRAINT CONFIGURATIONSET_CONFIGURATIONBUNDLE_PK PRIMARY KEY
>> (CONFIGURATIONBUNDLE_ID,CONFIGURATIONSET_ID)
>> );
>> ALTER TABLE "CORE_V1"."CONFIGURATIONSET_CONFIGURATIONBUNDLE"
>> ADD CONSTRAINT CONFIGURATIONSET_CONFIGURATIONBUNDLE_FK_2
>> FOREIGN KEY (CONFIGURATIONSET_ID)
>> REFERENCES "CORE_V1"."CONFIGURATION_SET"(ID);
>> ALTER TABLE "CORE_V1"."CONFIGURATIONSET_CONFIGURATIONBUNDLE"
>> ADD CONSTRAINT CONFIGURATIONSET_CONFIGURATIONBUNDLE_FK_1
>> FOREIGN KEY (CONFIGURATIONBUNDLE_ID)
>> REFERENCES "CORE_V1"."CONFIGURATION_BUNDLE"(ID);
>> CREATE INDEX SQL100922214558160 ON
>> "CORE_V1"."CONFIGURATIONSET_CONFIGURATIONBUNDLE"(CONFIGURATIONSET_ID);
>> CREATE INDEX SQL100922215312050 ON
>> "CORE_V1"."CONFIGURATIONSET_CONFIGURATIONBUNDLE"(CONFIGURATIONBUNDLE_I
>> D); CREATE UNIQUE INDEX SQL081029110254290 ON
>> "CORE_V1"."CONFIGURATIONSET_CONFIGURATIONBUNDLE"
>> (
>> CONFIGURATIONBUNDLE_ID,
>> CONFIGURATIONSET_ID
>> );
>>
>> // 4 Rows
>> CREATE TABLE "PKG_9145E10G"."INGRESS_COS_QUEUE_CONFIG_BUNDLE"
>> (
>> ID int PRIMARY KEY NOT NULL,
>> LLQ_CONFIG_ENTRY_ID int NOT NULL
>> );
>> ALTER TABLE "PKG_9145E10G"."INGRESS_COS_QUEUE_CONFIG_BUNDLE"
>> ADD CONSTRAINT INGRESS_COS_QUEUE_CONFIG_BUNDLE_FK_2
>> FOREIGN KEY (LLQ_CONFIG_ENTRY_ID)
>> REFERENCES "PKG_9145E10G"."INGRESS_COS_QUEUE_CONFIG_ENTRY"(ID);
>> ALTER TABLE "PKG_9145E10G"."INGRESS_COS_QUEUE_CONFIG_BUNDLE"
>> ADD CONSTRAINT INGRESS_COS_QUEUE_CONFIG_BUNDLE_FK_1
>> FOREIGN KEY (ID)
>> REFERENCES "CORE_V1"."CONFIGURATION_BUNDLE"(ID);
>> CREATE INDEX SQL130327093508050 ON
>> "PKG_9145E10G"."INGRESS_COS_QUEUE_CONFIG_BUNDLE"(ID);
>> CREATE INDEX SQL130327093508060 ON
>> "PKG_9145E10G"."INGRESS_COS_QUEUE_CONFIG_BUNDLE"(LLQ_CONFIG_ENTRY_ID);
>> CREATE UNIQUE INDEX SQL130327093437740 ON
>> "PKG_9145E10G"."INGRESS_COS_QUEUE_CONFIG_BUNDLE"(ID);
>>
>> // 197,363 Rows
>> CREATE TABLE "PKG_9145E10G"."CONFIGURATION_BUNDLE_9145E10G"
>> (
>> ID int PRIMARY KEY NOT NULL
>> );
>> ALTER TABLE "PKG_9145E10G"."CONFIGURATION_BUNDLE_9145E10G"
>> ADD CONSTRAINT CONFIGURATION_BUNDLE_9145E10G_FK_1
>> FOREIGN KEY (ID)
>> REFERENCES "CORE_V1"."CONFIGURATION_BUNDLE"(ID);
>> CREATE UNIQUE INDEX SQL100226025356610 ON
>> "PKG_9145E10G"."CONFIGURATION_BUNDLE_9145E10G"(ID);
>> CREATE INDEX SQL100922215631540 ON
>> "PKG_9145E10G"."CONFIGURATION_BUNDLE_9145E10G"(ID);
>>
>> // 6,740,327 Rows
>> CREATE TABLE "CORE_V1"."CONFIGURATION_BUNDLE"
>> (
>> DTYPE varchar(64),
>> OPLOCK int DEFAULT 0 NOT NULL,
>> BUNDLE_NAME varchar(64) NOT NULL,
>> ID int PRIMARY KEY NOT NULL
>> );
>> CREATE INDEX CONFIGURATION_BUNDLE_IX_2 ON
>> "CORE_V1"."CONFIGURATION_BUNDLE"(BUNDLE_NAME);
>> CREATE INDEX CONFIGURATION_BUNDLE_IX_1 ON
>> "CORE_V1"."CONFIGURATION_BUNDLE"(DTYPE);
>> CREATE UNIQUE INDEX SQL100922215131580 ON
>> "CORE_V1"."CONFIGURATION_BUNDLE"(ID);
>>
>>
>> For some reason, the optimizer is doing a table scan across the
>> CORE_V1.CONFIGURATIONSET_CONFIGURATIONBUNDLE table which has 64 million rows and it even goes across this 4 times!.
>>
>> One issue is that this query is generated by Eclipselink (JPA) and I have no control on the query generation.
>>
>> So any ideas on why it would chose this path and what I might be able to do about it? In playing
>> around and trying to find the issue, I notice that if I remove the
>>
>> t0.DTYPE = 'INGRESS_COS_QUEUE_CONFIG_BUNDLE_9145E10G')
>>
>> constraint, then the query returns 0 rows (it should even with this constraint as there are no rows
>> that are acceptable) and returns them in about .05 seconds. Note CORE_V1.CONFIGURATION_BUNDLE does
>> have a non-unique index on DTYPE.
>>
>> Ok, just on a whim, I removed the index on DTYPE and the query came
>> back .06 seconds. That column is used by Eclipselink in determining which of a "derived" object to return so I don't have much control on it.
>>
>> ----
>> Statement Name:
>> SQL_CURLH000C1
>> Statement Text:
>> SELECT t0.ID, t0.DTYPE, t0.BUNDLE_NAME, t0.OPLOCK, t1.ID, t2.ID,
>> t2.LLQ_CONFIG_ENTRY_ID FROM
>> CORE_V1.CONFIGURATIONSET_CONFIGURATIONBUNDLE t3,
>> PKG_9145E10G.INGRESS_COS_QUEUE_CONFIG_BUNDLE t2,
>> PKG_9145E10G.CONFIGURATION_BUNDLE_9145E10G t1,
>> CORE_V1.CONFIGURATION_BUNDLE t0 WHERE (((t3.CONFIGURATIONSET_ID =
>> 4000) AND (t0.ID = t3.CONFIGURATIONBUNDLE_ID)) AND (((t2.ID = t0.ID)
>> AND (t1.ID = t0.ID)) AND (t0.DTYPE =
>> 'INGRESS_COS_QUEUE_CONFIG_BUNDLE_9145E10G')))
>> Parse Time: 0
>> Bind Time: 0
>> Optimize Time: 0
>> Generate Time: 0
>> Compile Time: 0
>> Execute Time: 0
>> Begin Compilation Timestamp : null
>> End Compilation Timestamp : null
>> Begin Execution Timestamp : null
>> End Execution Timestamp : null
>> Statement Execution Plan Text:
>> Project-Restrict ResultSet (9):
>> Number of opens = 1
>> Rows seen = 0
>> Rows filtered = 0
>> restriction = false
>> projection = true
>> constructor time (milliseconds) = 0
>> open time (milliseconds) = 0
>> next time (milliseconds) = 0
>> close time (milliseconds) = 0
>> restriction time (milliseconds) = 0
>> projection time (milliseconds) = 0
>> optimizer estimated row count: 0.00
>> optimizer estimated cost: 8.05
>> Source result set:
>> Nested Loop Join ResultSet:
>> Number of opens = 1
>> Rows seen from the left = 0
>> Rows seen from the right = 0
>> Rows filtered = 0
>> Rows returned = 0
>> constructor time (milliseconds) = 0
>> open time (milliseconds) = 0
>> next time (milliseconds) = 0
>> close time (milliseconds) = 0
>> optimizer estimated row count: 0.00
>> optimizer estimated cost: 8.05
>> Left result set:
>> Nested Loop Join ResultSet:
>> Number of opens = 1
>> Rows seen from the left = 0
>> Rows seen from the right = 0
>> Rows filtered = 0
>> Rows returned = 0
>> constructor time (milliseconds) = 0
>> open time (milliseconds) = 0
>> next time (milliseconds) = 0
>> close time (milliseconds) = 0
>> optimizer estimated row count: 0.00
>> optimizer estimated cost: 8.05
>> Left result set:
>> Nested Loop Join ResultSet:
>> Number of opens = 1
>> Rows seen from the left = 4
>> Rows seen from the right = 0
>> Rows filtered = 0
>> Rows returned = 0
>> constructor time (milliseconds) = 0
>> open time (milliseconds) = 0
>> next time (milliseconds) = 0
>> close time (milliseconds) = 0
>> optimizer estimated row count: 0.00
>> optimizer estimated cost: 8.05
>> Left result set:
>> Index Row to Base Row ResultSet for CONFIGURATION_BUNDLE:
>> Number of opens = 1
>> Rows seen = 4
>> Columns accessed from heap = {0, 1, 2, 3}
>> constructor time (milliseconds) = 0
>> open time (milliseconds) = 0
>> next time (milliseconds) = 0
>> close time (milliseconds) = 0
>> optimizer estimated row count: 0.00
>> optimizer estimated cost: 8.05
>> Index Scan ResultSet for CONFIGURATION_BUNDLE using index CONFIGURATION_BUNDLE_IX_1 at read committed isolation level using instantaneous share row locking chosen by the optimizer
>> Number of opens = 1
>> Rows seen = 4
>> Rows filtered = 0
>> Fetch Size = 16
>> constructor time (milliseconds) = 0
>> open time (milliseconds) = 0
>> next time (milliseconds) = 0
>> close time (milliseconds) = 0
>> next time in
>> milliseconds/row = 0
>>
>> scan information:
>> Bit set of columns fetched=All
>> Number of columns fetched=2
>> Number of deleted rows visited=0
>> Number of pages visited=5
>> Number of rows qualified=4
>> Number of rows visited=5
>> Scan type=btree
>> Tree height=5
>> start position:
>> >= on first 1 column(s).
>> Ordered null semantics on the following columns:
>> stop position:
>> > on first 1 column(s).
>> Ordered null semantics on the following columns:
>> qualifiers:
>> None
>> optimizer estimated row count: 0.00
>> optimizer estimated
>> cost: 8.05
>>
>> Right result set:
>> Table Scan ResultSet for CONFIGURATIONSET_CONFIGURATIONBUNDLE at read committed isolation level using instantaneous share row locking chosen by the optimizer
>> Number of opens = 4
>> Rows seen = 0
>> Rows filtered = 0
>> Fetch Size = 16
>> constructor time (milliseconds) = 0
>> open time (milliseconds) = 0
>> next time (milliseconds) = 0
>> close time (milliseconds) = 0
>>
>> scan information:
>> Bit set of columns fetched=All
>> Number of columns fetched=2
>> Number of pages visited=670838
>> Number of rows qualified=0
>> Number of rows visited=262429876
>> Scan type=heap
>> start position:
>> null
>> stop position:
>> null
>> qualifiers:
>> Column[0][0] Id: 0
>> Operator: =
>> Ordered nulls: false
>> Unknown return value: false
>> Negate comparison result: false
>> Column[0][1] Id: 1
>> Operator: =
>> Ordered nulls: false
>> Unknown return value: false
>> Negate comparison result: false
>> optimizer estimated row count: 0.00
>> optimizer estimated cost: 0.00
>>
>> Right result set:
>> Table Scan ResultSet for INGRESS_COS_QUEUE_CONFIG_BUNDLE at read committed isolation level using instantaneous share row locking chosen by the optimizer
>> Number of opens = 0
>> Rows seen = 0
>> Rows filtered = 0
>> Fetch Size = 16
>> constructor time (milliseconds) = 0
>> open time (milliseconds) = 0
>> next time (milliseconds) = 0
>> close time (milliseconds) = 0
>>
>> scan information:
>> start position:
>> null
>> stop position:
>> null
>> qualifiers:
>> Column[0][0] Id: 0
>> Operator: =
>> Ordered nulls: false
>> Unknown return value: false
>> Negate comparison result: false
>> optimizer estimated row count: 0.00
>> optimizer estimated cost: 0.00
>>
>> Right result set:
>> Table Scan ResultSet for CONFIGURATION_BUNDLE_9145E10G at read committed isolation level using instantaneous share row locking chosen by the optimizer
>> Number of opens = 0
>> Rows seen = 0
>> Rows filtered = 0
>> Fetch Size = 16
>> constructor time (milliseconds) = 0
>> open time (milliseconds) = 0
>> next time (milliseconds) = 0
>> close time (milliseconds) = 0
>>
>> scan information:
>> start position:
>> null
>> stop position:
>> null
>> qualifiers:
>> Column[0][0] Id: 0
>> Operator: =
>> Ordered nulls: false
>> Unknown return value: false
>> Negate comparison result: false
>> optimizer estimated row count: 0.00
>> optimizer estimated cost: 0.00
>>
>>
>>
>
>
>
>
>
>
>
>
>
RE: Why is the optimizer choosing such a bad path
Posted by "Bergquist, Brett" <BB...@canoga.com>.
I tried adding:
derby.storage.indexStats.debug.keepDisposableStats=true
to derby.properties *and* regenerating statistics for the tables. There is no change in the query plan.
Does this mean that applying the patches suggested will probably have no effect either?
-----Original Message-----
From: Bergquist, Brett [mailto:BBergquist@canoga.com]
Sent: Thursday, March 28, 2013 8:52 AM
To: derby-dev@db.apache.org
Subject: RE: Why is the optimizer choosing such a bad path
After dropping and recreating on index:
DROP INDEX CORE_V1.CONFIGURATION_BUNDLE_IX_1;
CREATE INDEX CONFIGURATION_BUNDLE_IX_1 ON "CORE_V1"."CONFIGURATION_BUNDLE"(DTYPE);
And rerunning the query, the optimizer chose that index and the optimizer row count estimates are no longer 0.
So it appears that there is something bad with that index that SYSCS_UTIL.SYSCS_CHECK_TABLE does not see and even SYSCS_UTIL.SYSCS_DROP_STATISTICS and SYSCS_UTIL.SYSCS_UPDATE_STATISTICS cannot fix.
Statement Name:
SQL_CURLH000C2
Statement Text:
SELECT t0.ID, t0.DTYPE, t0.BUNDLE_NAME, t0.OPLOCK, t1.ID, t2.ID, t2.LLQ_CONFIG_ENTRY_ID FROM CORE_V1.CONFIGURATIONSET_CONFIGURATIONBUNDLE t3, PKG_9145E10G.INGRESS_COS_QUEUE_CONFIG_BUNDLE t2, PKG_9145E10G.CONFIGURATION_BUNDLE_9145E10G t1, CORE_V1.CONFIGURATION_BUNDLE t0 WHERE (((t3.CONFIGURATIONSET_ID = 4000) AND (t0.ID = t3.CONFIGURATIONBUNDLE_ID)) AND (((t2.ID = t0.ID) AND (t1.ID = t0.ID)) AND (t0.DTYPE = 'INGRESS_COS_QUEUE_CONFIG_BUNDLE_9145E10G')))
Parse Time: 5
Bind Time: 9
Optimize Time: 133
Generate Time: 6
Compile Time: 153
Execute Time: 35
Begin Compilation Timestamp : 2013-03-28 08:44:40.901 End Compilation Timestamp : 2013-03-28 08:44:41.054 Begin Execution Timestamp : 2013-03-28 08:44:41.058 End Execution Timestamp : 2013-03-28 08:44:41.094 Statement Execution Plan Text:
Project-Restrict ResultSet (10):
Number of opens = 1
Rows seen = 0
Rows filtered = 0
restriction = false
projection = true
constructor time (milliseconds) = 0
open time (milliseconds) = 35
next time (milliseconds) = 0
close time (milliseconds) = 0
restriction time (milliseconds) = 0
projection time (milliseconds) = 0
optimizer estimated row count: 2.00
optimizer estimated cost: 51.52
Source result set:
Nested Loop Exists Join ResultSet:
Number of opens = 1
Rows seen from the left = 0
Rows seen from the right = 0
Rows filtered = 0
Rows returned = 0
constructor time (milliseconds) = 0
open time (milliseconds) = 35
next time (milliseconds) = 0
close time (milliseconds) = 1
optimizer estimated row count: 2.00
optimizer estimated cost: 51.52
Left result set:
Nested Loop Exists Join ResultSet:
Number of opens = 1
Rows seen from the left = 0
Rows seen from the right = 0
Rows filtered = 0
Rows returned = 0
constructor time (milliseconds) = 0
open time (milliseconds) = 35
next time (milliseconds) = 0
close time (milliseconds) = 1
optimizer estimated row count: 2.00
optimizer estimated cost: 37.18
Left result set:
Nested Loop Exists Join ResultSet:
Number of opens = 1
Rows seen from the left = 4
Rows seen from the right = 0
Rows filtered = 0
Rows returned = 0
constructor time (milliseconds) = 0
open time (milliseconds) = 1
next time (milliseconds) = 34
close time (milliseconds) = 1
optimizer estimated row count: 2.00
optimizer estimated cost: 27.75
Left result set:
Index Row to Base Row ResultSet for CONFIGURATION_BUNDLE:
Number of opens = 1
Rows seen = 4
Columns accessed from heap = {0, 1, 2, 3}
constructor time (milliseconds) = 1
open time (milliseconds) = 0
next time (milliseconds) = 0
close time (milliseconds) = 1
optimizer estimated row count: 2.00
optimizer estimated cost: 12.04
Index Scan ResultSet for CONFIGURATION_BUNDLE using index CONFIGURATION_BUNDLE_IX_1 at read committed isolation level using instantaneous share row locking chosen by the optimizer
Number of opens = 1
Rows seen = 4
Rows filtered = 0
Fetch Size = 16
constructor time (milliseconds) = 0
open time (milliseconds) = 1
next time (milliseconds) = 0
close time (milliseconds) = 1
next time in milliseconds/row = 0
scan information:
Bit set of columns fetched=All
Number of columns fetched=2
Number of deleted rows visited=0
Number of pages visited=4
Number of rows qualified=4
Number of rows visited=5
Scan type=btree
Tree height=4
start position:
>= on first 1 column(s).
Ordered null semantics on the following columns:
stop position:
> on first 1 column(s).
Ordered null semantics on the following columns:
qualifiers:
None
optimizer estimated row count: 2.00
optimizer estimated cost: 12.04
Right result set:
Index Scan ResultSet for CONFIGURATIONSET_CONFIGURATIONBUNDLE using constraint CONFIGURATIONSET_CONFIGURATIONBUNDLE_PK at read committed isolation level using share row locking chosen by the optimizer
Number of opens = 4
Rows seen = 0
Rows filtered = 0
Fetch Size = 1
constructor time (milliseconds) = 0
open time (milliseconds) = 1
next time (milliseconds) = 33
close time (milliseconds) = 1
scan information:
Bit set of columns fetched={0, 1}
Number of columns fetched=2
Number of deleted rows visited=0
Number of pages visited=20
Number of rows qualified=0
Number of rows visited=4
Scan type=btree
Tree height=5
start position:
>= on first 2 column(s).
Ordered null semantics on the following columns:
0 1
stop position:
> on first 2 column(s).
Ordered null semantics on the following columns:
0 1
qualifiers:
None
optimizer estimated row count: 2.00
optimizer estimated cost: 15.72
Right result set:
Index Scan ResultSet for CONFIGURATION_BUNDLE_9145E10G using constraint SQL100226025356610 at read committed isolation level using share row locking chosen by the optimizer
Number of opens = 0
Rows seen = 0
Rows filtered = 0
Fetch Size = 1
constructor time (milliseconds) = 0
open time (milliseconds) = 0
next time (milliseconds) = 0
close time (milliseconds) = 0
scan information:
start position:
Positioning information not available because this ResultSet was never opened.
stop position:
Positioning information not available because this ResultSet was never opened.
qualifiers:
Column[0][0] Id: 0
Operator: =
Ordered nulls: false
Unknown return value: false
Negate comparison result: false
optimizer estimated row count: 2.00
optimizer estimated cost: 9.43
Right result set:
Index Row to Base Row ResultSet for INGRESS_COS_QUEUE_CONFIG_BUNDLE:
Number of opens = 0
Rows seen = 0
Columns accessed from heap = {1}
constructor time (milliseconds) = 0
open time (milliseconds) = 0
next time (milliseconds) = 0
close time (milliseconds) = 0
optimizer estimated row count: 2.00
optimizer estimated cost: 14.34
Index Scan ResultSet for INGRESS_COS_QUEUE_CONFIG_BUNDLE using constraint SQL130327093437740 at read committed isolation level using share row locking chosen by the optimizer
Number of opens = 0
Rows seen = 0
Rows filtered = 0
Fetch Size = 1
constructor time (milliseconds) = 0
open time (milliseconds) = 0
next time (milliseconds) = 0
close time (milliseconds) = 0
scan information:
start position:
Positioning information not available because this ResultSet was never opened.
stop position:
Positioning information not available because this ResultSet was never opened.
qualifiers:
Column[0][0] Id: 0
Operator: =
Ordered nulls: false
Unknown return value: false
Negate comparison result: false
optimizer estimated row count: 2.00
optimizer estimated cost: 14.34
-----Original Message-----
From: Bergquist, Brett [mailto:BBergquist@canoga.com]
Sent: Thursday, March 28, 2013 8:33 AM
To: derby-dev@db.apache.org
Subject: RE: Why is the optimizer choosing such a bad path
Okay, I finally figured out that " CALL SYSCS_UTIL.SYSCS_SET_STATISTICS_TIMING(1);" is required. Now from the name which has "timing" in it, one (or at least I) would not think that this would affect the returning of the optimizer estimates. I guess I naively assumed this would affect the reporting of the compile and execution times. Maybe the documentation needs to be fixed here.
In any case, below is the query plan with this turned on. Note that optimizer is estimating a row count of 0 for the table with 64 million rows and does a table scan.
Statement Name:
SQL_CURLH000C1
Statement Text:
SELECT t0.ID, t0.DTYPE, t0.BUNDLE_NAME, t0.OPLOCK, t1.ID, t2.ID, t2.LLQ_CONFIG_ENTRY_ID FROM CORE_V1.CONFIGURATIONSET_CONFIGURATIONBUNDLE t3, PKG_9145E10G.INGRESS_COS_QUEUE_CONFIG_BUNDLE t2, PKG_9145E10G.CONFIGURATION_BUNDLE_9145E10G t1, CORE_V1.CONFIGURATION_BUNDLE t0 WHERE (((t3.CONFIGURATIONSET_ID = 4000) AND (t0.ID = t3.CONFIGURATIONBUNDLE_ID)) AND (((t2.ID = t0.ID) AND (t1.ID = t0.ID)) AND (t0.DTYPE = 'INGRESS_COS_QUEUE_CONFIG_BUNDLE_9145E10G')))
Parse Time: 8
Bind Time: 66
Optimize Time: 3935
Generate Time: 7
Compile Time: 4016
Execute Time: 220556
Begin Compilation Timestamp : 2013-03-28 08:27:13.028 End Compilation Timestamp : 2013-03-28 08:27:17.044 Begin Execution Timestamp : 2013-03-28 08:27:17.053 End Execution Timestamp : 2013-03-28 08:30:57.615 Statement Execution Plan Text:
Project-Restrict ResultSet (9):
Number of opens = 1
Rows seen = 0
Rows filtered = 0
restriction = false
projection = true
constructor time (milliseconds) = 0
open time (milliseconds) = 220556
next time (milliseconds) = 0
close time (milliseconds) = 0
restriction time (milliseconds) = 0
projection time (milliseconds) = 0
optimizer estimated row count: 0.00
optimizer estimated cost: 8.05
Source result set:
Nested Loop Join ResultSet:
Number of opens = 1
Rows seen from the left = 0
Rows seen from the right = 0
Rows filtered = 0
Rows returned = 0
constructor time (milliseconds) = 0
open time (milliseconds) = 220556
next time (milliseconds) = 0
close time (milliseconds) = 6
optimizer estimated row count: 0.00
optimizer estimated cost: 8.05
Left result set:
Nested Loop Join ResultSet:
Number of opens = 1
Rows seen from the left = 0
Rows seen from the right = 0
Rows filtered = 0
Rows returned = 0
constructor time (milliseconds) = 0
open time (milliseconds) = 220556
next time (milliseconds) = 0
close time (milliseconds) = 6
optimizer estimated row count: 0.00
optimizer estimated cost: 8.05
Left result set:
Nested Loop Join ResultSet:
Number of opens = 1
Rows seen from the left = 4
Rows seen from the right = 0
Rows filtered = 0
Rows returned = 0
constructor time (milliseconds) = 0
open time (milliseconds) = 63
next time (milliseconds) = 220493
close time (milliseconds) = 6
optimizer estimated row count: 0.00
optimizer estimated cost: 8.05
Left result set:
Index Row to Base Row ResultSet for CONFIGURATION_BUNDLE:
Number of opens = 1
Rows seen = 4
Columns accessed from heap = {0, 1, 2, 3}
constructor time (milliseconds) = 0
open time (milliseconds) = 0
next time (milliseconds) = 64
close time (milliseconds) = 6
optimizer estimated row count: 0.00
optimizer estimated cost: 8.05
Index Scan ResultSet for CONFIGURATION_BUNDLE using index CONFIGURATION_BUNDLE_IX_1 at read committed isolation level using instantaneous share row locking chosen by the optimizer
Number of opens = 1
Rows seen = 4
Rows filtered = 0
Fetch Size = 16
constructor time (milliseconds) = 0
open time (milliseconds) = 2
next time (milliseconds) = 1
close time (milliseconds) = 6
next time in milliseconds/row = 0
scan information:
Bit set of columns fetched=All
Number of columns fetched=2
Number of deleted rows visited=0
Number of pages visited=5
Number of rows qualified=4
Number of rows visited=5
Scan type=btree
Tree height=5
start position:
>= on first 1 column(s).
Ordered null semantics on the following columns:
stop position:
> on first 1 column(s).
Ordered null semantics on the following columns:
qualifiers:
None
optimizer estimated row count: 0.00
optimizer estimated cost: 8.05
Right result set:
Table Scan ResultSet for CONFIGURATIONSET_CONFIGURATIONBUNDLE at read committed isolation level using instantaneous share row locking chosen by the optimizer
Number of opens = 4
Rows seen = 0
Rows filtered = 0
Fetch Size = 16
constructor time (milliseconds) = 0
open time (milliseconds) = 64
next time (milliseconds) = 0
close time (milliseconds) = 11
scan information:
Bit set of columns fetched=All
Number of columns fetched=2
Number of pages visited=670832
Number of rows qualified=0
Number of rows visited=262428000
Scan type=heap
start position:
null
stop position:
null
qualifiers:
Column[0][0] Id: 0
Operator: =
Ordered nulls: false
Unknown return value: false
Negate comparison result: false
Column[0][1] Id: 1
Operator: =
Ordered nulls: false
Unknown return value: false
Negate comparison result: false
optimizer estimated row count: 0.00
optimizer estimated cost: 0.00
Right result set:
Table Scan ResultSet for INGRESS_COS_QUEUE_CONFIG_BUNDLE at read committed isolation level using instantaneous share row locking chosen by the optimizer
Number of opens = 0
Rows seen = 0
Rows filtered = 0
Fetch Size = 16
constructor time (milliseconds) = 0
open time (milliseconds) = 0
next time (milliseconds) = 0
close time (milliseconds) = 0
scan information:
start position:
null
stop position:
null
qualifiers:
Column[0][0] Id: 0
Operator: =
Ordered nulls: false
Unknown return value: false
Negate comparison result: false
optimizer estimated row count: 0.00
optimizer estimated cost: 0.00
Right result set:
Table Scan ResultSet for CONFIGURATION_BUNDLE_9145E10G at read committed isolation level using instantaneous share row locking chosen by the optimizer
Number of opens = 0
Rows seen = 0
Rows filtered = 0
Fetch Size = 16
constructor time (milliseconds) = 0
open time (milliseconds) = 0
next time (milliseconds) = 0
close time (milliseconds) = 0
scan information:
start position:
null
stop position:
null
qualifiers:
Column[0][0] Id: 0
Operator: =
Ordered nulls: false
Unknown return value: false
Negate comparison result: false
optimizer estimated row count: 0.00
optimizer estimated cost: 0.00
-----Original Message-----
From: Bergquist, Brett [mailto:BBergquist@canoga.com]
Sent: Wednesday, March 27, 2013 8:42 PM
To: derby-dev@db.apache.org
Subject: RE: Why is the optimizer choosing such a bad path
I am able to build Derby so I can try a patch. On DERBY-6045, there are two attached patches. Two questions:
1. Are the patches against the trunk or can they be applied to 10.9.1.0 (I already have been building the equivalent of that release anyways myself).
2. Apply both patches?
________________________________________
From: Mike Matrigali [mikem_app@sbcglobal.net]
Sent: Wednesday, March 27, 2013 6:22 PM
To: derby-dev@db.apache.org
Subject: Re: Why is the optimizer choosing such a bad path
I would suggest seeing if this is related to DERBY-6045 or not. I
don't think this query goes through the in-list path but I am not sure, so if you are set up you could apply the patch and see if it makes a difference.
There is a patch available and I believe it will be going into trunk soon.
I have been waiting for that patch to go in, and then look to see if the underlying problem exists in other parts of the code. The problem is that we changed update statistics to not create a statistic on a unique single column index, and that the code above then did not do the right thing when that stat did not exist. To see if you are running into a similar problem you can use the workaround that Kristian suggested in that issue:
I think specifying
derby.storage.indexStats.debug.keepDisposableStats=true *and* regenerating statistics for the relevant tables will suffice as a work-around for this issue.
Given that we agree the statistics for single-column unique indexes aren't needed, do we know what puts off the optimizer?
The lack of statistics, or stale row estimates?
(I don't have time to dig into that, and I don't know what the optimizer does in this case.)
If you set the property on your db and rerun all the statistics and see a different result then it will point to another place in the code that needs to change to handle a stat not existing in the catalog.
On 3/27/2013 12:16 PM, Bergquist, Brett wrote:
> Some background.
>
> I have a customer that is using an earlier release of our system that has
> Derby 10.8.2.1 installed. Because of issues like
> https://issues.apache.org/jira/browse/DERBY-5680,
> it has been running with the indexStat daemon disabled.
>
> We are going to have a new release soon and it will be installing Derby 10.9.1.0 with the indexStat
> daemon enabled. I recently got a copy of the customer's database (132Gb) and ran into
> a very long query. I manually ran SYS_UTIL.SYSCS_UPDATE_STATISTICS on all of the tables
> in the query to ensure that the statistics are up to date.
>
> The tables in the query look like:
>
> // 62,908,433 Rows
> CREATE TABLE "CORE_V1"."CONFIGURATIONSET_CONFIGURATIONBUNDLE"
> (
> CONFIGURATIONBUNDLE_ID int NOT NULL,
> CONFIGURATIONSET_ID int NOT NULL,
> CONSTRAINT CONFIGURATIONSET_CONFIGURATIONBUNDLE_PK PRIMARY KEY
> (CONFIGURATIONBUNDLE_ID,CONFIGURATIONSET_ID)
> );
> ALTER TABLE "CORE_V1"."CONFIGURATIONSET_CONFIGURATIONBUNDLE"
> ADD CONSTRAINT CONFIGURATIONSET_CONFIGURATIONBUNDLE_FK_2
> FOREIGN KEY (CONFIGURATIONSET_ID)
> REFERENCES "CORE_V1"."CONFIGURATION_SET"(ID);
> ALTER TABLE "CORE_V1"."CONFIGURATIONSET_CONFIGURATIONBUNDLE"
> ADD CONSTRAINT CONFIGURATIONSET_CONFIGURATIONBUNDLE_FK_1
> FOREIGN KEY (CONFIGURATIONBUNDLE_ID)
> REFERENCES "CORE_V1"."CONFIGURATION_BUNDLE"(ID);
> CREATE INDEX SQL100922214558160 ON
> "CORE_V1"."CONFIGURATIONSET_CONFIGURATIONBUNDLE"(CONFIGURATIONSET_ID);
> CREATE INDEX SQL100922215312050 ON
> "CORE_V1"."CONFIGURATIONSET_CONFIGURATIONBUNDLE"(CONFIGURATIONBUNDLE_I
> D); CREATE UNIQUE INDEX SQL081029110254290 ON
> "CORE_V1"."CONFIGURATIONSET_CONFIGURATIONBUNDLE"
> (
> CONFIGURATIONBUNDLE_ID,
> CONFIGURATIONSET_ID
> );
>
> // 4 Rows
> CREATE TABLE "PKG_9145E10G"."INGRESS_COS_QUEUE_CONFIG_BUNDLE"
> (
> ID int PRIMARY KEY NOT NULL,
> LLQ_CONFIG_ENTRY_ID int NOT NULL
> );
> ALTER TABLE "PKG_9145E10G"."INGRESS_COS_QUEUE_CONFIG_BUNDLE"
> ADD CONSTRAINT INGRESS_COS_QUEUE_CONFIG_BUNDLE_FK_2
> FOREIGN KEY (LLQ_CONFIG_ENTRY_ID)
> REFERENCES "PKG_9145E10G"."INGRESS_COS_QUEUE_CONFIG_ENTRY"(ID);
> ALTER TABLE "PKG_9145E10G"."INGRESS_COS_QUEUE_CONFIG_BUNDLE"
> ADD CONSTRAINT INGRESS_COS_QUEUE_CONFIG_BUNDLE_FK_1
> FOREIGN KEY (ID)
> REFERENCES "CORE_V1"."CONFIGURATION_BUNDLE"(ID);
> CREATE INDEX SQL130327093508050 ON
> "PKG_9145E10G"."INGRESS_COS_QUEUE_CONFIG_BUNDLE"(ID);
> CREATE INDEX SQL130327093508060 ON
> "PKG_9145E10G"."INGRESS_COS_QUEUE_CONFIG_BUNDLE"(LLQ_CONFIG_ENTRY_ID);
> CREATE UNIQUE INDEX SQL130327093437740 ON
> "PKG_9145E10G"."INGRESS_COS_QUEUE_CONFIG_BUNDLE"(ID);
>
> // 197,363 Rows
> CREATE TABLE "PKG_9145E10G"."CONFIGURATION_BUNDLE_9145E10G"
> (
> ID int PRIMARY KEY NOT NULL
> );
> ALTER TABLE "PKG_9145E10G"."CONFIGURATION_BUNDLE_9145E10G"
> ADD CONSTRAINT CONFIGURATION_BUNDLE_9145E10G_FK_1
> FOREIGN KEY (ID)
> REFERENCES "CORE_V1"."CONFIGURATION_BUNDLE"(ID);
> CREATE UNIQUE INDEX SQL100226025356610 ON
> "PKG_9145E10G"."CONFIGURATION_BUNDLE_9145E10G"(ID);
> CREATE INDEX SQL100922215631540 ON
> "PKG_9145E10G"."CONFIGURATION_BUNDLE_9145E10G"(ID);
>
> // 6,740,327 Rows
> CREATE TABLE "CORE_V1"."CONFIGURATION_BUNDLE"
> (
> DTYPE varchar(64),
> OPLOCK int DEFAULT 0 NOT NULL,
> BUNDLE_NAME varchar(64) NOT NULL,
> ID int PRIMARY KEY NOT NULL
> );
> CREATE INDEX CONFIGURATION_BUNDLE_IX_2 ON
> "CORE_V1"."CONFIGURATION_BUNDLE"(BUNDLE_NAME);
> CREATE INDEX CONFIGURATION_BUNDLE_IX_1 ON
> "CORE_V1"."CONFIGURATION_BUNDLE"(DTYPE);
> CREATE UNIQUE INDEX SQL100922215131580 ON
> "CORE_V1"."CONFIGURATION_BUNDLE"(ID);
>
>
> For some reason, the optimizer is doing a table scan across the
> CORE_V1.CONFIGURATIONSET_CONFIGURATIONBUNDLE table which has 64 million rows and it even goes across this 4 times!.
>
> One issue is that this query is generated by Eclipselink (JPA) and I have no control on the query generation.
>
> So any ideas on why it would chose this path and what I might be able to do about it? In playing
> around and trying to find the issue, I notice that if I remove the
>
> t0.DTYPE = 'INGRESS_COS_QUEUE_CONFIG_BUNDLE_9145E10G')
>
> constraint, then the query returns 0 rows (it should even with this constraint as there are no rows
> that are acceptable) and returns them in about .05 seconds. Note CORE_V1.CONFIGURATION_BUNDLE does
> have a non-unique index on DTYPE.
>
> Ok, just on a whim, I removed the index on DTYPE and the query came
> back .06 seconds. That column is used by Eclipselink in determining which of a "derived" object to return so I don't have much control on it.
>
> ----
> Statement Name:
> SQL_CURLH000C1
> Statement Text:
> SELECT t0.ID, t0.DTYPE, t0.BUNDLE_NAME, t0.OPLOCK, t1.ID, t2.ID,
> t2.LLQ_CONFIG_ENTRY_ID FROM
> CORE_V1.CONFIGURATIONSET_CONFIGURATIONBUNDLE t3,
> PKG_9145E10G.INGRESS_COS_QUEUE_CONFIG_BUNDLE t2,
> PKG_9145E10G.CONFIGURATION_BUNDLE_9145E10G t1,
> CORE_V1.CONFIGURATION_BUNDLE t0 WHERE (((t3.CONFIGURATIONSET_ID =
> 4000) AND (t0.ID = t3.CONFIGURATIONBUNDLE_ID)) AND (((t2.ID = t0.ID)
> AND (t1.ID = t0.ID)) AND (t0.DTYPE =
> 'INGRESS_COS_QUEUE_CONFIG_BUNDLE_9145E10G')))
> Parse Time: 0
> Bind Time: 0
> Optimize Time: 0
> Generate Time: 0
> Compile Time: 0
> Execute Time: 0
> Begin Compilation Timestamp : null
> End Compilation Timestamp : null
> Begin Execution Timestamp : null
> End Execution Timestamp : null
> Statement Execution Plan Text:
> Project-Restrict ResultSet (9):
> Number of opens = 1
> Rows seen = 0
> Rows filtered = 0
> restriction = false
> projection = true
> constructor time (milliseconds) = 0
> open time (milliseconds) = 0
> next time (milliseconds) = 0
> close time (milliseconds) = 0
> restriction time (milliseconds) = 0
> projection time (milliseconds) = 0
> optimizer estimated row count: 0.00
> optimizer estimated cost: 8.05
> Source result set:
> Nested Loop Join ResultSet:
> Number of opens = 1
> Rows seen from the left = 0
> Rows seen from the right = 0
> Rows filtered = 0
> Rows returned = 0
> constructor time (milliseconds) = 0
> open time (milliseconds) = 0
> next time (milliseconds) = 0
> close time (milliseconds) = 0
> optimizer estimated row count: 0.00
> optimizer estimated cost: 8.05
> Left result set:
> Nested Loop Join ResultSet:
> Number of opens = 1
> Rows seen from the left = 0
> Rows seen from the right = 0
> Rows filtered = 0
> Rows returned = 0
> constructor time (milliseconds) = 0
> open time (milliseconds) = 0
> next time (milliseconds) = 0
> close time (milliseconds) = 0
> optimizer estimated row count: 0.00
> optimizer estimated cost: 8.05
> Left result set:
> Nested Loop Join ResultSet:
> Number of opens = 1
> Rows seen from the left = 4
> Rows seen from the right = 0
> Rows filtered = 0
> Rows returned = 0
> constructor time (milliseconds) = 0
> open time (milliseconds) = 0
> next time (milliseconds) = 0
> close time (milliseconds) = 0
> optimizer estimated row count: 0.00
> optimizer estimated cost: 8.05
> Left result set:
> Index Row to Base Row ResultSet for CONFIGURATION_BUNDLE:
> Number of opens = 1
> Rows seen = 4
> Columns accessed from heap = {0, 1, 2, 3}
> constructor time (milliseconds) = 0
> open time (milliseconds) = 0
> next time (milliseconds) = 0
> close time (milliseconds) = 0
> optimizer estimated row count: 0.00
> optimizer estimated cost: 8.05
> Index Scan ResultSet for CONFIGURATION_BUNDLE using index CONFIGURATION_BUNDLE_IX_1 at read committed isolation level using instantaneous share row locking chosen by the optimizer
> Number of opens = 1
> Rows seen = 4
> Rows filtered = 0
> Fetch Size = 16
> constructor time (milliseconds) = 0
> open time (milliseconds) = 0
> next time (milliseconds) = 0
> close time (milliseconds) = 0
> next time in
> milliseconds/row = 0
>
> scan information:
> Bit set of columns fetched=All
> Number of columns fetched=2
> Number of deleted rows visited=0
> Number of pages visited=5
> Number of rows qualified=4
> Number of rows visited=5
> Scan type=btree
> Tree height=5
> start position:
> >= on first 1 column(s).
> Ordered null semantics on the following columns:
> stop position:
> > on first 1 column(s).
> Ordered null semantics on the following columns:
> qualifiers:
> None
> optimizer estimated row count: 0.00
> optimizer estimated
> cost: 8.05
>
> Right result set:
> Table Scan ResultSet for CONFIGURATIONSET_CONFIGURATIONBUNDLE at read committed isolation level using instantaneous share row locking chosen by the optimizer
> Number of opens = 4
> Rows seen = 0
> Rows filtered = 0
> Fetch Size = 16
> constructor time (milliseconds) = 0
> open time (milliseconds) = 0
> next time (milliseconds) = 0
> close time (milliseconds) = 0
>
> scan information:
> Bit set of columns fetched=All
> Number of columns fetched=2
> Number of pages visited=670838
> Number of rows qualified=0
> Number of rows visited=262429876
> Scan type=heap
> start position:
> null
> stop position:
> null
> qualifiers:
> Column[0][0] Id: 0
> Operator: =
> Ordered nulls: false
> Unknown return value: false
> Negate comparison result: false
> Column[0][1] Id: 1
> Operator: =
> Ordered nulls: false
> Unknown return value: false
> Negate comparison result: false
> optimizer estimated row count: 0.00
> optimizer estimated cost: 0.00
>
> Right result set:
> Table Scan ResultSet for INGRESS_COS_QUEUE_CONFIG_BUNDLE at read committed isolation level using instantaneous share row locking chosen by the optimizer
> Number of opens = 0
> Rows seen = 0
> Rows filtered = 0
> Fetch Size = 16
> constructor time (milliseconds) = 0
> open time (milliseconds) = 0
> next time (milliseconds) = 0
> close time (milliseconds) = 0
>
> scan information:
> start position:
> null
> stop position:
> null
> qualifiers:
> Column[0][0] Id: 0
> Operator: =
> Ordered nulls: false
> Unknown return value: false
> Negate comparison result: false
> optimizer estimated row count: 0.00
> optimizer estimated cost: 0.00
>
> Right result set:
> Table Scan ResultSet for CONFIGURATION_BUNDLE_9145E10G at read committed isolation level using instantaneous share row locking chosen by the optimizer
> Number of opens = 0
> Rows seen = 0
> Rows filtered = 0
> Fetch Size = 16
> constructor time (milliseconds) = 0
> open time (milliseconds) = 0
> next time (milliseconds) = 0
> close time (milliseconds) = 0
>
> scan information:
> start position:
> null
> stop position:
> null
> qualifiers:
> Column[0][0] Id: 0
> Operator: =
> Ordered nulls: false
> Unknown return value: false
> Negate comparison result: false
> optimizer estimated row count: 0.00
> optimizer estimated cost: 0.00
>
>
>
RE: Why is the optimizer choosing such a bad path
Posted by "Bergquist, Brett" <BB...@canoga.com>.
After dropping and recreating on index:
DROP INDEX CORE_V1.CONFIGURATION_BUNDLE_IX_1;
CREATE INDEX CONFIGURATION_BUNDLE_IX_1 ON "CORE_V1"."CONFIGURATION_BUNDLE"(DTYPE);
And rerunning the query, the optimizer chose that index and the optimizer row count estimates are no longer 0.
So it appears that there is something bad with that index that SYSCS_UTIL.SYSCS_CHECK_TABLE does not see and even SYSCS_UTIL.SYSCS_DROP_STATISTICS and SYSCS_UTIL.SYSCS_UPDATE_STATISTICS cannot fix.
Statement Name:
SQL_CURLH000C2
Statement Text:
SELECT t0.ID, t0.DTYPE, t0.BUNDLE_NAME, t0.OPLOCK, t1.ID, t2.ID, t2.LLQ_CONFIG_ENTRY_ID FROM CORE_V1.CONFIGURATIONSET_CONFIGURATIONBUNDLE t3, PKG_9145E10G.INGRESS_COS_QUEUE_CONFIG_BUNDLE t2, PKG_9145E10G.CONFIGURATION_BUNDLE_9145E10G t1, CORE_V1.CONFIGURATION_BUNDLE t0 WHERE (((t3.CONFIGURATIONSET_ID = 4000) AND (t0.ID = t3.CONFIGURATIONBUNDLE_ID)) AND (((t2.ID = t0.ID) AND (t1.ID = t0.ID)) AND (t0.DTYPE = 'INGRESS_COS_QUEUE_CONFIG_BUNDLE_9145E10G')))
Parse Time: 5
Bind Time: 9
Optimize Time: 133
Generate Time: 6
Compile Time: 153
Execute Time: 35
Begin Compilation Timestamp : 2013-03-28 08:44:40.901
End Compilation Timestamp : 2013-03-28 08:44:41.054
Begin Execution Timestamp : 2013-03-28 08:44:41.058
End Execution Timestamp : 2013-03-28 08:44:41.094
Statement Execution Plan Text:
Project-Restrict ResultSet (10):
Number of opens = 1
Rows seen = 0
Rows filtered = 0
restriction = false
projection = true
constructor time (milliseconds) = 0
open time (milliseconds) = 35
next time (milliseconds) = 0
close time (milliseconds) = 0
restriction time (milliseconds) = 0
projection time (milliseconds) = 0
optimizer estimated row count: 2.00
optimizer estimated cost: 51.52
Source result set:
Nested Loop Exists Join ResultSet:
Number of opens = 1
Rows seen from the left = 0
Rows seen from the right = 0
Rows filtered = 0
Rows returned = 0
constructor time (milliseconds) = 0
open time (milliseconds) = 35
next time (milliseconds) = 0
close time (milliseconds) = 1
optimizer estimated row count: 2.00
optimizer estimated cost: 51.52
Left result set:
Nested Loop Exists Join ResultSet:
Number of opens = 1
Rows seen from the left = 0
Rows seen from the right = 0
Rows filtered = 0
Rows returned = 0
constructor time (milliseconds) = 0
open time (milliseconds) = 35
next time (milliseconds) = 0
close time (milliseconds) = 1
optimizer estimated row count: 2.00
optimizer estimated cost: 37.18
Left result set:
Nested Loop Exists Join ResultSet:
Number of opens = 1
Rows seen from the left = 4
Rows seen from the right = 0
Rows filtered = 0
Rows returned = 0
constructor time (milliseconds) = 0
open time (milliseconds) = 1
next time (milliseconds) = 34
close time (milliseconds) = 1
optimizer estimated row count: 2.00
optimizer estimated cost: 27.75
Left result set:
Index Row to Base Row ResultSet for CONFIGURATION_BUNDLE:
Number of opens = 1
Rows seen = 4
Columns accessed from heap = {0, 1, 2, 3}
constructor time (milliseconds) = 1
open time (milliseconds) = 0
next time (milliseconds) = 0
close time (milliseconds) = 1
optimizer estimated row count: 2.00
optimizer estimated cost: 12.04
Index Scan ResultSet for CONFIGURATION_BUNDLE using index CONFIGURATION_BUNDLE_IX_1 at read committed isolation level using instantaneous share row locking chosen by the optimizer
Number of opens = 1
Rows seen = 4
Rows filtered = 0
Fetch Size = 16
constructor time (milliseconds) = 0
open time (milliseconds) = 1
next time (milliseconds) = 0
close time (milliseconds) = 1
next time in milliseconds/row = 0
scan information:
Bit set of columns fetched=All
Number of columns fetched=2
Number of deleted rows visited=0
Number of pages visited=4
Number of rows qualified=4
Number of rows visited=5
Scan type=btree
Tree height=4
start position:
>= on first 1 column(s).
Ordered null semantics on the following columns:
stop position:
> on first 1 column(s).
Ordered null semantics on the following columns:
qualifiers:
None
optimizer estimated row count: 2.00
optimizer estimated cost: 12.04
Right result set:
Index Scan ResultSet for CONFIGURATIONSET_CONFIGURATIONBUNDLE using constraint CONFIGURATIONSET_CONFIGURATIONBUNDLE_PK at read committed isolation level using share row locking chosen by the optimizer
Number of opens = 4
Rows seen = 0
Rows filtered = 0
Fetch Size = 1
constructor time (milliseconds) = 0
open time (milliseconds) = 1
next time (milliseconds) = 33
close time (milliseconds) = 1
scan information:
Bit set of columns fetched={0, 1}
Number of columns fetched=2
Number of deleted rows visited=0
Number of pages visited=20
Number of rows qualified=0
Number of rows visited=4
Scan type=btree
Tree height=5
start position:
>= on first 2 column(s).
Ordered null semantics on the following columns:
0 1
stop position:
> on first 2 column(s).
Ordered null semantics on the following columns:
0 1
qualifiers:
None
optimizer estimated row count: 2.00
optimizer estimated cost: 15.72
Right result set:
Index Scan ResultSet for CONFIGURATION_BUNDLE_9145E10G using constraint SQL100226025356610 at read committed isolation level using share row locking chosen by the optimizer
Number of opens = 0
Rows seen = 0
Rows filtered = 0
Fetch Size = 1
constructor time (milliseconds) = 0
open time (milliseconds) = 0
next time (milliseconds) = 0
close time (milliseconds) = 0
scan information:
start position:
Positioning information not available because this ResultSet was never opened.
stop position:
Positioning information not available because this ResultSet was never opened.
qualifiers:
Column[0][0] Id: 0
Operator: =
Ordered nulls: false
Unknown return value: false
Negate comparison result: false
optimizer estimated row count: 2.00
optimizer estimated cost: 9.43
Right result set:
Index Row to Base Row ResultSet for INGRESS_COS_QUEUE_CONFIG_BUNDLE:
Number of opens = 0
Rows seen = 0
Columns accessed from heap = {1}
constructor time (milliseconds) = 0
open time (milliseconds) = 0
next time (milliseconds) = 0
close time (milliseconds) = 0
optimizer estimated row count: 2.00
optimizer estimated cost: 14.34
Index Scan ResultSet for INGRESS_COS_QUEUE_CONFIG_BUNDLE using constraint SQL130327093437740 at read committed isolation level using share row locking chosen by the optimizer
Number of opens = 0
Rows seen = 0
Rows filtered = 0
Fetch Size = 1
constructor time (milliseconds) = 0
open time (milliseconds) = 0
next time (milliseconds) = 0
close time (milliseconds) = 0
scan information:
start position:
Positioning information not available because this ResultSet was never opened.
stop position:
Positioning information not available because this ResultSet was never opened.
qualifiers:
Column[0][0] Id: 0
Operator: =
Ordered nulls: false
Unknown return value: false
Negate comparison result: false
optimizer estimated row count: 2.00
optimizer estimated cost: 14.34
-----Original Message-----
From: Bergquist, Brett [mailto:BBergquist@canoga.com]
Sent: Thursday, March 28, 2013 8:33 AM
To: derby-dev@db.apache.org
Subject: RE: Why is the optimizer choosing such a bad path
Okay, I finally figured out that " CALL SYSCS_UTIL.SYSCS_SET_STATISTICS_TIMING(1);" is required. Now from the name which has "timing" in it, one (or at least I) would not think that this would affect the returning of the optimizer estimates. I guess I naively assumed this would affect the reporting of the compile and execution times. Maybe the documentation needs to be fixed here.
In any case, below is the query plan with this turned on. Note that optimizer is estimating a row count of 0 for the table with 64 million rows and does a table scan.
Statement Name:
SQL_CURLH000C1
Statement Text:
SELECT t0.ID, t0.DTYPE, t0.BUNDLE_NAME, t0.OPLOCK, t1.ID, t2.ID, t2.LLQ_CONFIG_ENTRY_ID FROM CORE_V1.CONFIGURATIONSET_CONFIGURATIONBUNDLE t3, PKG_9145E10G.INGRESS_COS_QUEUE_CONFIG_BUNDLE t2, PKG_9145E10G.CONFIGURATION_BUNDLE_9145E10G t1, CORE_V1.CONFIGURATION_BUNDLE t0 WHERE (((t3.CONFIGURATIONSET_ID = 4000) AND (t0.ID = t3.CONFIGURATIONBUNDLE_ID)) AND (((t2.ID = t0.ID) AND (t1.ID = t0.ID)) AND (t0.DTYPE = 'INGRESS_COS_QUEUE_CONFIG_BUNDLE_9145E10G')))
Parse Time: 8
Bind Time: 66
Optimize Time: 3935
Generate Time: 7
Compile Time: 4016
Execute Time: 220556
Begin Compilation Timestamp : 2013-03-28 08:27:13.028 End Compilation Timestamp : 2013-03-28 08:27:17.044 Begin Execution Timestamp : 2013-03-28 08:27:17.053 End Execution Timestamp : 2013-03-28 08:30:57.615 Statement Execution Plan Text:
Project-Restrict ResultSet (9):
Number of opens = 1
Rows seen = 0
Rows filtered = 0
restriction = false
projection = true
constructor time (milliseconds) = 0
open time (milliseconds) = 220556
next time (milliseconds) = 0
close time (milliseconds) = 0
restriction time (milliseconds) = 0
projection time (milliseconds) = 0
optimizer estimated row count: 0.00
optimizer estimated cost: 8.05
Source result set:
Nested Loop Join ResultSet:
Number of opens = 1
Rows seen from the left = 0
Rows seen from the right = 0
Rows filtered = 0
Rows returned = 0
constructor time (milliseconds) = 0
open time (milliseconds) = 220556
next time (milliseconds) = 0
close time (milliseconds) = 6
optimizer estimated row count: 0.00
optimizer estimated cost: 8.05
Left result set:
Nested Loop Join ResultSet:
Number of opens = 1
Rows seen from the left = 0
Rows seen from the right = 0
Rows filtered = 0
Rows returned = 0
constructor time (milliseconds) = 0
open time (milliseconds) = 220556
next time (milliseconds) = 0
close time (milliseconds) = 6
optimizer estimated row count: 0.00
optimizer estimated cost: 8.05
Left result set:
Nested Loop Join ResultSet:
Number of opens = 1
Rows seen from the left = 4
Rows seen from the right = 0
Rows filtered = 0
Rows returned = 0
constructor time (milliseconds) = 0
open time (milliseconds) = 63
next time (milliseconds) = 220493
close time (milliseconds) = 6
optimizer estimated row count: 0.00
optimizer estimated cost: 8.05
Left result set:
Index Row to Base Row ResultSet for CONFIGURATION_BUNDLE:
Number of opens = 1
Rows seen = 4
Columns accessed from heap = {0, 1, 2, 3}
constructor time (milliseconds) = 0
open time (milliseconds) = 0
next time (milliseconds) = 64
close time (milliseconds) = 6
optimizer estimated row count: 0.00
optimizer estimated cost: 8.05
Index Scan ResultSet for CONFIGURATION_BUNDLE using index CONFIGURATION_BUNDLE_IX_1 at read committed isolation level using instantaneous share row locking chosen by the optimizer
Number of opens = 1
Rows seen = 4
Rows filtered = 0
Fetch Size = 16
constructor time (milliseconds) = 0
open time (milliseconds) = 2
next time (milliseconds) = 1
close time (milliseconds) = 6
next time in milliseconds/row = 0
scan information:
Bit set of columns fetched=All
Number of columns fetched=2
Number of deleted rows visited=0
Number of pages visited=5
Number of rows qualified=4
Number of rows visited=5
Scan type=btree
Tree height=5
start position:
>= on first 1 column(s).
Ordered null semantics on the following columns:
stop position:
> on first 1 column(s).
Ordered null semantics on the following columns:
qualifiers:
None
optimizer estimated row count: 0.00
optimizer estimated cost: 8.05
Right result set:
Table Scan ResultSet for CONFIGURATIONSET_CONFIGURATIONBUNDLE at read committed isolation level using instantaneous share row locking chosen by the optimizer
Number of opens = 4
Rows seen = 0
Rows filtered = 0
Fetch Size = 16
constructor time (milliseconds) = 0
open time (milliseconds) = 64
next time (milliseconds) = 0
close time (milliseconds) = 11
scan information:
Bit set of columns fetched=All
Number of columns fetched=2
Number of pages visited=670832
Number of rows qualified=0
Number of rows visited=262428000
Scan type=heap
start position:
null
stop position:
null
qualifiers:
Column[0][0] Id: 0
Operator: =
Ordered nulls: false
Unknown return value: false
Negate comparison result: false
Column[0][1] Id: 1
Operator: =
Ordered nulls: false
Unknown return value: false
Negate comparison result: false
optimizer estimated row count: 0.00
optimizer estimated cost: 0.00
Right result set:
Table Scan ResultSet for INGRESS_COS_QUEUE_CONFIG_BUNDLE at read committed isolation level using instantaneous share row locking chosen by the optimizer
Number of opens = 0
Rows seen = 0
Rows filtered = 0
Fetch Size = 16
constructor time (milliseconds) = 0
open time (milliseconds) = 0
next time (milliseconds) = 0
close time (milliseconds) = 0
scan information:
start position:
null
stop position:
null
qualifiers:
Column[0][0] Id: 0
Operator: =
Ordered nulls: false
Unknown return value: false
Negate comparison result: false
optimizer estimated row count: 0.00
optimizer estimated cost: 0.00
Right result set:
Table Scan ResultSet for CONFIGURATION_BUNDLE_9145E10G at read committed isolation level using instantaneous share row locking chosen by the optimizer
Number of opens = 0
Rows seen = 0
Rows filtered = 0
Fetch Size = 16
constructor time (milliseconds) = 0
open time (milliseconds) = 0
next time (milliseconds) = 0
close time (milliseconds) = 0
scan information:
start position:
null
stop position:
null
qualifiers:
Column[0][0] Id: 0
Operator: =
Ordered nulls: false
Unknown return value: false
Negate comparison result: false
optimizer estimated row count: 0.00
optimizer estimated cost: 0.00
-----Original Message-----
From: Bergquist, Brett [mailto:BBergquist@canoga.com]
Sent: Wednesday, March 27, 2013 8:42 PM
To: derby-dev@db.apache.org
Subject: RE: Why is the optimizer choosing such a bad path
I am able to build Derby so I can try a patch. On DERBY-6045, there are two attached patches. Two questions:
1. Are the patches against the trunk or can they be applied to 10.9.1.0 (I already have been building the equivalent of that release anyways myself).
2. Apply both patches?
________________________________________
From: Mike Matrigali [mikem_app@sbcglobal.net]
Sent: Wednesday, March 27, 2013 6:22 PM
To: derby-dev@db.apache.org
Subject: Re: Why is the optimizer choosing such a bad path
I would suggest seeing if this is related to DERBY-6045 or not. I
don't think this query goes through the in-list path but I am not sure, so if you are set up you could apply the patch and see if it makes a difference.
There is a patch available and I believe it will be going into trunk soon.
I have been waiting for that patch to go in, and then look to see if the underlying problem exists in other parts of the code. The problem is that we changed update statistics to not create a statistic on a unique single column index, and that the code above then did not do the right thing when that stat did not exist. To see if you are running into a similar problem you can use the workaround that Kristian suggested in that issue:
I think specifying
derby.storage.indexStats.debug.keepDisposableStats=true *and* regenerating statistics for the relevant tables will suffice as a work-around for this issue.
Given that we agree the statistics for single-column unique indexes aren't needed, do we know what puts off the optimizer?
The lack of statistics, or stale row estimates?
(I don't have time to dig into that, and I don't know what the optimizer does in this case.)
If you set the property on your db and rerun all the statistics and see a different result then it will point to another place in the code that needs to change to handle a stat not existing in the catalog.
On 3/27/2013 12:16 PM, Bergquist, Brett wrote:
> Some background.
>
> I have a customer that is using an earlier release of our system that has
> Derby 10.8.2.1 installed. Because of issues like
> https://issues.apache.org/jira/browse/DERBY-5680,
> it has been running with the indexStat daemon disabled.
>
> We are going to have a new release soon and it will be installing Derby 10.9.1.0 with the indexStat
> daemon enabled. I recently got a copy of the customer's database (132Gb) and ran into
> a very long query. I manually ran SYS_UTIL.SYSCS_UPDATE_STATISTICS on all of the tables
> in the query to ensure that the statistics are up to date.
>
> The tables in the query look like:
>
> // 62,908,433 Rows
> CREATE TABLE "CORE_V1"."CONFIGURATIONSET_CONFIGURATIONBUNDLE"
> (
> CONFIGURATIONBUNDLE_ID int NOT NULL,
> CONFIGURATIONSET_ID int NOT NULL,
> CONSTRAINT CONFIGURATIONSET_CONFIGURATIONBUNDLE_PK PRIMARY KEY
> (CONFIGURATIONBUNDLE_ID,CONFIGURATIONSET_ID)
> );
> ALTER TABLE "CORE_V1"."CONFIGURATIONSET_CONFIGURATIONBUNDLE"
> ADD CONSTRAINT CONFIGURATIONSET_CONFIGURATIONBUNDLE_FK_2
> FOREIGN KEY (CONFIGURATIONSET_ID)
> REFERENCES "CORE_V1"."CONFIGURATION_SET"(ID);
> ALTER TABLE "CORE_V1"."CONFIGURATIONSET_CONFIGURATIONBUNDLE"
> ADD CONSTRAINT CONFIGURATIONSET_CONFIGURATIONBUNDLE_FK_1
> FOREIGN KEY (CONFIGURATIONBUNDLE_ID)
> REFERENCES "CORE_V1"."CONFIGURATION_BUNDLE"(ID);
> CREATE INDEX SQL100922214558160 ON
> "CORE_V1"."CONFIGURATIONSET_CONFIGURATIONBUNDLE"(CONFIGURATIONSET_ID);
> CREATE INDEX SQL100922215312050 ON
> "CORE_V1"."CONFIGURATIONSET_CONFIGURATIONBUNDLE"(CONFIGURATIONBUNDLE_I
> D); CREATE UNIQUE INDEX SQL081029110254290 ON
> "CORE_V1"."CONFIGURATIONSET_CONFIGURATIONBUNDLE"
> (
> CONFIGURATIONBUNDLE_ID,
> CONFIGURATIONSET_ID
> );
>
> // 4 Rows
> CREATE TABLE "PKG_9145E10G"."INGRESS_COS_QUEUE_CONFIG_BUNDLE"
> (
> ID int PRIMARY KEY NOT NULL,
> LLQ_CONFIG_ENTRY_ID int NOT NULL
> );
> ALTER TABLE "PKG_9145E10G"."INGRESS_COS_QUEUE_CONFIG_BUNDLE"
> ADD CONSTRAINT INGRESS_COS_QUEUE_CONFIG_BUNDLE_FK_2
> FOREIGN KEY (LLQ_CONFIG_ENTRY_ID)
> REFERENCES "PKG_9145E10G"."INGRESS_COS_QUEUE_CONFIG_ENTRY"(ID);
> ALTER TABLE "PKG_9145E10G"."INGRESS_COS_QUEUE_CONFIG_BUNDLE"
> ADD CONSTRAINT INGRESS_COS_QUEUE_CONFIG_BUNDLE_FK_1
> FOREIGN KEY (ID)
> REFERENCES "CORE_V1"."CONFIGURATION_BUNDLE"(ID);
> CREATE INDEX SQL130327093508050 ON
> "PKG_9145E10G"."INGRESS_COS_QUEUE_CONFIG_BUNDLE"(ID);
> CREATE INDEX SQL130327093508060 ON
> "PKG_9145E10G"."INGRESS_COS_QUEUE_CONFIG_BUNDLE"(LLQ_CONFIG_ENTRY_ID);
> CREATE UNIQUE INDEX SQL130327093437740 ON
> "PKG_9145E10G"."INGRESS_COS_QUEUE_CONFIG_BUNDLE"(ID);
>
> // 197,363 Rows
> CREATE TABLE "PKG_9145E10G"."CONFIGURATION_BUNDLE_9145E10G"
> (
> ID int PRIMARY KEY NOT NULL
> );
> ALTER TABLE "PKG_9145E10G"."CONFIGURATION_BUNDLE_9145E10G"
> ADD CONSTRAINT CONFIGURATION_BUNDLE_9145E10G_FK_1
> FOREIGN KEY (ID)
> REFERENCES "CORE_V1"."CONFIGURATION_BUNDLE"(ID);
> CREATE UNIQUE INDEX SQL100226025356610 ON
> "PKG_9145E10G"."CONFIGURATION_BUNDLE_9145E10G"(ID);
> CREATE INDEX SQL100922215631540 ON
> "PKG_9145E10G"."CONFIGURATION_BUNDLE_9145E10G"(ID);
>
> // 6,740,327 Rows
> CREATE TABLE "CORE_V1"."CONFIGURATION_BUNDLE"
> (
> DTYPE varchar(64),
> OPLOCK int DEFAULT 0 NOT NULL,
> BUNDLE_NAME varchar(64) NOT NULL,
> ID int PRIMARY KEY NOT NULL
> );
> CREATE INDEX CONFIGURATION_BUNDLE_IX_2 ON
> "CORE_V1"."CONFIGURATION_BUNDLE"(BUNDLE_NAME);
> CREATE INDEX CONFIGURATION_BUNDLE_IX_1 ON
> "CORE_V1"."CONFIGURATION_BUNDLE"(DTYPE);
> CREATE UNIQUE INDEX SQL100922215131580 ON
> "CORE_V1"."CONFIGURATION_BUNDLE"(ID);
>
>
> For some reason, the optimizer is doing a table scan across the
> CORE_V1.CONFIGURATIONSET_CONFIGURATIONBUNDLE table which has 64 million rows and it even goes across this 4 times!.
>
> One issue is that this query is generated by Eclipselink (JPA) and I have no control on the query generation.
>
> So any ideas on why it would chose this path and what I might be able to do about it? In playing
> around and trying to find the issue, I notice that if I remove the
>
> t0.DTYPE = 'INGRESS_COS_QUEUE_CONFIG_BUNDLE_9145E10G')
>
> constraint, then the query returns 0 rows (it should even with this constraint as there are no rows
> that are acceptable) and returns them in about .05 seconds. Note CORE_V1.CONFIGURATION_BUNDLE does
> have a non-unique index on DTYPE.
>
> Ok, just on a whim, I removed the index on DTYPE and the query came
> back .06 seconds. That column is used by Eclipselink in determining which of a "derived" object to return so I don't have much control on it.
>
> ----
> Statement Name:
> SQL_CURLH000C1
> Statement Text:
> SELECT t0.ID, t0.DTYPE, t0.BUNDLE_NAME, t0.OPLOCK, t1.ID, t2.ID,
> t2.LLQ_CONFIG_ENTRY_ID FROM
> CORE_V1.CONFIGURATIONSET_CONFIGURATIONBUNDLE t3,
> PKG_9145E10G.INGRESS_COS_QUEUE_CONFIG_BUNDLE t2,
> PKG_9145E10G.CONFIGURATION_BUNDLE_9145E10G t1,
> CORE_V1.CONFIGURATION_BUNDLE t0 WHERE (((t3.CONFIGURATIONSET_ID =
> 4000) AND (t0.ID = t3.CONFIGURATIONBUNDLE_ID)) AND (((t2.ID = t0.ID)
> AND (t1.ID = t0.ID)) AND (t0.DTYPE =
> 'INGRESS_COS_QUEUE_CONFIG_BUNDLE_9145E10G')))
> Parse Time: 0
> Bind Time: 0
> Optimize Time: 0
> Generate Time: 0
> Compile Time: 0
> Execute Time: 0
> Begin Compilation Timestamp : null
> End Compilation Timestamp : null
> Begin Execution Timestamp : null
> End Execution Timestamp : null
> Statement Execution Plan Text:
> Project-Restrict ResultSet (9):
> Number of opens = 1
> Rows seen = 0
> Rows filtered = 0
> restriction = false
> projection = true
> constructor time (milliseconds) = 0
> open time (milliseconds) = 0
> next time (milliseconds) = 0
> close time (milliseconds) = 0
> restriction time (milliseconds) = 0
> projection time (milliseconds) = 0
> optimizer estimated row count: 0.00
> optimizer estimated cost: 8.05
> Source result set:
> Nested Loop Join ResultSet:
> Number of opens = 1
> Rows seen from the left = 0
> Rows seen from the right = 0
> Rows filtered = 0
> Rows returned = 0
> constructor time (milliseconds) = 0
> open time (milliseconds) = 0
> next time (milliseconds) = 0
> close time (milliseconds) = 0
> optimizer estimated row count: 0.00
> optimizer estimated cost: 8.05
> Left result set:
> Nested Loop Join ResultSet:
> Number of opens = 1
> Rows seen from the left = 0
> Rows seen from the right = 0
> Rows filtered = 0
> Rows returned = 0
> constructor time (milliseconds) = 0
> open time (milliseconds) = 0
> next time (milliseconds) = 0
> close time (milliseconds) = 0
> optimizer estimated row count: 0.00
> optimizer estimated cost: 8.05
> Left result set:
> Nested Loop Join ResultSet:
> Number of opens = 1
> Rows seen from the left = 4
> Rows seen from the right = 0
> Rows filtered = 0
> Rows returned = 0
> constructor time (milliseconds) = 0
> open time (milliseconds) = 0
> next time (milliseconds) = 0
> close time (milliseconds) = 0
> optimizer estimated row count: 0.00
> optimizer estimated cost: 8.05
> Left result set:
> Index Row to Base Row ResultSet for CONFIGURATION_BUNDLE:
> Number of opens = 1
> Rows seen = 4
> Columns accessed from heap = {0, 1, 2, 3}
> constructor time (milliseconds) = 0
> open time (milliseconds) = 0
> next time (milliseconds) = 0
> close time (milliseconds) = 0
> optimizer estimated row count: 0.00
> optimizer estimated cost: 8.05
> Index Scan ResultSet for CONFIGURATION_BUNDLE using index CONFIGURATION_BUNDLE_IX_1 at read committed isolation level using instantaneous share row locking chosen by the optimizer
> Number of opens = 1
> Rows seen = 4
> Rows filtered = 0
> Fetch Size = 16
> constructor time (milliseconds) = 0
> open time (milliseconds) = 0
> next time (milliseconds) = 0
> close time (milliseconds) = 0
> next time in
> milliseconds/row = 0
>
> scan information:
> Bit set of columns fetched=All
> Number of columns fetched=2
> Number of deleted rows visited=0
> Number of pages visited=5
> Number of rows qualified=4
> Number of rows visited=5
> Scan type=btree
> Tree height=5
> start position:
> >= on first 1 column(s).
> Ordered null semantics on the following columns:
> stop position:
> > on first 1 column(s).
> Ordered null semantics on the following columns:
> qualifiers:
> None
> optimizer estimated row count: 0.00
> optimizer estimated
> cost: 8.05
>
> Right result set:
> Table Scan ResultSet for CONFIGURATIONSET_CONFIGURATIONBUNDLE at read committed isolation level using instantaneous share row locking chosen by the optimizer
> Number of opens = 4
> Rows seen = 0
> Rows filtered = 0
> Fetch Size = 16
> constructor time (milliseconds) = 0
> open time (milliseconds) = 0
> next time (milliseconds) = 0
> close time (milliseconds) = 0
>
> scan information:
> Bit set of columns fetched=All
> Number of columns fetched=2
> Number of pages visited=670838
> Number of rows qualified=0
> Number of rows visited=262429876
> Scan type=heap
> start position:
> null
> stop position:
> null
> qualifiers:
> Column[0][0] Id: 0
> Operator: =
> Ordered nulls: false
> Unknown return value: false
> Negate comparison result: false
> Column[0][1] Id: 1
> Operator: =
> Ordered nulls: false
> Unknown return value: false
> Negate comparison result: false
> optimizer estimated row count: 0.00
> optimizer estimated cost: 0.00
>
> Right result set:
> Table Scan ResultSet for INGRESS_COS_QUEUE_CONFIG_BUNDLE at read committed isolation level using instantaneous share row locking chosen by the optimizer
> Number of opens = 0
> Rows seen = 0
> Rows filtered = 0
> Fetch Size = 16
> constructor time (milliseconds) = 0
> open time (milliseconds) = 0
> next time (milliseconds) = 0
> close time (milliseconds) = 0
>
> scan information:
> start position:
> null
> stop position:
> null
> qualifiers:
> Column[0][0] Id: 0
> Operator: =
> Ordered nulls: false
> Unknown return value: false
> Negate comparison result: false
> optimizer estimated row count: 0.00
> optimizer estimated cost: 0.00
>
> Right result set:
> Table Scan ResultSet for CONFIGURATION_BUNDLE_9145E10G at read committed isolation level using instantaneous share row locking chosen by the optimizer
> Number of opens = 0
> Rows seen = 0
> Rows filtered = 0
> Fetch Size = 16
> constructor time (milliseconds) = 0
> open time (milliseconds) = 0
> next time (milliseconds) = 0
> close time (milliseconds) = 0
>
> scan information:
> start position:
> null
> stop position:
> null
> qualifiers:
> Column[0][0] Id: 0
> Operator: =
> Ordered nulls: false
> Unknown return value: false
> Negate comparison result: false
> optimizer estimated row count: 0.00
> optimizer estimated cost: 0.00
>
>
>
Re: Why is the optimizer choosing such a bad path
Posted by Dag Wanvik <da...@oracle.com>.
On 28.03.2013 22:32, Bergquist, Brett wrote:
> Okay, I finally figured out that " CALL SYSCS_UTIL.SYSCS_SET_STATISTICS_TIMING(1);" is required. Now from the name which has "timing" in it, one (or at least I) would not think that this would affect the returning of the optimizer estimates. I guess I naively assumed this would affect the reporting of the compile and execution times. Maybe the documentation needs to be fixed here.
Interesting. In my little test program I saw the same estimates with and
without setting the timing collection. Does anyone know why this should
be the case? If you can repro this, I'd be happy to file a JIRA bug, or
feel free to do it yourself. Initial category should probably be
documentation.
Thanks,
Dag
RE: Why is the optimizer choosing such a bad path
Posted by "Bergquist, Brett" <BB...@canoga.com>.
Okay, I finally figured out that " CALL SYSCS_UTIL.SYSCS_SET_STATISTICS_TIMING(1);" is required. Now from the name which has "timing" in it, one (or at least I) would not think that this would affect the returning of the optimizer estimates. I guess I naively assumed this would affect the reporting of the compile and execution times. Maybe the documentation needs to be fixed here.
In any case, below is the query plan with this turned on. Note that optimizer is estimating a row count of 0 for the table with 64 million rows and does a table scan.
Statement Name:
SQL_CURLH000C1
Statement Text:
SELECT t0.ID, t0.DTYPE, t0.BUNDLE_NAME, t0.OPLOCK, t1.ID, t2.ID, t2.LLQ_CONFIG_ENTRY_ID FROM CORE_V1.CONFIGURATIONSET_CONFIGURATIONBUNDLE t3, PKG_9145E10G.INGRESS_COS_QUEUE_CONFIG_BUNDLE t2, PKG_9145E10G.CONFIGURATION_BUNDLE_9145E10G t1, CORE_V1.CONFIGURATION_BUNDLE t0 WHERE (((t3.CONFIGURATIONSET_ID = 4000) AND (t0.ID = t3.CONFIGURATIONBUNDLE_ID)) AND (((t2.ID = t0.ID) AND (t1.ID = t0.ID)) AND (t0.DTYPE = 'INGRESS_COS_QUEUE_CONFIG_BUNDLE_9145E10G')))
Parse Time: 8
Bind Time: 66
Optimize Time: 3935
Generate Time: 7
Compile Time: 4016
Execute Time: 220556
Begin Compilation Timestamp : 2013-03-28 08:27:13.028
End Compilation Timestamp : 2013-03-28 08:27:17.044
Begin Execution Timestamp : 2013-03-28 08:27:17.053
End Execution Timestamp : 2013-03-28 08:30:57.615
Statement Execution Plan Text:
Project-Restrict ResultSet (9):
Number of opens = 1
Rows seen = 0
Rows filtered = 0
restriction = false
projection = true
constructor time (milliseconds) = 0
open time (milliseconds) = 220556
next time (milliseconds) = 0
close time (milliseconds) = 0
restriction time (milliseconds) = 0
projection time (milliseconds) = 0
optimizer estimated row count: 0.00
optimizer estimated cost: 8.05
Source result set:
Nested Loop Join ResultSet:
Number of opens = 1
Rows seen from the left = 0
Rows seen from the right = 0
Rows filtered = 0
Rows returned = 0
constructor time (milliseconds) = 0
open time (milliseconds) = 220556
next time (milliseconds) = 0
close time (milliseconds) = 6
optimizer estimated row count: 0.00
optimizer estimated cost: 8.05
Left result set:
Nested Loop Join ResultSet:
Number of opens = 1
Rows seen from the left = 0
Rows seen from the right = 0
Rows filtered = 0
Rows returned = 0
constructor time (milliseconds) = 0
open time (milliseconds) = 220556
next time (milliseconds) = 0
close time (milliseconds) = 6
optimizer estimated row count: 0.00
optimizer estimated cost: 8.05
Left result set:
Nested Loop Join ResultSet:
Number of opens = 1
Rows seen from the left = 4
Rows seen from the right = 0
Rows filtered = 0
Rows returned = 0
constructor time (milliseconds) = 0
open time (milliseconds) = 63
next time (milliseconds) = 220493
close time (milliseconds) = 6
optimizer estimated row count: 0.00
optimizer estimated cost: 8.05
Left result set:
Index Row to Base Row ResultSet for CONFIGURATION_BUNDLE:
Number of opens = 1
Rows seen = 4
Columns accessed from heap = {0, 1, 2, 3}
constructor time (milliseconds) = 0
open time (milliseconds) = 0
next time (milliseconds) = 64
close time (milliseconds) = 6
optimizer estimated row count: 0.00
optimizer estimated cost: 8.05
Index Scan ResultSet for CONFIGURATION_BUNDLE using index CONFIGURATION_BUNDLE_IX_1 at read committed isolation level using instantaneous share row locking chosen by the optimizer
Number of opens = 1
Rows seen = 4
Rows filtered = 0
Fetch Size = 16
constructor time (milliseconds) = 0
open time (milliseconds) = 2
next time (milliseconds) = 1
close time (milliseconds) = 6
next time in milliseconds/row = 0
scan information:
Bit set of columns fetched=All
Number of columns fetched=2
Number of deleted rows visited=0
Number of pages visited=5
Number of rows qualified=4
Number of rows visited=5
Scan type=btree
Tree height=5
start position:
>= on first 1 column(s).
Ordered null semantics on the following columns:
stop position:
> on first 1 column(s).
Ordered null semantics on the following columns:
qualifiers:
None
optimizer estimated row count: 0.00
optimizer estimated cost: 8.05
Right result set:
Table Scan ResultSet for CONFIGURATIONSET_CONFIGURATIONBUNDLE at read committed isolation level using instantaneous share row locking chosen by the optimizer
Number of opens = 4
Rows seen = 0
Rows filtered = 0
Fetch Size = 16
constructor time (milliseconds) = 0
open time (milliseconds) = 64
next time (milliseconds) = 0
close time (milliseconds) = 11
scan information:
Bit set of columns fetched=All
Number of columns fetched=2
Number of pages visited=670832
Number of rows qualified=0
Number of rows visited=262428000
Scan type=heap
start position:
null
stop position:
null
qualifiers:
Column[0][0] Id: 0
Operator: =
Ordered nulls: false
Unknown return value: false
Negate comparison result: false
Column[0][1] Id: 1
Operator: =
Ordered nulls: false
Unknown return value: false
Negate comparison result: false
optimizer estimated row count: 0.00
optimizer estimated cost: 0.00
Right result set:
Table Scan ResultSet for INGRESS_COS_QUEUE_CONFIG_BUNDLE at read committed isolation level using instantaneous share row locking chosen by the optimizer
Number of opens = 0
Rows seen = 0
Rows filtered = 0
Fetch Size = 16
constructor time (milliseconds) = 0
open time (milliseconds) = 0
next time (milliseconds) = 0
close time (milliseconds) = 0
scan information:
start position:
null
stop position:
null
qualifiers:
Column[0][0] Id: 0
Operator: =
Ordered nulls: false
Unknown return value: false
Negate comparison result: false
optimizer estimated row count: 0.00
optimizer estimated cost: 0.00
Right result set:
Table Scan ResultSet for CONFIGURATION_BUNDLE_9145E10G at read committed isolation level using instantaneous share row locking chosen by the optimizer
Number of opens = 0
Rows seen = 0
Rows filtered = 0
Fetch Size = 16
constructor time (milliseconds) = 0
open time (milliseconds) = 0
next time (milliseconds) = 0
close time (milliseconds) = 0
scan information:
start position:
null
stop position:
null
qualifiers:
Column[0][0] Id: 0
Operator: =
Ordered nulls: false
Unknown return value: false
Negate comparison result: false
optimizer estimated row count: 0.00
optimizer estimated cost: 0.00
-----Original Message-----
From: Bergquist, Brett [mailto:BBergquist@canoga.com]
Sent: Wednesday, March 27, 2013 8:42 PM
To: derby-dev@db.apache.org
Subject: RE: Why is the optimizer choosing such a bad path
I am able to build Derby so I can try a patch. On DERBY-6045, there are two attached patches. Two questions:
1. Are the patches against the trunk or can they be applied to 10.9.1.0 (I already have been building the equivalent of that release anyways myself).
2. Apply both patches?
________________________________________
From: Mike Matrigali [mikem_app@sbcglobal.net]
Sent: Wednesday, March 27, 2013 6:22 PM
To: derby-dev@db.apache.org
Subject: Re: Why is the optimizer choosing such a bad path
I would suggest seeing if this is related to DERBY-6045 or not. I
don't think this query goes through the in-list path but I am not sure, so if you are set up you could apply the patch and see if it makes a difference.
There is a patch available and I believe it will be going into trunk soon.
I have been waiting for that patch to go in, and then look to see if the underlying problem exists in other parts of the code. The problem is that we changed update statistics to not create a statistic on a unique single column index, and that the code above then did not do the right thing when that stat did not exist. To see if you are running into a similar problem you can use the workaround that Kristian suggested in that issue:
I think specifying
derby.storage.indexStats.debug.keepDisposableStats=true *and* regenerating statistics for the relevant tables will suffice as a work-around for this issue.
Given that we agree the statistics for single-column unique indexes aren't needed, do we know what puts off the optimizer?
The lack of statistics, or stale row estimates?
(I don't have time to dig into that, and I don't know what the optimizer does in this case.)
If you set the property on your db and rerun all the statistics and see a different result then it will point to another place in the code that needs to change to handle a stat not existing in the catalog.
On 3/27/2013 12:16 PM, Bergquist, Brett wrote:
> Some background.
>
> I have a customer that is using an earlier release of our system that has
> Derby 10.8.2.1 installed. Because of issues like
> https://issues.apache.org/jira/browse/DERBY-5680,
> it has been running with the indexStat daemon disabled.
>
> We are going to have a new release soon and it will be installing Derby 10.9.1.0 with the indexStat
> daemon enabled. I recently got a copy of the customer's database (132Gb) and ran into
> a very long query. I manually ran SYS_UTIL.SYSCS_UPDATE_STATISTICS on all of the tables
> in the query to ensure that the statistics are up to date.
>
> The tables in the query look like:
>
> // 62,908,433 Rows
> CREATE TABLE "CORE_V1"."CONFIGURATIONSET_CONFIGURATIONBUNDLE"
> (
> CONFIGURATIONBUNDLE_ID int NOT NULL,
> CONFIGURATIONSET_ID int NOT NULL,
> CONSTRAINT CONFIGURATIONSET_CONFIGURATIONBUNDLE_PK PRIMARY KEY
> (CONFIGURATIONBUNDLE_ID,CONFIGURATIONSET_ID)
> );
> ALTER TABLE "CORE_V1"."CONFIGURATIONSET_CONFIGURATIONBUNDLE"
> ADD CONSTRAINT CONFIGURATIONSET_CONFIGURATIONBUNDLE_FK_2
> FOREIGN KEY (CONFIGURATIONSET_ID)
> REFERENCES "CORE_V1"."CONFIGURATION_SET"(ID);
> ALTER TABLE "CORE_V1"."CONFIGURATIONSET_CONFIGURATIONBUNDLE"
> ADD CONSTRAINT CONFIGURATIONSET_CONFIGURATIONBUNDLE_FK_1
> FOREIGN KEY (CONFIGURATIONBUNDLE_ID)
> REFERENCES "CORE_V1"."CONFIGURATION_BUNDLE"(ID);
> CREATE INDEX SQL100922214558160 ON
> "CORE_V1"."CONFIGURATIONSET_CONFIGURATIONBUNDLE"(CONFIGURATIONSET_ID);
> CREATE INDEX SQL100922215312050 ON
> "CORE_V1"."CONFIGURATIONSET_CONFIGURATIONBUNDLE"(CONFIGURATIONBUNDLE_I
> D); CREATE UNIQUE INDEX SQL081029110254290 ON
> "CORE_V1"."CONFIGURATIONSET_CONFIGURATIONBUNDLE"
> (
> CONFIGURATIONBUNDLE_ID,
> CONFIGURATIONSET_ID
> );
>
> // 4 Rows
> CREATE TABLE "PKG_9145E10G"."INGRESS_COS_QUEUE_CONFIG_BUNDLE"
> (
> ID int PRIMARY KEY NOT NULL,
> LLQ_CONFIG_ENTRY_ID int NOT NULL
> );
> ALTER TABLE "PKG_9145E10G"."INGRESS_COS_QUEUE_CONFIG_BUNDLE"
> ADD CONSTRAINT INGRESS_COS_QUEUE_CONFIG_BUNDLE_FK_2
> FOREIGN KEY (LLQ_CONFIG_ENTRY_ID)
> REFERENCES "PKG_9145E10G"."INGRESS_COS_QUEUE_CONFIG_ENTRY"(ID);
> ALTER TABLE "PKG_9145E10G"."INGRESS_COS_QUEUE_CONFIG_BUNDLE"
> ADD CONSTRAINT INGRESS_COS_QUEUE_CONFIG_BUNDLE_FK_1
> FOREIGN KEY (ID)
> REFERENCES "CORE_V1"."CONFIGURATION_BUNDLE"(ID);
> CREATE INDEX SQL130327093508050 ON
> "PKG_9145E10G"."INGRESS_COS_QUEUE_CONFIG_BUNDLE"(ID);
> CREATE INDEX SQL130327093508060 ON
> "PKG_9145E10G"."INGRESS_COS_QUEUE_CONFIG_BUNDLE"(LLQ_CONFIG_ENTRY_ID);
> CREATE UNIQUE INDEX SQL130327093437740 ON
> "PKG_9145E10G"."INGRESS_COS_QUEUE_CONFIG_BUNDLE"(ID);
>
> // 197,363 Rows
> CREATE TABLE "PKG_9145E10G"."CONFIGURATION_BUNDLE_9145E10G"
> (
> ID int PRIMARY KEY NOT NULL
> );
> ALTER TABLE "PKG_9145E10G"."CONFIGURATION_BUNDLE_9145E10G"
> ADD CONSTRAINT CONFIGURATION_BUNDLE_9145E10G_FK_1
> FOREIGN KEY (ID)
> REFERENCES "CORE_V1"."CONFIGURATION_BUNDLE"(ID);
> CREATE UNIQUE INDEX SQL100226025356610 ON
> "PKG_9145E10G"."CONFIGURATION_BUNDLE_9145E10G"(ID);
> CREATE INDEX SQL100922215631540 ON
> "PKG_9145E10G"."CONFIGURATION_BUNDLE_9145E10G"(ID);
>
> // 6,740,327 Rows
> CREATE TABLE "CORE_V1"."CONFIGURATION_BUNDLE"
> (
> DTYPE varchar(64),
> OPLOCK int DEFAULT 0 NOT NULL,
> BUNDLE_NAME varchar(64) NOT NULL,
> ID int PRIMARY KEY NOT NULL
> );
> CREATE INDEX CONFIGURATION_BUNDLE_IX_2 ON
> "CORE_V1"."CONFIGURATION_BUNDLE"(BUNDLE_NAME);
> CREATE INDEX CONFIGURATION_BUNDLE_IX_1 ON
> "CORE_V1"."CONFIGURATION_BUNDLE"(DTYPE);
> CREATE UNIQUE INDEX SQL100922215131580 ON
> "CORE_V1"."CONFIGURATION_BUNDLE"(ID);
>
>
> For some reason, the optimizer is doing a table scan across the
> CORE_V1.CONFIGURATIONSET_CONFIGURATIONBUNDLE table which has 64 million rows and it even goes across this 4 times!.
>
> One issue is that this query is generated by Eclipselink (JPA) and I have no control on the query generation.
>
> So any ideas on why it would chose this path and what I might be able to do about it? In playing
> around and trying to find the issue, I notice that if I remove the
>
> t0.DTYPE = 'INGRESS_COS_QUEUE_CONFIG_BUNDLE_9145E10G')
>
> constraint, then the query returns 0 rows (it should even with this constraint as there are no rows
> that are acceptable) and returns them in about .05 seconds. Note CORE_V1.CONFIGURATION_BUNDLE does
> have a non-unique index on DTYPE.
>
> Ok, just on a whim, I removed the index on DTYPE and the query came
> back .06 seconds. That column is used by Eclipselink in determining which of a "derived" object to return so I don't have much control on it.
>
> ----
> Statement Name:
> SQL_CURLH000C1
> Statement Text:
> SELECT t0.ID, t0.DTYPE, t0.BUNDLE_NAME, t0.OPLOCK, t1.ID, t2.ID,
> t2.LLQ_CONFIG_ENTRY_ID FROM
> CORE_V1.CONFIGURATIONSET_CONFIGURATIONBUNDLE t3,
> PKG_9145E10G.INGRESS_COS_QUEUE_CONFIG_BUNDLE t2,
> PKG_9145E10G.CONFIGURATION_BUNDLE_9145E10G t1,
> CORE_V1.CONFIGURATION_BUNDLE t0 WHERE (((t3.CONFIGURATIONSET_ID =
> 4000) AND (t0.ID = t3.CONFIGURATIONBUNDLE_ID)) AND (((t2.ID = t0.ID)
> AND (t1.ID = t0.ID)) AND (t0.DTYPE =
> 'INGRESS_COS_QUEUE_CONFIG_BUNDLE_9145E10G')))
> Parse Time: 0
> Bind Time: 0
> Optimize Time: 0
> Generate Time: 0
> Compile Time: 0
> Execute Time: 0
> Begin Compilation Timestamp : null
> End Compilation Timestamp : null
> Begin Execution Timestamp : null
> End Execution Timestamp : null
> Statement Execution Plan Text:
> Project-Restrict ResultSet (9):
> Number of opens = 1
> Rows seen = 0
> Rows filtered = 0
> restriction = false
> projection = true
> constructor time (milliseconds) = 0
> open time (milliseconds) = 0
> next time (milliseconds) = 0
> close time (milliseconds) = 0
> restriction time (milliseconds) = 0
> projection time (milliseconds) = 0
> optimizer estimated row count: 0.00
> optimizer estimated cost: 8.05
> Source result set:
> Nested Loop Join ResultSet:
> Number of opens = 1
> Rows seen from the left = 0
> Rows seen from the right = 0
> Rows filtered = 0
> Rows returned = 0
> constructor time (milliseconds) = 0
> open time (milliseconds) = 0
> next time (milliseconds) = 0
> close time (milliseconds) = 0
> optimizer estimated row count: 0.00
> optimizer estimated cost: 8.05
> Left result set:
> Nested Loop Join ResultSet:
> Number of opens = 1
> Rows seen from the left = 0
> Rows seen from the right = 0
> Rows filtered = 0
> Rows returned = 0
> constructor time (milliseconds) = 0
> open time (milliseconds) = 0
> next time (milliseconds) = 0
> close time (milliseconds) = 0
> optimizer estimated row count: 0.00
> optimizer estimated cost: 8.05
> Left result set:
> Nested Loop Join ResultSet:
> Number of opens = 1
> Rows seen from the left = 4
> Rows seen from the right = 0
> Rows filtered = 0
> Rows returned = 0
> constructor time (milliseconds) = 0
> open time (milliseconds) = 0
> next time (milliseconds) = 0
> close time (milliseconds) = 0
> optimizer estimated row count: 0.00
> optimizer estimated cost: 8.05
> Left result set:
> Index Row to Base Row ResultSet for CONFIGURATION_BUNDLE:
> Number of opens = 1
> Rows seen = 4
> Columns accessed from heap = {0, 1, 2, 3}
> constructor time (milliseconds) = 0
> open time (milliseconds) = 0
> next time (milliseconds) = 0
> close time (milliseconds) = 0
> optimizer estimated row count: 0.00
> optimizer estimated cost: 8.05
> Index Scan ResultSet for CONFIGURATION_BUNDLE using index CONFIGURATION_BUNDLE_IX_1 at read committed isolation level using instantaneous share row locking chosen by the optimizer
> Number of opens = 1
> Rows seen = 4
> Rows filtered = 0
> Fetch Size = 16
> constructor time (milliseconds) = 0
> open time (milliseconds) = 0
> next time (milliseconds) = 0
> close time (milliseconds) = 0
> next time in
> milliseconds/row = 0
>
> scan information:
> Bit set of columns fetched=All
> Number of columns fetched=2
> Number of deleted rows visited=0
> Number of pages visited=5
> Number of rows qualified=4
> Number of rows visited=5
> Scan type=btree
> Tree height=5
> start position:
> >= on first 1 column(s).
> Ordered null semantics on the following columns:
> stop position:
> > on first 1 column(s).
> Ordered null semantics on the following columns:
> qualifiers:
> None
> optimizer estimated row count: 0.00
> optimizer estimated
> cost: 8.05
>
> Right result set:
> Table Scan ResultSet for CONFIGURATIONSET_CONFIGURATIONBUNDLE at read committed isolation level using instantaneous share row locking chosen by the optimizer
> Number of opens = 4
> Rows seen = 0
> Rows filtered = 0
> Fetch Size = 16
> constructor time (milliseconds) = 0
> open time (milliseconds) = 0
> next time (milliseconds) = 0
> close time (milliseconds) = 0
>
> scan information:
> Bit set of columns fetched=All
> Number of columns fetched=2
> Number of pages visited=670838
> Number of rows qualified=0
> Number of rows visited=262429876
> Scan type=heap
> start position:
> null
> stop position:
> null
> qualifiers:
> Column[0][0] Id: 0
> Operator: =
> Ordered nulls: false
> Unknown return value: false
> Negate comparison result: false
> Column[0][1] Id: 1
> Operator: =
> Ordered nulls: false
> Unknown return value: false
> Negate comparison result: false
> optimizer estimated row count: 0.00
> optimizer estimated cost: 0.00
>
> Right result set:
> Table Scan ResultSet for INGRESS_COS_QUEUE_CONFIG_BUNDLE at read committed isolation level using instantaneous share row locking chosen by the optimizer
> Number of opens = 0
> Rows seen = 0
> Rows filtered = 0
> Fetch Size = 16
> constructor time (milliseconds) = 0
> open time (milliseconds) = 0
> next time (milliseconds) = 0
> close time (milliseconds) = 0
>
> scan information:
> start position:
> null
> stop position:
> null
> qualifiers:
> Column[0][0] Id: 0
> Operator: =
> Ordered nulls: false
> Unknown return value: false
> Negate comparison result: false
> optimizer estimated row count: 0.00
> optimizer estimated cost: 0.00
>
> Right result set:
> Table Scan ResultSet for CONFIGURATION_BUNDLE_9145E10G at read committed isolation level using instantaneous share row locking chosen by the optimizer
> Number of opens = 0
> Rows seen = 0
> Rows filtered = 0
> Fetch Size = 16
> constructor time (milliseconds) = 0
> open time (milliseconds) = 0
> next time (milliseconds) = 0
> close time (milliseconds) = 0
>
> scan information:
> start position:
> null
> stop position:
> null
> qualifiers:
> Column[0][0] Id: 0
> Operator: =
> Ordered nulls: false
> Unknown return value: false
> Negate comparison result: false
> optimizer estimated row count: 0.00
> optimizer estimated cost: 0.00
>
>
>
RE: Why is the optimizer choosing such a bad path
Posted by "Bergquist, Brett" <BB...@canoga.com>.
I am able to build Derby so I can try a patch. On DERBY-6045, there are two attached patches. Two questions:
1. Are the patches against the trunk or can they be applied to 10.9.1.0 (I already have been building the equivalent of that release anyways myself).
2. Apply both patches?
________________________________________
From: Mike Matrigali [mikem_app@sbcglobal.net]
Sent: Wednesday, March 27, 2013 6:22 PM
To: derby-dev@db.apache.org
Subject: Re: Why is the optimizer choosing such a bad path
I would suggest seeing if this is related to DERBY-6045 or not. I
don't think this query goes through the in-list path but I am not sure,
so if you are set up you could apply the patch and see if it makes
a difference.
There is a patch available and I believe it will be going into trunk
soon.
I have been waiting for that patch to go in, and then look to see if
the underlying problem exists in other parts of the code. The problem
is that we changed update statistics to not create a statistic on a
unique single column index, and that the code above then did not do
the right thing when that stat did not exist. To see if you are running
into a similar problem you can use the workaround that Kristian
suggested in that issue:
I think specifying
derby.storage.indexStats.debug.keepDisposableStats=true *and*
regenerating statistics for the relevant tables will suffice as a
work-around for this issue.
Given that we agree the statistics for single-column unique indexes
aren't needed, do we know what puts off the optimizer?
The lack of statistics, or stale row estimates?
(I don't have time to dig into that, and I don't know what the optimizer
does in this case.)
If you set the property on your db and rerun all the statistics and see
a different result then it will point to another place in the code that
needs to change to handle a stat not existing in the catalog.
On 3/27/2013 12:16 PM, Bergquist, Brett wrote:
> Some background.
>
> I have a customer that is using an earlier release of our system that has
> Derby 10.8.2.1 installed. Because of issues like
> https://issues.apache.org/jira/browse/DERBY-5680,
> it has been running with the indexStat daemon disabled.
>
> We are going to have a new release soon and it will be installing Derby 10.9.1.0 with the indexStat
> daemon enabled. I recently got a copy of the customer's database (132Gb) and ran into
> a very long query. I manually ran SYS_UTIL.SYSCS_UPDATE_STATISTICS on all of the tables
> in the query to ensure that the statistics are up to date.
>
> The tables in the query look like:
>
> // 62,908,433 Rows
> CREATE TABLE "CORE_V1"."CONFIGURATIONSET_CONFIGURATIONBUNDLE"
> (
> CONFIGURATIONBUNDLE_ID int NOT NULL,
> CONFIGURATIONSET_ID int NOT NULL,
> CONSTRAINT CONFIGURATIONSET_CONFIGURATIONBUNDLE_PK PRIMARY KEY (CONFIGURATIONBUNDLE_ID,CONFIGURATIONSET_ID)
> );
> ALTER TABLE "CORE_V1"."CONFIGURATIONSET_CONFIGURATIONBUNDLE"
> ADD CONSTRAINT CONFIGURATIONSET_CONFIGURATIONBUNDLE_FK_2
> FOREIGN KEY (CONFIGURATIONSET_ID)
> REFERENCES "CORE_V1"."CONFIGURATION_SET"(ID);
> ALTER TABLE "CORE_V1"."CONFIGURATIONSET_CONFIGURATIONBUNDLE"
> ADD CONSTRAINT CONFIGURATIONSET_CONFIGURATIONBUNDLE_FK_1
> FOREIGN KEY (CONFIGURATIONBUNDLE_ID)
> REFERENCES "CORE_V1"."CONFIGURATION_BUNDLE"(ID);
> CREATE INDEX SQL100922214558160 ON "CORE_V1"."CONFIGURATIONSET_CONFIGURATIONBUNDLE"(CONFIGURATIONSET_ID);
> CREATE INDEX SQL100922215312050 ON "CORE_V1"."CONFIGURATIONSET_CONFIGURATIONBUNDLE"(CONFIGURATIONBUNDLE_ID);
> CREATE UNIQUE INDEX SQL081029110254290 ON "CORE_V1"."CONFIGURATIONSET_CONFIGURATIONBUNDLE"
> (
> CONFIGURATIONBUNDLE_ID,
> CONFIGURATIONSET_ID
> );
>
> // 4 Rows
> CREATE TABLE "PKG_9145E10G"."INGRESS_COS_QUEUE_CONFIG_BUNDLE"
> (
> ID int PRIMARY KEY NOT NULL,
> LLQ_CONFIG_ENTRY_ID int NOT NULL
> );
> ALTER TABLE "PKG_9145E10G"."INGRESS_COS_QUEUE_CONFIG_BUNDLE"
> ADD CONSTRAINT INGRESS_COS_QUEUE_CONFIG_BUNDLE_FK_2
> FOREIGN KEY (LLQ_CONFIG_ENTRY_ID)
> REFERENCES "PKG_9145E10G"."INGRESS_COS_QUEUE_CONFIG_ENTRY"(ID);
> ALTER TABLE "PKG_9145E10G"."INGRESS_COS_QUEUE_CONFIG_BUNDLE"
> ADD CONSTRAINT INGRESS_COS_QUEUE_CONFIG_BUNDLE_FK_1
> FOREIGN KEY (ID)
> REFERENCES "CORE_V1"."CONFIGURATION_BUNDLE"(ID);
> CREATE INDEX SQL130327093508050 ON "PKG_9145E10G"."INGRESS_COS_QUEUE_CONFIG_BUNDLE"(ID);
> CREATE INDEX SQL130327093508060 ON "PKG_9145E10G"."INGRESS_COS_QUEUE_CONFIG_BUNDLE"(LLQ_CONFIG_ENTRY_ID);
> CREATE UNIQUE INDEX SQL130327093437740 ON "PKG_9145E10G"."INGRESS_COS_QUEUE_CONFIG_BUNDLE"(ID);
>
> // 197,363 Rows
> CREATE TABLE "PKG_9145E10G"."CONFIGURATION_BUNDLE_9145E10G"
> (
> ID int PRIMARY KEY NOT NULL
> );
> ALTER TABLE "PKG_9145E10G"."CONFIGURATION_BUNDLE_9145E10G"
> ADD CONSTRAINT CONFIGURATION_BUNDLE_9145E10G_FK_1
> FOREIGN KEY (ID)
> REFERENCES "CORE_V1"."CONFIGURATION_BUNDLE"(ID);
> CREATE UNIQUE INDEX SQL100226025356610 ON "PKG_9145E10G"."CONFIGURATION_BUNDLE_9145E10G"(ID);
> CREATE INDEX SQL100922215631540 ON "PKG_9145E10G"."CONFIGURATION_BUNDLE_9145E10G"(ID);
>
> // 6,740,327 Rows
> CREATE TABLE "CORE_V1"."CONFIGURATION_BUNDLE"
> (
> DTYPE varchar(64),
> OPLOCK int DEFAULT 0 NOT NULL,
> BUNDLE_NAME varchar(64) NOT NULL,
> ID int PRIMARY KEY NOT NULL
> );
> CREATE INDEX CONFIGURATION_BUNDLE_IX_2 ON "CORE_V1"."CONFIGURATION_BUNDLE"(BUNDLE_NAME);
> CREATE INDEX CONFIGURATION_BUNDLE_IX_1 ON "CORE_V1"."CONFIGURATION_BUNDLE"(DTYPE);
> CREATE UNIQUE INDEX SQL100922215131580 ON "CORE_V1"."CONFIGURATION_BUNDLE"(ID);
>
>
> For some reason, the optimizer is doing a table scan across the CORE_V1.CONFIGURATIONSET_CONFIGURATIONBUNDLE table
> which has 64 million rows and it even goes across this 4 times!.
>
> One issue is that this query is generated by Eclipselink (JPA) and I have no control on the query generation.
>
> So any ideas on why it would chose this path and what I might be able to do about it? In playing
> around and trying to find the issue, I notice that if I remove the
>
> t0.DTYPE = 'INGRESS_COS_QUEUE_CONFIG_BUNDLE_9145E10G')
>
> constraint, then the query returns 0 rows (it should even with this constraint as there are no rows
> that are acceptable) and returns them in about .05 seconds. Note CORE_V1.CONFIGURATION_BUNDLE does
> have a non-unique index on DTYPE.
>
> Ok, just on a whim, I removed the index on DTYPE and the query came back .06 seconds. That column is used
> by Eclipselink in determining which of a "derived" object to return so I don't have much control on it.
>
> ----
> Statement Name:
> SQL_CURLH000C1
> Statement Text:
> SELECT t0.ID, t0.DTYPE, t0.BUNDLE_NAME, t0.OPLOCK, t1.ID, t2.ID, t2.LLQ_CONFIG_ENTRY_ID FROM CORE_V1.CONFIGURATIONSET_CONFIGURATIONBUNDLE t3, PKG_9145E10G.INGRESS_COS_QUEUE_CONFIG_BUNDLE t2, PKG_9145E10G.CONFIGURATION_BUNDLE_9145E10G t1, CORE_V1.CONFIGURATION_BUNDLE t0 WHERE (((t3.CONFIGURATIONSET_ID = 4000) AND (t0.ID = t3.CONFIGURATIONBUNDLE_ID)) AND (((t2.ID = t0.ID) AND (t1.ID = t0.ID)) AND (t0.DTYPE = 'INGRESS_COS_QUEUE_CONFIG_BUNDLE_9145E10G')))
> Parse Time: 0
> Bind Time: 0
> Optimize Time: 0
> Generate Time: 0
> Compile Time: 0
> Execute Time: 0
> Begin Compilation Timestamp : null
> End Compilation Timestamp : null
> Begin Execution Timestamp : null
> End Execution Timestamp : null
> Statement Execution Plan Text:
> Project-Restrict ResultSet (9):
> Number of opens = 1
> Rows seen = 0
> Rows filtered = 0
> restriction = false
> projection = true
> constructor time (milliseconds) = 0
> open time (milliseconds) = 0
> next time (milliseconds) = 0
> close time (milliseconds) = 0
> restriction time (milliseconds) = 0
> projection time (milliseconds) = 0
> optimizer estimated row count: 0.00
> optimizer estimated cost: 8.05
> Source result set:
> Nested Loop Join ResultSet:
> Number of opens = 1
> Rows seen from the left = 0
> Rows seen from the right = 0
> Rows filtered = 0
> Rows returned = 0
> constructor time (milliseconds) = 0
> open time (milliseconds) = 0
> next time (milliseconds) = 0
> close time (milliseconds) = 0
> optimizer estimated row count: 0.00
> optimizer estimated cost: 8.05
> Left result set:
> Nested Loop Join ResultSet:
> Number of opens = 1
> Rows seen from the left = 0
> Rows seen from the right = 0
> Rows filtered = 0
> Rows returned = 0
> constructor time (milliseconds) = 0
> open time (milliseconds) = 0
> next time (milliseconds) = 0
> close time (milliseconds) = 0
> optimizer estimated row count: 0.00
> optimizer estimated cost: 8.05
> Left result set:
> Nested Loop Join ResultSet:
> Number of opens = 1
> Rows seen from the left = 4
> Rows seen from the right = 0
> Rows filtered = 0
> Rows returned = 0
> constructor time (milliseconds) = 0
> open time (milliseconds) = 0
> next time (milliseconds) = 0
> close time (milliseconds) = 0
> optimizer estimated row count: 0.00
> optimizer estimated cost: 8.05
> Left result set:
> Index Row to Base Row ResultSet for CONFIGURATION_BUNDLE:
> Number of opens = 1
> Rows seen = 4
> Columns accessed from heap = {0, 1, 2, 3}
> constructor time (milliseconds) = 0
> open time (milliseconds) = 0
> next time (milliseconds) = 0
> close time (milliseconds) = 0
> optimizer estimated row count: 0.00
> optimizer estimated cost: 8.05
> Index Scan ResultSet for CONFIGURATION_BUNDLE using index CONFIGURATION_BUNDLE_IX_1 at read committed isolation level using instantaneous share row locking chosen by the optimizer
> Number of opens = 1
> Rows seen = 4
> Rows filtered = 0
> Fetch Size = 16
> constructor time (milliseconds) = 0
> open time (milliseconds) = 0
> next time (milliseconds) = 0
> close time (milliseconds) = 0
> next time in milliseconds/row = 0
>
> scan information:
> Bit set of columns fetched=All
> Number of columns fetched=2
> Number of deleted rows visited=0
> Number of pages visited=5
> Number of rows qualified=4
> Number of rows visited=5
> Scan type=btree
> Tree height=5
> start position:
> >= on first 1 column(s).
> Ordered null semantics on the following columns:
> stop position:
> > on first 1 column(s).
> Ordered null semantics on the following columns:
> qualifiers:
> None
> optimizer estimated row count: 0.00
> optimizer estimated cost: 8.05
>
> Right result set:
> Table Scan ResultSet for CONFIGURATIONSET_CONFIGURATIONBUNDLE at read committed isolation level using instantaneous share row locking chosen by the optimizer
> Number of opens = 4
> Rows seen = 0
> Rows filtered = 0
> Fetch Size = 16
> constructor time (milliseconds) = 0
> open time (milliseconds) = 0
> next time (milliseconds) = 0
> close time (milliseconds) = 0
>
> scan information:
> Bit set of columns fetched=All
> Number of columns fetched=2
> Number of pages visited=670838
> Number of rows qualified=0
> Number of rows visited=262429876
> Scan type=heap
> start position:
> null
> stop position:
> null
> qualifiers:
> Column[0][0] Id: 0
> Operator: =
> Ordered nulls: false
> Unknown return value: false
> Negate comparison result: false
> Column[0][1] Id: 1
> Operator: =
> Ordered nulls: false
> Unknown return value: false
> Negate comparison result: false
> optimizer estimated row count: 0.00
> optimizer estimated cost: 0.00
>
> Right result set:
> Table Scan ResultSet for INGRESS_COS_QUEUE_CONFIG_BUNDLE at read committed isolation level using instantaneous share row locking chosen by the optimizer
> Number of opens = 0
> Rows seen = 0
> Rows filtered = 0
> Fetch Size = 16
> constructor time (milliseconds) = 0
> open time (milliseconds) = 0
> next time (milliseconds) = 0
> close time (milliseconds) = 0
>
> scan information:
> start position:
> null
> stop position:
> null
> qualifiers:
> Column[0][0] Id: 0
> Operator: =
> Ordered nulls: false
> Unknown return value: false
> Negate comparison result: false
> optimizer estimated row count: 0.00
> optimizer estimated cost: 0.00
>
> Right result set:
> Table Scan ResultSet for CONFIGURATION_BUNDLE_9145E10G at read committed isolation level using instantaneous share row locking chosen by the optimizer
> Number of opens = 0
> Rows seen = 0
> Rows filtered = 0
> Fetch Size = 16
> constructor time (milliseconds) = 0
> open time (milliseconds) = 0
> next time (milliseconds) = 0
> close time (milliseconds) = 0
>
> scan information:
> start position:
> null
> stop position:
> null
> qualifiers:
> Column[0][0] Id: 0
> Operator: =
> Ordered nulls: false
> Unknown return value: false
> Negate comparison result: false
> optimizer estimated row count: 0.00
> optimizer estimated cost: 0.00
>
>
>
Re: Why is the optimizer choosing such a bad path
Posted by Mike Matrigali <mi...@sbcglobal.net>.
I would suggest seeing if this is related to DERBY-6045 or not. I
don't think this query goes through the in-list path but I am not sure,
so if you are set up you could apply the patch and see if it makes
a difference.
There is a patch available and I believe it will be going into trunk
soon.
I have been waiting for that patch to go in, and then look to see if
the underlying problem exists in other parts of the code. The problem
is that we changed update statistics to not create a statistic on a
unique single column index, and that the code above then did not do
the right thing when that stat did not exist. To see if you are running
into a similar problem you can use the workaround that Kristian
suggested in that issue:
I think specifying
derby.storage.indexStats.debug.keepDisposableStats=true *and*
regenerating statistics for the relevant tables will suffice as a
work-around for this issue.
Given that we agree the statistics for single-column unique indexes
aren't needed, do we know what puts off the optimizer?
The lack of statistics, or stale row estimates?
(I don't have time to dig into that, and I don't know what the optimizer
does in this case.)
If you set the property on your db and rerun all the statistics and see
a different result then it will point to another place in the code that
needs to change to handle a stat not existing in the catalog.
On 3/27/2013 12:16 PM, Bergquist, Brett wrote:
> Some background.
>
> I have a customer that is using an earlier release of our system that has
> Derby 10.8.2.1 installed. Because of issues like
> https://issues.apache.org/jira/browse/DERBY-5680,
> it has been running with the indexStat daemon disabled.
>
> We are going to have a new release soon and it will be installing Derby 10.9.1.0 with the indexStat
> daemon enabled. I recently got a copy of the customer's database (132Gb) and ran into
> a very long query. I manually ran SYS_UTIL.SYSCS_UPDATE_STATISTICS on all of the tables
> in the query to ensure that the statistics are up to date.
>
> The tables in the query look like:
>
> // 62,908,433 Rows
> CREATE TABLE "CORE_V1"."CONFIGURATIONSET_CONFIGURATIONBUNDLE"
> (
> CONFIGURATIONBUNDLE_ID int NOT NULL,
> CONFIGURATIONSET_ID int NOT NULL,
> CONSTRAINT CONFIGURATIONSET_CONFIGURATIONBUNDLE_PK PRIMARY KEY (CONFIGURATIONBUNDLE_ID,CONFIGURATIONSET_ID)
> );
> ALTER TABLE "CORE_V1"."CONFIGURATIONSET_CONFIGURATIONBUNDLE"
> ADD CONSTRAINT CONFIGURATIONSET_CONFIGURATIONBUNDLE_FK_2
> FOREIGN KEY (CONFIGURATIONSET_ID)
> REFERENCES "CORE_V1"."CONFIGURATION_SET"(ID);
> ALTER TABLE "CORE_V1"."CONFIGURATIONSET_CONFIGURATIONBUNDLE"
> ADD CONSTRAINT CONFIGURATIONSET_CONFIGURATIONBUNDLE_FK_1
> FOREIGN KEY (CONFIGURATIONBUNDLE_ID)
> REFERENCES "CORE_V1"."CONFIGURATION_BUNDLE"(ID);
> CREATE INDEX SQL100922214558160 ON "CORE_V1"."CONFIGURATIONSET_CONFIGURATIONBUNDLE"(CONFIGURATIONSET_ID);
> CREATE INDEX SQL100922215312050 ON "CORE_V1"."CONFIGURATIONSET_CONFIGURATIONBUNDLE"(CONFIGURATIONBUNDLE_ID);
> CREATE UNIQUE INDEX SQL081029110254290 ON "CORE_V1"."CONFIGURATIONSET_CONFIGURATIONBUNDLE"
> (
> CONFIGURATIONBUNDLE_ID,
> CONFIGURATIONSET_ID
> );
>
> // 4 Rows
> CREATE TABLE "PKG_9145E10G"."INGRESS_COS_QUEUE_CONFIG_BUNDLE"
> (
> ID int PRIMARY KEY NOT NULL,
> LLQ_CONFIG_ENTRY_ID int NOT NULL
> );
> ALTER TABLE "PKG_9145E10G"."INGRESS_COS_QUEUE_CONFIG_BUNDLE"
> ADD CONSTRAINT INGRESS_COS_QUEUE_CONFIG_BUNDLE_FK_2
> FOREIGN KEY (LLQ_CONFIG_ENTRY_ID)
> REFERENCES "PKG_9145E10G"."INGRESS_COS_QUEUE_CONFIG_ENTRY"(ID);
> ALTER TABLE "PKG_9145E10G"."INGRESS_COS_QUEUE_CONFIG_BUNDLE"
> ADD CONSTRAINT INGRESS_COS_QUEUE_CONFIG_BUNDLE_FK_1
> FOREIGN KEY (ID)
> REFERENCES "CORE_V1"."CONFIGURATION_BUNDLE"(ID);
> CREATE INDEX SQL130327093508050 ON "PKG_9145E10G"."INGRESS_COS_QUEUE_CONFIG_BUNDLE"(ID);
> CREATE INDEX SQL130327093508060 ON "PKG_9145E10G"."INGRESS_COS_QUEUE_CONFIG_BUNDLE"(LLQ_CONFIG_ENTRY_ID);
> CREATE UNIQUE INDEX SQL130327093437740 ON "PKG_9145E10G"."INGRESS_COS_QUEUE_CONFIG_BUNDLE"(ID);
>
> // 197,363 Rows
> CREATE TABLE "PKG_9145E10G"."CONFIGURATION_BUNDLE_9145E10G"
> (
> ID int PRIMARY KEY NOT NULL
> );
> ALTER TABLE "PKG_9145E10G"."CONFIGURATION_BUNDLE_9145E10G"
> ADD CONSTRAINT CONFIGURATION_BUNDLE_9145E10G_FK_1
> FOREIGN KEY (ID)
> REFERENCES "CORE_V1"."CONFIGURATION_BUNDLE"(ID);
> CREATE UNIQUE INDEX SQL100226025356610 ON "PKG_9145E10G"."CONFIGURATION_BUNDLE_9145E10G"(ID);
> CREATE INDEX SQL100922215631540 ON "PKG_9145E10G"."CONFIGURATION_BUNDLE_9145E10G"(ID);
>
> // 6,740,327 Rows
> CREATE TABLE "CORE_V1"."CONFIGURATION_BUNDLE"
> (
> DTYPE varchar(64),
> OPLOCK int DEFAULT 0 NOT NULL,
> BUNDLE_NAME varchar(64) NOT NULL,
> ID int PRIMARY KEY NOT NULL
> );
> CREATE INDEX CONFIGURATION_BUNDLE_IX_2 ON "CORE_V1"."CONFIGURATION_BUNDLE"(BUNDLE_NAME);
> CREATE INDEX CONFIGURATION_BUNDLE_IX_1 ON "CORE_V1"."CONFIGURATION_BUNDLE"(DTYPE);
> CREATE UNIQUE INDEX SQL100922215131580 ON "CORE_V1"."CONFIGURATION_BUNDLE"(ID);
>
>
> For some reason, the optimizer is doing a table scan across the CORE_V1.CONFIGURATIONSET_CONFIGURATIONBUNDLE table
> which has 64 million rows and it even goes across this 4 times!.
>
> One issue is that this query is generated by Eclipselink (JPA) and I have no control on the query generation.
>
> So any ideas on why it would chose this path and what I might be able to do about it? In playing
> around and trying to find the issue, I notice that if I remove the
>
> t0.DTYPE = 'INGRESS_COS_QUEUE_CONFIG_BUNDLE_9145E10G')
>
> constraint, then the query returns 0 rows (it should even with this constraint as there are no rows
> that are acceptable) and returns them in about .05 seconds. Note CORE_V1.CONFIGURATION_BUNDLE does
> have a non-unique index on DTYPE.
>
> Ok, just on a whim, I removed the index on DTYPE and the query came back .06 seconds. That column is used
> by Eclipselink in determining which of a "derived" object to return so I don't have much control on it.
>
> ----
> Statement Name:
> SQL_CURLH000C1
> Statement Text:
> SELECT t0.ID, t0.DTYPE, t0.BUNDLE_NAME, t0.OPLOCK, t1.ID, t2.ID, t2.LLQ_CONFIG_ENTRY_ID FROM CORE_V1.CONFIGURATIONSET_CONFIGURATIONBUNDLE t3, PKG_9145E10G.INGRESS_COS_QUEUE_CONFIG_BUNDLE t2, PKG_9145E10G.CONFIGURATION_BUNDLE_9145E10G t1, CORE_V1.CONFIGURATION_BUNDLE t0 WHERE (((t3.CONFIGURATIONSET_ID = 4000) AND (t0.ID = t3.CONFIGURATIONBUNDLE_ID)) AND (((t2.ID = t0.ID) AND (t1.ID = t0.ID)) AND (t0.DTYPE = 'INGRESS_COS_QUEUE_CONFIG_BUNDLE_9145E10G')))
> Parse Time: 0
> Bind Time: 0
> Optimize Time: 0
> Generate Time: 0
> Compile Time: 0
> Execute Time: 0
> Begin Compilation Timestamp : null
> End Compilation Timestamp : null
> Begin Execution Timestamp : null
> End Execution Timestamp : null
> Statement Execution Plan Text:
> Project-Restrict ResultSet (9):
> Number of opens = 1
> Rows seen = 0
> Rows filtered = 0
> restriction = false
> projection = true
> constructor time (milliseconds) = 0
> open time (milliseconds) = 0
> next time (milliseconds) = 0
> close time (milliseconds) = 0
> restriction time (milliseconds) = 0
> projection time (milliseconds) = 0
> optimizer estimated row count: 0.00
> optimizer estimated cost: 8.05
> Source result set:
> Nested Loop Join ResultSet:
> Number of opens = 1
> Rows seen from the left = 0
> Rows seen from the right = 0
> Rows filtered = 0
> Rows returned = 0
> constructor time (milliseconds) = 0
> open time (milliseconds) = 0
> next time (milliseconds) = 0
> close time (milliseconds) = 0
> optimizer estimated row count: 0.00
> optimizer estimated cost: 8.05
> Left result set:
> Nested Loop Join ResultSet:
> Number of opens = 1
> Rows seen from the left = 0
> Rows seen from the right = 0
> Rows filtered = 0
> Rows returned = 0
> constructor time (milliseconds) = 0
> open time (milliseconds) = 0
> next time (milliseconds) = 0
> close time (milliseconds) = 0
> optimizer estimated row count: 0.00
> optimizer estimated cost: 8.05
> Left result set:
> Nested Loop Join ResultSet:
> Number of opens = 1
> Rows seen from the left = 4
> Rows seen from the right = 0
> Rows filtered = 0
> Rows returned = 0
> constructor time (milliseconds) = 0
> open time (milliseconds) = 0
> next time (milliseconds) = 0
> close time (milliseconds) = 0
> optimizer estimated row count: 0.00
> optimizer estimated cost: 8.05
> Left result set:
> Index Row to Base Row ResultSet for CONFIGURATION_BUNDLE:
> Number of opens = 1
> Rows seen = 4
> Columns accessed from heap = {0, 1, 2, 3}
> constructor time (milliseconds) = 0
> open time (milliseconds) = 0
> next time (milliseconds) = 0
> close time (milliseconds) = 0
> optimizer estimated row count: 0.00
> optimizer estimated cost: 8.05
> Index Scan ResultSet for CONFIGURATION_BUNDLE using index CONFIGURATION_BUNDLE_IX_1 at read committed isolation level using instantaneous share row locking chosen by the optimizer
> Number of opens = 1
> Rows seen = 4
> Rows filtered = 0
> Fetch Size = 16
> constructor time (milliseconds) = 0
> open time (milliseconds) = 0
> next time (milliseconds) = 0
> close time (milliseconds) = 0
> next time in milliseconds/row = 0
>
> scan information:
> Bit set of columns fetched=All
> Number of columns fetched=2
> Number of deleted rows visited=0
> Number of pages visited=5
> Number of rows qualified=4
> Number of rows visited=5
> Scan type=btree
> Tree height=5
> start position:
> >= on first 1 column(s).
> Ordered null semantics on the following columns:
> stop position:
> > on first 1 column(s).
> Ordered null semantics on the following columns:
> qualifiers:
> None
> optimizer estimated row count: 0.00
> optimizer estimated cost: 8.05
>
> Right result set:
> Table Scan ResultSet for CONFIGURATIONSET_CONFIGURATIONBUNDLE at read committed isolation level using instantaneous share row locking chosen by the optimizer
> Number of opens = 4
> Rows seen = 0
> Rows filtered = 0
> Fetch Size = 16
> constructor time (milliseconds) = 0
> open time (milliseconds) = 0
> next time (milliseconds) = 0
> close time (milliseconds) = 0
>
> scan information:
> Bit set of columns fetched=All
> Number of columns fetched=2
> Number of pages visited=670838
> Number of rows qualified=0
> Number of rows visited=262429876
> Scan type=heap
> start position:
> null
> stop position:
> null
> qualifiers:
> Column[0][0] Id: 0
> Operator: =
> Ordered nulls: false
> Unknown return value: false
> Negate comparison result: false
> Column[0][1] Id: 1
> Operator: =
> Ordered nulls: false
> Unknown return value: false
> Negate comparison result: false
> optimizer estimated row count: 0.00
> optimizer estimated cost: 0.00
>
> Right result set:
> Table Scan ResultSet for INGRESS_COS_QUEUE_CONFIG_BUNDLE at read committed isolation level using instantaneous share row locking chosen by the optimizer
> Number of opens = 0
> Rows seen = 0
> Rows filtered = 0
> Fetch Size = 16
> constructor time (milliseconds) = 0
> open time (milliseconds) = 0
> next time (milliseconds) = 0
> close time (milliseconds) = 0
>
> scan information:
> start position:
> null
> stop position:
> null
> qualifiers:
> Column[0][0] Id: 0
> Operator: =
> Ordered nulls: false
> Unknown return value: false
> Negate comparison result: false
> optimizer estimated row count: 0.00
> optimizer estimated cost: 0.00
>
> Right result set:
> Table Scan ResultSet for CONFIGURATION_BUNDLE_9145E10G at read committed isolation level using instantaneous share row locking chosen by the optimizer
> Number of opens = 0
> Rows seen = 0
> Rows filtered = 0
> Fetch Size = 16
> constructor time (milliseconds) = 0
> open time (milliseconds) = 0
> next time (milliseconds) = 0
> close time (milliseconds) = 0
>
> scan information:
> start position:
> null
> stop position:
> null
> qualifiers:
> Column[0][0] Id: 0
> Operator: =
> Ordered nulls: false
> Unknown return value: false
> Negate comparison result: false
> optimizer estimated row count: 0.00
> optimizer estimated cost: 0.00
>
>
>
RE: Why is the optimizer choosing such a bad path
Posted by "Bergquist, Brett" <BB...@canoga.com>.
Also note that I ran
VALUES SYSCS_UTIL.SYSCS_CHECK_TABLE('CORE_V1', 'CONFIGURATION_BUNDLE')
Before dropping and recreating the index and this returned '1'.
-----Original Message-----
From: Bergquist, Brett [mailto:BBergquist@canoga.com]
Sent: Wednesday, March 27, 2013 3:52 PM
To: derby-dev@db.apache.org
Subject: RE: Why is the optimizer choosing such a bad path
Another update. On a whim, I dropped and recreated:
CREATE INDEX CONFIGURATION_BUNDLE_IX_1 ON "CORE_V1"."CONFIGURATION_BUNDLE"(DTYPE);
And then the query returns in a fraction of a second.
-----Original Message-----
From: Bergquist, Brett [mailto:BBergquist@canoga.com]
Sent: Wednesday, March 27, 2013 3:17 PM
To: derby-dev@db.apache.org
Subject: Why is the optimizer choosing such a bad path
Some background.
I have a customer that is using an earlier release of our system that has
Derby 10.8.2.1 installed. Because of issues like
https://issues.apache.org/jira/browse/DERBY-5680,
it has been running with the indexStat daemon disabled.
We are going to have a new release soon and it will be installing Derby 10.9.1.0 with the indexStat
daemon enabled. I recently got a copy of the customer's database (132Gb) and ran into
a very long query. I manually ran SYS_UTIL.SYSCS_UPDATE_STATISTICS on all of the tables
in the query to ensure that the statistics are up to date.
The tables in the query look like:
// 62,908,433 Rows
CREATE TABLE "CORE_V1"."CONFIGURATIONSET_CONFIGURATIONBUNDLE"
(
CONFIGURATIONBUNDLE_ID int NOT NULL,
CONFIGURATIONSET_ID int NOT NULL,
CONSTRAINT CONFIGURATIONSET_CONFIGURATIONBUNDLE_PK PRIMARY KEY (CONFIGURATIONBUNDLE_ID,CONFIGURATIONSET_ID)
);
ALTER TABLE "CORE_V1"."CONFIGURATIONSET_CONFIGURATIONBUNDLE"
ADD CONSTRAINT CONFIGURATIONSET_CONFIGURATIONBUNDLE_FK_2
FOREIGN KEY (CONFIGURATIONSET_ID)
REFERENCES "CORE_V1"."CONFIGURATION_SET"(ID);
ALTER TABLE "CORE_V1"."CONFIGURATIONSET_CONFIGURATIONBUNDLE"
ADD CONSTRAINT CONFIGURATIONSET_CONFIGURATIONBUNDLE_FK_1
FOREIGN KEY (CONFIGURATIONBUNDLE_ID)
REFERENCES "CORE_V1"."CONFIGURATION_BUNDLE"(ID);
CREATE INDEX SQL100922214558160 ON "CORE_V1"."CONFIGURATIONSET_CONFIGURATIONBUNDLE"(CONFIGURATIONSET_ID);
CREATE INDEX SQL100922215312050 ON "CORE_V1"."CONFIGURATIONSET_CONFIGURATIONBUNDLE"(CONFIGURATIONBUNDLE_ID);
CREATE UNIQUE INDEX SQL081029110254290 ON "CORE_V1"."CONFIGURATIONSET_CONFIGURATIONBUNDLE"
(
CONFIGURATIONBUNDLE_ID,
CONFIGURATIONSET_ID
);
// 4 Rows
CREATE TABLE "PKG_9145E10G"."INGRESS_COS_QUEUE_CONFIG_BUNDLE"
(
ID int PRIMARY KEY NOT NULL,
LLQ_CONFIG_ENTRY_ID int NOT NULL
);
ALTER TABLE "PKG_9145E10G"."INGRESS_COS_QUEUE_CONFIG_BUNDLE"
ADD CONSTRAINT INGRESS_COS_QUEUE_CONFIG_BUNDLE_FK_2
FOREIGN KEY (LLQ_CONFIG_ENTRY_ID)
REFERENCES "PKG_9145E10G"."INGRESS_COS_QUEUE_CONFIG_ENTRY"(ID);
ALTER TABLE "PKG_9145E10G"."INGRESS_COS_QUEUE_CONFIG_BUNDLE"
ADD CONSTRAINT INGRESS_COS_QUEUE_CONFIG_BUNDLE_FK_1
FOREIGN KEY (ID)
REFERENCES "CORE_V1"."CONFIGURATION_BUNDLE"(ID);
CREATE INDEX SQL130327093508050 ON "PKG_9145E10G"."INGRESS_COS_QUEUE_CONFIG_BUNDLE"(ID);
CREATE INDEX SQL130327093508060 ON "PKG_9145E10G"."INGRESS_COS_QUEUE_CONFIG_BUNDLE"(LLQ_CONFIG_ENTRY_ID);
CREATE UNIQUE INDEX SQL130327093437740 ON "PKG_9145E10G"."INGRESS_COS_QUEUE_CONFIG_BUNDLE"(ID);
// 197,363 Rows
CREATE TABLE "PKG_9145E10G"."CONFIGURATION_BUNDLE_9145E10G"
(
ID int PRIMARY KEY NOT NULL
);
ALTER TABLE "PKG_9145E10G"."CONFIGURATION_BUNDLE_9145E10G"
ADD CONSTRAINT CONFIGURATION_BUNDLE_9145E10G_FK_1
FOREIGN KEY (ID)
REFERENCES "CORE_V1"."CONFIGURATION_BUNDLE"(ID);
CREATE UNIQUE INDEX SQL100226025356610 ON "PKG_9145E10G"."CONFIGURATION_BUNDLE_9145E10G"(ID);
CREATE INDEX SQL100922215631540 ON "PKG_9145E10G"."CONFIGURATION_BUNDLE_9145E10G"(ID);
// 6,740,327 Rows
CREATE TABLE "CORE_V1"."CONFIGURATION_BUNDLE"
(
DTYPE varchar(64),
OPLOCK int DEFAULT 0 NOT NULL,
BUNDLE_NAME varchar(64) NOT NULL,
ID int PRIMARY KEY NOT NULL
);
CREATE INDEX CONFIGURATION_BUNDLE_IX_2 ON "CORE_V1"."CONFIGURATION_BUNDLE"(BUNDLE_NAME);
CREATE INDEX CONFIGURATION_BUNDLE_IX_1 ON "CORE_V1"."CONFIGURATION_BUNDLE"(DTYPE);
CREATE UNIQUE INDEX SQL100922215131580 ON "CORE_V1"."CONFIGURATION_BUNDLE"(ID);
For some reason, the optimizer is doing a table scan across the CORE_V1.CONFIGURATIONSET_CONFIGURATIONBUNDLE table
which has 64 million rows and it even goes across this 4 times!.
One issue is that this query is generated by Eclipselink (JPA) and I have no control on the query generation.
So any ideas on why it would chose this path and what I might be able to do about it? In playing
around and trying to find the issue, I notice that if I remove the
t0.DTYPE = 'INGRESS_COS_QUEUE_CONFIG_BUNDLE_9145E10G')
constraint, then the query returns 0 rows (it should even with this constraint as there are no rows
that are acceptable) and returns them in about .05 seconds. Note CORE_V1.CONFIGURATION_BUNDLE does
have a non-unique index on DTYPE.
Ok, just on a whim, I removed the index on DTYPE and the query came back .06 seconds. That column is used by Eclipselink in determining which of a "derived" object to return so I don't have much control on it.
----
Statement Name:
SQL_CURLH000C1
Statement Text:
SELECT t0.ID, t0.DTYPE, t0.BUNDLE_NAME, t0.OPLOCK, t1.ID, t2.ID, t2.LLQ_CONFIG_ENTRY_ID FROM CORE_V1.CONFIGURATIONSET_CONFIGURATIONBUNDLE t3, PKG_9145E10G.INGRESS_COS_QUEUE_CONFIG_BUNDLE t2, PKG_9145E10G.CONFIGURATION_BUNDLE_9145E10G t1, CORE_V1.CONFIGURATION_BUNDLE t0 WHERE (((t3.CONFIGURATIONSET_ID = 4000) AND (t0.ID = t3.CONFIGURATIONBUNDLE_ID)) AND (((t2.ID = t0.ID) AND (t1.ID = t0.ID)) AND (t0.DTYPE = 'INGRESS_COS_QUEUE_CONFIG_BUNDLE_9145E10G')))
Parse Time: 0
Bind Time: 0
Optimize Time: 0
Generate Time: 0
Compile Time: 0
Execute Time: 0
Begin Compilation Timestamp : null
End Compilation Timestamp : null
Begin Execution Timestamp : null
End Execution Timestamp : null
Statement Execution Plan Text:
Project-Restrict ResultSet (9):
Number of opens = 1
Rows seen = 0
Rows filtered = 0
restriction = false
projection = true
constructor time (milliseconds) = 0
open time (milliseconds) = 0
next time (milliseconds) = 0
close time (milliseconds) = 0
restriction time (milliseconds) = 0
projection time (milliseconds) = 0
optimizer estimated row count: 0.00
optimizer estimated cost: 8.05
Source result set:
Nested Loop Join ResultSet:
Number of opens = 1
Rows seen from the left = 0
Rows seen from the right = 0
Rows filtered = 0
Rows returned = 0
constructor time (milliseconds) = 0
open time (milliseconds) = 0
next time (milliseconds) = 0
close time (milliseconds) = 0
optimizer estimated row count: 0.00
optimizer estimated cost: 8.05
Left result set:
Nested Loop Join ResultSet:
Number of opens = 1
Rows seen from the left = 0
Rows seen from the right = 0
Rows filtered = 0
Rows returned = 0
constructor time (milliseconds) = 0
open time (milliseconds) = 0
next time (milliseconds) = 0
close time (milliseconds) = 0
optimizer estimated row count: 0.00
optimizer estimated cost: 8.05
Left result set:
Nested Loop Join ResultSet:
Number of opens = 1
Rows seen from the left = 4
Rows seen from the right = 0
Rows filtered = 0
Rows returned = 0
constructor time (milliseconds) = 0
open time (milliseconds) = 0
next time (milliseconds) = 0
close time (milliseconds) = 0
optimizer estimated row count: 0.00
optimizer estimated cost: 8.05
Left result set:
Index Row to Base Row ResultSet for CONFIGURATION_BUNDLE:
Number of opens = 1
Rows seen = 4
Columns accessed from heap = {0, 1, 2, 3}
constructor time (milliseconds) = 0
open time (milliseconds) = 0
next time (milliseconds) = 0
close time (milliseconds) = 0
optimizer estimated row count: 0.00
optimizer estimated cost: 8.05
Index Scan ResultSet for CONFIGURATION_BUNDLE using index CONFIGURATION_BUNDLE_IX_1 at read committed isolation level using instantaneous share row locking chosen by the optimizer
Number of opens = 1
Rows seen = 4
Rows filtered = 0
Fetch Size = 16
constructor time (milliseconds) = 0
open time (milliseconds) = 0
next time (milliseconds) = 0
close time (milliseconds) = 0
next time in milliseconds/row = 0
scan information:
Bit set of columns fetched=All
Number of columns fetched=2
Number of deleted rows visited=0
Number of pages visited=5
Number of rows qualified=4
Number of rows visited=5
Scan type=btree
Tree height=5
start position:
>= on first 1 column(s).
Ordered null semantics on the following columns:
stop position:
> on first 1 column(s).
Ordered null semantics on the following columns:
qualifiers:
None
optimizer estimated row count: 0.00
optimizer estimated cost: 8.05
Right result set:
Table Scan ResultSet for CONFIGURATIONSET_CONFIGURATIONBUNDLE at read committed isolation level using instantaneous share row locking chosen by the optimizer
Number of opens = 4
Rows seen = 0
Rows filtered = 0
Fetch Size = 16
constructor time (milliseconds) = 0
open time (milliseconds) = 0
next time (milliseconds) = 0
close time (milliseconds) = 0
scan information:
Bit set of columns fetched=All
Number of columns fetched=2
Number of pages visited=670838
Number of rows qualified=0
Number of rows visited=262429876
Scan type=heap
start position:
null
stop position:
null
qualifiers:
Column[0][0] Id: 0
Operator: =
Ordered nulls: false
Unknown return value: false
Negate comparison result: false
Column[0][1] Id: 1
Operator: =
Ordered nulls: false
Unknown return value: false
Negate comparison result: false
optimizer estimated row count: 0.00
optimizer estimated cost: 0.00
Right result set:
Table Scan ResultSet for INGRESS_COS_QUEUE_CONFIG_BUNDLE at read committed isolation level using instantaneous share row locking chosen by the optimizer
Number of opens = 0
Rows seen = 0
Rows filtered = 0
Fetch Size = 16
constructor time (milliseconds) = 0
open time (milliseconds) = 0
next time (milliseconds) = 0
close time (milliseconds) = 0
scan information:
start position:
null
stop position:
null
qualifiers:
Column[0][0] Id: 0
Operator: =
Ordered nulls: false
Unknown return value: false
Negate comparison result: false
optimizer estimated row count: 0.00
optimizer estimated cost: 0.00
Right result set:
Table Scan ResultSet for CONFIGURATION_BUNDLE_9145E10G at read committed isolation level using instantaneous share row locking chosen by the optimizer
Number of opens = 0
Rows seen = 0
Rows filtered = 0
Fetch Size = 16
constructor time (milliseconds) = 0
open time (milliseconds) = 0
next time (milliseconds) = 0
close time (milliseconds) = 0
scan information:
start position:
null
stop position:
null
qualifiers:
Column[0][0] Id: 0
Operator: =
Ordered nulls: false
Unknown return value: false
Negate comparison result: false
optimizer estimated row count: 0.00
optimizer estimated cost: 0.00
RE: Why is the optimizer choosing such a bad path
Posted by "Bergquist, Brett" <BB...@canoga.com>.
Another update. On a whim, I dropped and recreated:
CREATE INDEX CONFIGURATION_BUNDLE_IX_1 ON "CORE_V1"."CONFIGURATION_BUNDLE"(DTYPE);
And then the query returns in a fraction of a second.
-----Original Message-----
From: Bergquist, Brett [mailto:BBergquist@canoga.com]
Sent: Wednesday, March 27, 2013 3:17 PM
To: derby-dev@db.apache.org
Subject: Why is the optimizer choosing such a bad path
Some background.
I have a customer that is using an earlier release of our system that has
Derby 10.8.2.1 installed. Because of issues like
https://issues.apache.org/jira/browse/DERBY-5680,
it has been running with the indexStat daemon disabled.
We are going to have a new release soon and it will be installing Derby 10.9.1.0 with the indexStat
daemon enabled. I recently got a copy of the customer's database (132Gb) and ran into
a very long query. I manually ran SYS_UTIL.SYSCS_UPDATE_STATISTICS on all of the tables
in the query to ensure that the statistics are up to date.
The tables in the query look like:
// 62,908,433 Rows
CREATE TABLE "CORE_V1"."CONFIGURATIONSET_CONFIGURATIONBUNDLE"
(
CONFIGURATIONBUNDLE_ID int NOT NULL,
CONFIGURATIONSET_ID int NOT NULL,
CONSTRAINT CONFIGURATIONSET_CONFIGURATIONBUNDLE_PK PRIMARY KEY (CONFIGURATIONBUNDLE_ID,CONFIGURATIONSET_ID)
);
ALTER TABLE "CORE_V1"."CONFIGURATIONSET_CONFIGURATIONBUNDLE"
ADD CONSTRAINT CONFIGURATIONSET_CONFIGURATIONBUNDLE_FK_2
FOREIGN KEY (CONFIGURATIONSET_ID)
REFERENCES "CORE_V1"."CONFIGURATION_SET"(ID);
ALTER TABLE "CORE_V1"."CONFIGURATIONSET_CONFIGURATIONBUNDLE"
ADD CONSTRAINT CONFIGURATIONSET_CONFIGURATIONBUNDLE_FK_1
FOREIGN KEY (CONFIGURATIONBUNDLE_ID)
REFERENCES "CORE_V1"."CONFIGURATION_BUNDLE"(ID);
CREATE INDEX SQL100922214558160 ON "CORE_V1"."CONFIGURATIONSET_CONFIGURATIONBUNDLE"(CONFIGURATIONSET_ID);
CREATE INDEX SQL100922215312050 ON "CORE_V1"."CONFIGURATIONSET_CONFIGURATIONBUNDLE"(CONFIGURATIONBUNDLE_ID);
CREATE UNIQUE INDEX SQL081029110254290 ON "CORE_V1"."CONFIGURATIONSET_CONFIGURATIONBUNDLE"
(
CONFIGURATIONBUNDLE_ID,
CONFIGURATIONSET_ID
);
// 4 Rows
CREATE TABLE "PKG_9145E10G"."INGRESS_COS_QUEUE_CONFIG_BUNDLE"
(
ID int PRIMARY KEY NOT NULL,
LLQ_CONFIG_ENTRY_ID int NOT NULL
);
ALTER TABLE "PKG_9145E10G"."INGRESS_COS_QUEUE_CONFIG_BUNDLE"
ADD CONSTRAINT INGRESS_COS_QUEUE_CONFIG_BUNDLE_FK_2
FOREIGN KEY (LLQ_CONFIG_ENTRY_ID)
REFERENCES "PKG_9145E10G"."INGRESS_COS_QUEUE_CONFIG_ENTRY"(ID);
ALTER TABLE "PKG_9145E10G"."INGRESS_COS_QUEUE_CONFIG_BUNDLE"
ADD CONSTRAINT INGRESS_COS_QUEUE_CONFIG_BUNDLE_FK_1
FOREIGN KEY (ID)
REFERENCES "CORE_V1"."CONFIGURATION_BUNDLE"(ID);
CREATE INDEX SQL130327093508050 ON "PKG_9145E10G"."INGRESS_COS_QUEUE_CONFIG_BUNDLE"(ID);
CREATE INDEX SQL130327093508060 ON "PKG_9145E10G"."INGRESS_COS_QUEUE_CONFIG_BUNDLE"(LLQ_CONFIG_ENTRY_ID);
CREATE UNIQUE INDEX SQL130327093437740 ON "PKG_9145E10G"."INGRESS_COS_QUEUE_CONFIG_BUNDLE"(ID);
// 197,363 Rows
CREATE TABLE "PKG_9145E10G"."CONFIGURATION_BUNDLE_9145E10G"
(
ID int PRIMARY KEY NOT NULL
);
ALTER TABLE "PKG_9145E10G"."CONFIGURATION_BUNDLE_9145E10G"
ADD CONSTRAINT CONFIGURATION_BUNDLE_9145E10G_FK_1
FOREIGN KEY (ID)
REFERENCES "CORE_V1"."CONFIGURATION_BUNDLE"(ID);
CREATE UNIQUE INDEX SQL100226025356610 ON "PKG_9145E10G"."CONFIGURATION_BUNDLE_9145E10G"(ID);
CREATE INDEX SQL100922215631540 ON "PKG_9145E10G"."CONFIGURATION_BUNDLE_9145E10G"(ID);
// 6,740,327 Rows
CREATE TABLE "CORE_V1"."CONFIGURATION_BUNDLE"
(
DTYPE varchar(64),
OPLOCK int DEFAULT 0 NOT NULL,
BUNDLE_NAME varchar(64) NOT NULL,
ID int PRIMARY KEY NOT NULL
);
CREATE INDEX CONFIGURATION_BUNDLE_IX_2 ON "CORE_V1"."CONFIGURATION_BUNDLE"(BUNDLE_NAME);
CREATE INDEX CONFIGURATION_BUNDLE_IX_1 ON "CORE_V1"."CONFIGURATION_BUNDLE"(DTYPE);
CREATE UNIQUE INDEX SQL100922215131580 ON "CORE_V1"."CONFIGURATION_BUNDLE"(ID);
For some reason, the optimizer is doing a table scan across the CORE_V1.CONFIGURATIONSET_CONFIGURATIONBUNDLE table
which has 64 million rows and it even goes across this 4 times!.
One issue is that this query is generated by Eclipselink (JPA) and I have no control on the query generation.
So any ideas on why it would chose this path and what I might be able to do about it? In playing
around and trying to find the issue, I notice that if I remove the
t0.DTYPE = 'INGRESS_COS_QUEUE_CONFIG_BUNDLE_9145E10G')
constraint, then the query returns 0 rows (it should even with this constraint as there are no rows
that are acceptable) and returns them in about .05 seconds. Note CORE_V1.CONFIGURATION_BUNDLE does
have a non-unique index on DTYPE.
Ok, just on a whim, I removed the index on DTYPE and the query came back .06 seconds. That column is used by Eclipselink in determining which of a "derived" object to return so I don't have much control on it.
----
Statement Name:
SQL_CURLH000C1
Statement Text:
SELECT t0.ID, t0.DTYPE, t0.BUNDLE_NAME, t0.OPLOCK, t1.ID, t2.ID, t2.LLQ_CONFIG_ENTRY_ID FROM CORE_V1.CONFIGURATIONSET_CONFIGURATIONBUNDLE t3, PKG_9145E10G.INGRESS_COS_QUEUE_CONFIG_BUNDLE t2, PKG_9145E10G.CONFIGURATION_BUNDLE_9145E10G t1, CORE_V1.CONFIGURATION_BUNDLE t0 WHERE (((t3.CONFIGURATIONSET_ID = 4000) AND (t0.ID = t3.CONFIGURATIONBUNDLE_ID)) AND (((t2.ID = t0.ID) AND (t1.ID = t0.ID)) AND (t0.DTYPE = 'INGRESS_COS_QUEUE_CONFIG_BUNDLE_9145E10G')))
Parse Time: 0
Bind Time: 0
Optimize Time: 0
Generate Time: 0
Compile Time: 0
Execute Time: 0
Begin Compilation Timestamp : null
End Compilation Timestamp : null
Begin Execution Timestamp : null
End Execution Timestamp : null
Statement Execution Plan Text:
Project-Restrict ResultSet (9):
Number of opens = 1
Rows seen = 0
Rows filtered = 0
restriction = false
projection = true
constructor time (milliseconds) = 0
open time (milliseconds) = 0
next time (milliseconds) = 0
close time (milliseconds) = 0
restriction time (milliseconds) = 0
projection time (milliseconds) = 0
optimizer estimated row count: 0.00
optimizer estimated cost: 8.05
Source result set:
Nested Loop Join ResultSet:
Number of opens = 1
Rows seen from the left = 0
Rows seen from the right = 0
Rows filtered = 0
Rows returned = 0
constructor time (milliseconds) = 0
open time (milliseconds) = 0
next time (milliseconds) = 0
close time (milliseconds) = 0
optimizer estimated row count: 0.00
optimizer estimated cost: 8.05
Left result set:
Nested Loop Join ResultSet:
Number of opens = 1
Rows seen from the left = 0
Rows seen from the right = 0
Rows filtered = 0
Rows returned = 0
constructor time (milliseconds) = 0
open time (milliseconds) = 0
next time (milliseconds) = 0
close time (milliseconds) = 0
optimizer estimated row count: 0.00
optimizer estimated cost: 8.05
Left result set:
Nested Loop Join ResultSet:
Number of opens = 1
Rows seen from the left = 4
Rows seen from the right = 0
Rows filtered = 0
Rows returned = 0
constructor time (milliseconds) = 0
open time (milliseconds) = 0
next time (milliseconds) = 0
close time (milliseconds) = 0
optimizer estimated row count: 0.00
optimizer estimated cost: 8.05
Left result set:
Index Row to Base Row ResultSet for CONFIGURATION_BUNDLE:
Number of opens = 1
Rows seen = 4
Columns accessed from heap = {0, 1, 2, 3}
constructor time (milliseconds) = 0
open time (milliseconds) = 0
next time (milliseconds) = 0
close time (milliseconds) = 0
optimizer estimated row count: 0.00
optimizer estimated cost: 8.05
Index Scan ResultSet for CONFIGURATION_BUNDLE using index CONFIGURATION_BUNDLE_IX_1 at read committed isolation level using instantaneous share row locking chosen by the optimizer
Number of opens = 1
Rows seen = 4
Rows filtered = 0
Fetch Size = 16
constructor time (milliseconds) = 0
open time (milliseconds) = 0
next time (milliseconds) = 0
close time (milliseconds) = 0
next time in milliseconds/row = 0
scan information:
Bit set of columns fetched=All
Number of columns fetched=2
Number of deleted rows visited=0
Number of pages visited=5
Number of rows qualified=4
Number of rows visited=5
Scan type=btree
Tree height=5
start position:
>= on first 1 column(s).
Ordered null semantics on the following columns:
stop position:
> on first 1 column(s).
Ordered null semantics on the following columns:
qualifiers:
None
optimizer estimated row count: 0.00
optimizer estimated cost: 8.05
Right result set:
Table Scan ResultSet for CONFIGURATIONSET_CONFIGURATIONBUNDLE at read committed isolation level using instantaneous share row locking chosen by the optimizer
Number of opens = 4
Rows seen = 0
Rows filtered = 0
Fetch Size = 16
constructor time (milliseconds) = 0
open time (milliseconds) = 0
next time (milliseconds) = 0
close time (milliseconds) = 0
scan information:
Bit set of columns fetched=All
Number of columns fetched=2
Number of pages visited=670838
Number of rows qualified=0
Number of rows visited=262429876
Scan type=heap
start position:
null
stop position:
null
qualifiers:
Column[0][0] Id: 0
Operator: =
Ordered nulls: false
Unknown return value: false
Negate comparison result: false
Column[0][1] Id: 1
Operator: =
Ordered nulls: false
Unknown return value: false
Negate comparison result: false
optimizer estimated row count: 0.00
optimizer estimated cost: 0.00
Right result set:
Table Scan ResultSet for INGRESS_COS_QUEUE_CONFIG_BUNDLE at read committed isolation level using instantaneous share row locking chosen by the optimizer
Number of opens = 0
Rows seen = 0
Rows filtered = 0
Fetch Size = 16
constructor time (milliseconds) = 0
open time (milliseconds) = 0
next time (milliseconds) = 0
close time (milliseconds) = 0
scan information:
start position:
null
stop position:
null
qualifiers:
Column[0][0] Id: 0
Operator: =
Ordered nulls: false
Unknown return value: false
Negate comparison result: false
optimizer estimated row count: 0.00
optimizer estimated cost: 0.00
Right result set:
Table Scan ResultSet for CONFIGURATION_BUNDLE_9145E10G at read committed isolation level using instantaneous share row locking chosen by the optimizer
Number of opens = 0
Rows seen = 0
Rows filtered = 0
Fetch Size = 16
constructor time (milliseconds) = 0
open time (milliseconds) = 0
next time (milliseconds) = 0
close time (milliseconds) = 0
scan information:
start position:
null
stop position:
null
qualifiers:
Column[0][0] Id: 0
Operator: =
Ordered nulls: false
Unknown return value: false
Negate comparison result: false
optimizer estimated row count: 0.00
optimizer estimated cost: 0.00
RE: Why is the optimizer choosing such a bad path
Posted by "Bergquist, Brett" <BB...@canoga.com>.
Mike, I would like to understand the "you aren't gathering the
plan with all options enabled" comment. I followed this from the Derby Tuning guide:
-- turn on RUNTIMESTATISTICS for connection:
CALL SYSCS_UTIL.SYSCS_SET_RUNTIMESTATISTICS(1);
-- execute complex query here -- step through the result set
-- access runtime statistics information:
VALUES SYSCS_UTIL.SYSCS_GET_RUNTIMESTATISTICS();
CALL SYSCS_UTIL.SYSCS_SET_RUNTIMESTATISTICS(0);
And placed my query in there. So if there is something else that needs to be done, can
you point me in the correct direction.
I am going to check the large table tonight and see if returns an error on that. How
could the optimizer have the correct row counts?
________________________________________
From: Mike Matrigali [mikem_app@sbcglobal.net]
Sent: Wednesday, March 27, 2013 6:36 PM
To: derby-dev@db.apache.org
Subject: Re: Why is the optimizer choosing such a bad path
On 3/27/2013 12:16 PM, Bergquist, Brett wrote:
> Some background.
>
> I have a customer that is using an earlier release of our system that has
> Derby 10.8.2.1 installed. Because of issues like
> https://issues.apache.org/jira/browse/DERBY-5680,
> it has been running with the indexStat daemon disabled.
>
> We are going to have a new release soon and it will be installing Derby 10.9.1.0 with the indexStat
> daemon enabled. I recently got a copy of the customer's database (132Gb) and ran into
> a very long query. I manually ran SYS_UTIL.SYSCS_UPDATE_STATISTICS on all of the tables
> in the query to ensure that the statistics are up to date.
> ...
when I look at bad query plans i usually look for estimated row counts
vs actual to see where the optimizer made some bad assumptions. The
plan you posted has a bunch of 0's. So maybe you aren't gathering the
plan with all options enabled? If optimizer actually thinks there are
0 rows in your 62 million row table that would be a problem.
Re: Why is the optimizer choosing such a bad path
Posted by Mike Matrigali <mi...@sbcglobal.net>.
On 3/27/2013 12:16 PM, Bergquist, Brett wrote:
> Some background.
>
> I have a customer that is using an earlier release of our system that has
> Derby 10.8.2.1 installed. Because of issues like
> https://issues.apache.org/jira/browse/DERBY-5680,
> it has been running with the indexStat daemon disabled.
>
> We are going to have a new release soon and it will be installing Derby 10.9.1.0 with the indexStat
> daemon enabled. I recently got a copy of the customer's database (132Gb) and ran into
> a very long query. I manually ran SYS_UTIL.SYSCS_UPDATE_STATISTICS on all of the tables
> in the query to ensure that the statistics are up to date.
> ...
when I look at bad query plans i usually look for estimated row counts
vs actual to see where the optimizer made some bad assumptions. The
plan you posted has a bunch of 0's. So maybe you aren't gathering the
plan with all options enabled? If optimizer actually thinks there are
0 rows in your 62 million row table that would be a problem.