db-derby-dev mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From "Bergquist, Brett" <BBergqu...@canoga.com>
Subject RE: Why is the optimizer choosing such a bad path
Date Thu, 28 Mar 2013 12:32:30 GMT
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
>
>
>





Mime
View raw message