Hi Brett, Looks like 1)The query correctly uses index on 10.8.2.2. 2)On 10.9, the use of derby.storage.indexStats.debug.keepDisposableStats=true hasn't caused Derby to use the index. The version of 10.9 you are using does not have a fix for DERBY-6045 but using the property should have provided an alternative to bug DERBY-6045. So may be we are running into a different problem. I realize that the db is really large but it will be helpful to have a reproducible db to debug the issue.
thanks, Mamta On Fri, Aug 23, 2013 at 11:04 AM, Bergquist, Brett <[email protected]>wrote: > I just enabled the derby.storage.indexStats.debug.keepDisposableStats=true > in derby.properties and restarted the network server. I am running with > straight 10.9.1.0 right now and have a database with exactly two tables. I > have used the "syscs_util.syscs_drop_statistics" to drop the statistics and > then uses the "syscs_util.syscs_update_statistics" to recreate the > statistics. Here is the statistics query: > > select tablename || ' (' || CONGLOMERATENAME || ')' as INDEX, > REFERENCEID, > CREATIONTIMESTAMP, > TYPE, > VALID, > COLCOUNT, > cast (STATISTICS as varchar(80)) stats, > CASE WHEN CAST(creationtimestamp AS varchar(24)) IS NULL > THEN 'Recreate Index to Initialize' > ELSE CAST(creationtimestamp AS varchar(24)) END > from sys.systables t, sys.sysconglomerates c > LEFT OUTER JOIN sys.sysstatistics s ON c.conglomerateid = s.referenceid > where t.tableid = c.tableid > and c.isindex = true and t.tabletype = 'T' > order by INDEX; > > Here is the output from that: > > INDEX REFERENCEID CREATIONTIMESTAMP TYPE VALID COLCOUNT STATS 8 > CONFIGURATION_BUNDLE3 (CONFIGURATION_BUNDLE3_IX_1) > 522b00e8-0140-ab92-f364-ffff93450f77 2013-08-23 13:54:30.812 I true 1 > numunique= > 135 numrows= 7003481 2013-08-23 13:54:30.812 > CONFIGURATION_BUNDLE3 (CONFIGURATION_BUNDLE3_IX_2) > 597e80e5-0140-ab92-f364-ffff93450f77 2013-08-23 13:54:21.516 I true 1 > numunique= > 92 numrows= 7003481 2013-08-23 13:54:21.516 > CONFIGURATION_BUNDLE3 (SQL130823102831500) > d7bd80dd-0140-ab92-f364-ffff93450f77 2013-08-23 13:54:13.129 I true 1 > numunique= > 7003481 numrows= 7003481 2013-08-23 13:54:13.129 > COSEDDROPPROFILEDSCPTABLEBUNDLE_COSEDDROPPROFILEDSCPTABLEENTRY3 > (COSEDDROPPROFILEDSCPTABLEBUNDLE_COSEDDROPPROFILEDSCPTABLEENTRY3_IX_0) > 46f7c11b-0140-ab92-f364-ffff93450f77 2013-08-23 13:57:22.96 I true 1 > numunique= > 53053312 numrows= 58248128 2013-08-23 13:57:22.96 > COSEDDROPPROFILEDSCPTABLEBUNDLE_COSEDDROPPROFILEDSCPTABLEENTRY3 > (SQL130823102836170) 4760c0fe-0140-ab92-f364-ffff93450f77 2013-08-23 > 13:55:30.662 I true 2 numunique= 58248128 numrows= 58248128 2013-08-23 > 13:55:30.662 > COSEDDROPPROFILEDSCPTABLEBUNDLE_COSEDDROPPROFILEDSCPTABLEENTRY3 > (SQL130823102836170) 4760c0fe-0140-ab92-f364-ffff93450f77 2013-08-23 > 13:55:30.661 I true 1 numunique= 910127 numrows= 58248128 2013-08-23 > 13:55:30.661 > COSEDDROPPROFILEDSCPTABLEBUNDLE_COSEDDROPPROFILEDSCPTABLEENTRY3 > (SQL130823102836240) f8e18104-0140-ab92-f364-ffff93450f77 2013-08-23 > 13:56:24.379 I true 1 numunique= 910127 numrows= 58248128 2013-08-23 > 13:56:24.379 > > > So as can be seen, the primary key backing index of CONFIGURATION_BUNDLE3 > shows that the are 7003481 unique rows > and COSEDDROPPROFILEDSCPTABLEBUNDLE_COSEDDROPPROFILEDSCPTABLEENTRY3 > shows 58248128 unique rows. > > The query that I am performing is: > > CALL SYSCS_UTIL.SYSCS_SET_RUNTIMESTATISTICS(1); > CALL SYSCS_UTIL.SYSCS_SET_STATISTICS_TIMING(1); > SELECT * FROM APP.CONFIGURATION_BUNDLE3 T1, > APP.COSEDDROPPROFILEDSCPTABLEBUNDLE_COSEDDROPPROFILEDSCPTABLEENTRY3 t0 > WHERE t1.ID = t0.COSEDDROPPROFILEDSCPTABLEBUNDLE_ID and > t0.COSEDDROPPROFILEDSCPTABLEENTRY_ID = 12344444; > VALUES SYSCS_UTIL.SYSCS_GET_RUNTIMESTATISTICS(); > CALL SYSCS_UTIL.SYSCS_SET_RUNTIMESTATISTICS(0); > CALL SYSCS_UTIL.SYSCS_SET_STATISTICS_TIMING(0); > > The optimizer plan from this is below. The plan correctly chooses to use > the index on the COSEDDROPPROFILEDSCPTABLEENTRY_ID on > the COSEDDROPPROFILEDSCPTABLEBUNDLE_COSEDDROPPROFILEDSCPTABLEENTRY3 table > but still estimates 0 rows (there is actually 1 row) and then uses a table > scan on CONFIGURATION_BUNDLE3 even though the join field > APP.CONFIGURATION_BUNDLE3.ID is the primary key. > > I have so far been able to do nothing that will cause this to operate > correctly now that it is in this state. Dropping and recreating > statistics has no effect. I will try dropping and recreating the indexes > and primary key next. > > Here is the query plan: > > Statement Name: > SQL_CURLH000C2 > Statement Text: > SELECT * FROM APP.CONFIGURATION_BUNDLE3 T1, > APP.COSEDDROPPROFILEDSCPTABLEBUNDLE_COSEDDROPPROFILEDSCPTABLEENTRY3 t0 > WHERE t1.ID = t0.COSEDDROPPROFILEDSCPTABLEBUNDLE_ID and > t0.COSEDDROPPROFILEDSCPTABLEENTRY_ID = 12344444 > Parse Time: 2 > Bind Time: 3 > Optimize Time: 16 > Generate Time: 3 > Compile Time: 24 > Execute Time: 9609 > Begin Compilation Timestamp : 2013-08-23 13:59:44.959 > End Compilation Timestamp : 2013-08-23 13:59:44.983 > Begin Execution Timestamp : 2013-08-23 13:59:44.986 > End Execution Timestamp : 2013-08-23 13:59:54.595 > Statement Execution Plan Text: > Project-Restrict ResultSet (5): > Number of opens = 1 > Rows seen = 1 > Rows filtered = 0 > restriction = false > projection = true > constructor time (milliseconds) = 0 > open time (milliseconds) = 1 > next time (milliseconds) = 9608 > close time (milliseconds) = 0 > restriction time (milliseconds) = 0 > projection time (milliseconds) = 0 > optimizer estimated row count: 0.00 > optimizer estimated cost: 7.86 > Source result set: > Nested Loop Join ResultSet: > Number of opens = 1 > Rows seen from the left = 1 > Rows seen from the right = 1 > Rows filtered = 0 > Rows returned = 1 > constructor time (milliseconds) = 0 > open time (milliseconds) = 1 > next time (milliseconds) = 9608 > close time (milliseconds) = 0 > optimizer estimated row count: 0.00 > optimizer estimated cost: 7.86 > Left result set: > Index Row to Base Row ResultSet for > COSEDDROPPROFILEDSCPTABLEBUNDLE_COSEDDROPPROFILEDSCPTABLEENTRY3: > Number of opens = 1 > Rows seen = 1 > Columns accessed from heap = {0, 1} > 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: 7.86 > Index Scan ResultSet for > COSEDDROPPROFILEDSCPTABLEBUNDLE_COSEDDROPPROFILEDSCPTABLEENTRY3 using index > COSEDDROPPROFILEDSCPTABLEBUNDLE_COSEDDROPPROFILEDSCPTABLEENTRY3_IX_0 at > read committed isolation level using instantaneous share row locking chosen > by the optimizer > Number of opens = 1 > Rows seen = 1 > 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=1 > Number of rows visited=2 > Scan type=btree > Tree height=5 > start position: > >= on first 1 column(s). > Ordered null semantics on the following columns: > 0 > stop position: > > on first 1 column(s). > Ordered null semantics on the following columns: > 0 > qualifiers: > None > optimizer estimated row count: 0.00 > optimizer estimated cost: 7.86 > > Right result set: > Table Scan ResultSet for CONFIGURATION_BUNDLE3 at read committed isolation > level using instantaneous share row locking chosen by the optimizer > Number of opens = 1 > Rows seen = 1 > Rows filtered = 0 > Fetch Size = 16 > constructor time (milliseconds) = 0 > open time (milliseconds) = 1 > next time (milliseconds) = 9607 > close time (milliseconds) = 1 > next time in milliseconds/row = 9607 > > scan information: > Bit set of columns fetched=All > Number of columns fetched=4 > Number of pages visited=197281 > Number of rows qualified=1 > Number of rows visited=7003481 > Scan type=heap > start position: > null > stop position: > null > qualifiers: > Column[0][0] Id: 3 > Operator: = > Ordered nulls: false > Unknown return value: false > Negate comparison result: false > optimizer estimated row count: 0.00 > optimizer estimated cost: 0.00 > > > On Aug 23, 2013, at 1:10 PM, Mamta Satoor <[email protected]> wrote: > > Hi Brett, > > We have encountered and fixed at least one bug in case of single-column > unique index, where starting 10.9 we have decided not to keep stats for > such indexes. The bug fixed is DERBY-6045 and it is in Derby > 10.10.1.1(revision 1480153). I was wondering if you could share java > org.apache.derby.tools.sysinfo so we know if you have that fix. > > If you do have that fix, then it is possible (though I am not certain) > that there may be other bug in this area that > you are running into. One way to figure that out is to use the property > derby.storage.indexStats.debug.keepDisposableStats=true. This property will > force Derby to collect the stats for single-column unique index. So, if you > can recreate your db with this property and run the query, we can check the > query plan to see if it starts using the single-column unique index. It > might be possible to use existing db with this property and recreate the > stats and try the query if creating the db from scratch with this property > is a time consuming process. > > thanks, > Mamta > > > > On Wed, Aug 21, 2013 at 4:55 PM, Bryan Pendleton < > [email protected]> wrote: > >> Any thoughts or comments on why this the optimizer chooses on over the >>> other? >>> >> >> Unfortunately, no. >> >> But there have been concerns about the optimizer's cost >> analysis for years; see https://issues.apache.org/** >> jira/browse/DERBY-1905 <https://issues.apache.org/jira/browse/DERBY-1905> >> and some of the other issues linked from it (DERBY-1259, DERBY-1260). >> >> So, while I know it's frustrating for you to be wrestling with >> an optimizer that won't behave, it's also good news, for Derby, >> that you've made such good progress in trying to understand >> this peculiar behavior. >> >> Perhaps when we get to the bottom of the strange behavior >> you're seeing, we'll have a better understanding of some of >> the other strange optimizer behaviors we've seen in the past. >> >> thanks, >> >> bryan >> >> >> > >
