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 Mike Matrigali <mi...@sbcglobal.net> on 2012/04/01 00:28:12 UTC
Re: Question on why indexStat deamon is being triggered
Bergquist, Brett wrote:
> So I guess there are two things going on here. The indexStat is finding the left over rows. The second is that dropping a constraint should drop the statistics for the constraint as well.
>
> I really would like to get a fix going for this as in production I had to turn off indexStat because it was causing about a 20% performance hit. I do have tables that are going to start out empty each week and then be populated and will need the statistics present for queries during the week. I don't know enough yet about Derby to figure out how to determine this is a row for a constraint that does not exist anymore but will look into it.
>
do go ahead and log a JIRA with your info on drop not removing the stat.
But that fix is not going to help you.
I would suggest running an offline compress on your test case to see
if it gets rid of orphan row. If so it is the easiest workaround.
Next would see if drop table gets rid of it. If so, if you can afford
any downtime you could copy the data from the table to a temp table,
drop old table, and copy data back. I don't think derby rename will
help.
I think a code level fix would be in the area I suggested. Make the
update statistics code understand there might be unexpected rows and
delete them at update statistics time.
> ________________________________________
> From: Mike Matrigali [mikem_app@sbcglobal.net]
> Sent: Saturday, March 31, 2012 4:28 PM
> To: derby-dev@db.apache.org
> Subject: Re: Question on why indexStat deamon is being triggered
>
> Bergquist, Brett wrote:
>> I hitched up the debugger and caught the indexStat return "49" for the number of rows. I walked the stack back and found this was for conglomeratename = "f3ec4922-011d-491f-3d8c-0000376d74d3"
>>
>> So I did this query:
>>
>> select
>> c.TABLEID,
>> c.CONGLOMERATENUMBER,
>> c.CONGLOMERATENAME,
>> c.ISINDEX,
>> c.ISCONSTRAINT,
>> c.CONGLOMERATEID,
>> t.TABLEID,
>> t.TABLENAME,
>> t.TABLETYPE,
>> s.STATID,
>> s.REFERENCEID,
>> s.TABLEID,
>> s.CREATIONTIMESTAMP,
>> s.TYPE,
>> s.VALID,
>> s.COLCOUNT,
>> CAST(STATISTICS AS VARCHAR(40)) as STATISTICS
>> from sys.SYSCONGLOMERATES c join sys.SYSTABLES t on c.TABLEID = t.TABLEID join sys.SYSSTATISTICS s on s.TABLEID = t.TABLEID where c.CONGLOMERATENAME = 'f3ec4922-011d-491f-3d8c-0000376d74d3'
>>
>> Which is for one of the tables that I am having problems with. This returned:
>>
>> TABLEID CONGLOMERATENUMBER CONGLOMERATENAME ISINDEX ISCONSTRAINT CONGLOMERATEID TABLEID TABLENAME TABLETYPE STATID REFERENCEID TABLEID CREATIONTIMESTAMP TYPE VALID COLCOUNT STATISTICS
>> f3ec4922-011d-491f-3d8c-0000376d74d3 30768 f3ec4922-011d-491f-3d8c-0000376d74d3 false false 0e34c923-011d-491f-3d8c-0000376d74d3 f3ec4922-011d-491f-3d8c-0000376d74d3 BC01_CONFIGURATION_SET T 645c405f-0136-6999-c1b4-000065089f97 2c5f8294-012b-3c38-b55c-000043ea6398 f3ec4922-011d-491f-3d8c-0000376d74d3 2012-03-31 12:50:05.348 I true 1 numunique= 20334 numrows= 20334
>> f3ec4922-011d-491f-3d8c-0000376d74d3 30768 f3ec4922-011d-491f-3d8c-0000376d74d3 false false 0e34c923-011d-491f-3d8c-0000376d74d3 f3ec4922-011d-491f-3d8c-0000376d74d3 BC01_CONFIGURATION_SET T 49fc4ea2-0129-489a-0a26-00000732b350 592fcc26-011d-491f-3d8c-0000376d74d3 f3ec4922-011d-491f-3d8c-0000376d74d3 2010-06-17 23:16:40.018 I true 1 numunique= 49 numrows= 49
>> f3ec4922-011d-491f-3d8c-0000376d74d3 30768 f3ec4922-011d-491f-3d8c-0000376d74d3 false false 0e34c923-011d-491f-3d8c-0000376d74d3 f3ec4922-011d-491f-3d8c-0000376d74d3 BC01_CONFIGURATION_SET T 2c44c05e-0136-6999-c1b4-000065089f97 e9a40921-011d-491f-3d8c-0000376d74d3 f3ec4922-011d-491f-3d8c-0000376d74d3 2012-03-31 12:50:03.427 I true 1 numunique= 20334 numrows= 20334
>>
>> So there seems to be 3 statistics rows for this table. And low and behold there is the "numrows = 49" which I see the indexStat when I turn on tracing.
>>
> First thought is I didn't think we needed any statistics at all
> for a single column primary key.
>
> There should be entries in this catalog for every index on a table, so
> it is not necessarily expected to be one per table. I think for each
> index there is an entry for each column in the index (actually the stat
> applies to multiple columns so in a 3 column index I think there is an
> entry for (col1), (col1,col2), and (col1, col2, col3). But looking at
> your ddl I would only expect 1 entry, as there is one
> index on the table, and it has one column. I am not sure what the
> expectation is for the foreign key that matches the primary key, maybe
> it is 2 rows?
>
> I do wonder if the foreign key is causing some extra issues. I think
> in the long past we would end up creating 2 indexes in this case and
> they would be exactly the same. So functionality was added to just
> "logically" create the index and it would rely on the underlying
> physical index sort of "shared" by the primary key on id and the foreign
> constraint on id. We have had bugs in this area in the past and wonder
> if it left an "orphan" row in the statistics.
>
> Interesting that the second column it looks like it was created in 2010.
>
> seems like there might be multiple problems here. It would be great to
> figure out how the multiple rows got in there in the first place. I
> would suggest seeing what the system does for ddl in a brand new
> database, turn off index stat thread, run your ddl, add some rows to the
> table, and hand run update statistics procedure.
>
> I would not be surprised if existing code does not expect the number of
> rows you are seeing. If this is really a buggy orphan row, probably
> best zero admin fix is to change the update statistics code to look for
> other rows and delete them.
> you can follow the update statistic code starting at:
> java/engine/org/apache/derby/impl/sql/execute/AlterTableConstantAction/updateStatistics
>
> There may be a index stat daemon bug here too, but I think it might just
> be getting confused by the bad data in the catalog. Maybe it just keeps
> reading all the rows and queueing work, but calling update statistics
> only update 2 of the 3 rows.
>
>
>> I ran:
>>
>> VALUES syscs_util.syscs_check_table('PKG_9145E_V1', 'BC01_CONFIGURATION_SET')
>>
>> And this returns that the table is okay.
>>
>> I ran:
>>
>> VALUES syscs_util.syscs_check_table('SYS', 'SYSSTATISTICS')
>>
>> And this returns that the table is okay but I am not sure this is even valid.
>>
>> So the question is how/why are there 3 sets of statistics for this table. Here is the DDL for the table:
>>
>> CREATE TABLE "PKG_9145E_V1"."BC01_CONFIGURATION_SET"
>> (
>> ID int PRIMARY KEY NOT NULL
>> );
>> ALTER TABLE "PKG_9145E_V1"."BC01_CONFIGURATION_SET"
>> ADD CONSTRAINT BC01_CONFIGURATION_SET_FK_1 FOREIGN KEY (ID) REFERENCES "CORE_V1"."CONFIGURATION_SET"(ID) ;
>>
>>
>>
>> -----Original Message-----
>> From: Bergquist, Brett [mailto:BBergquist@canoga.com]
>> Sent: Friday, March 30, 2012 5:33 PM
>> To: derby-dev@db.apache.org
>> Subject: RE: Question on why indexStat deamon is being triggered
>>
>> I will hitch up the debugger and try to figure this out this weekend. I will keep you posted.
>> ________________________________________
>> From: Kristian Waagan [kristian.waagan@oracle.com]
>> Sent: Friday, March 30, 2012 4:36 PM
>> To: derby-dev@db.apache.org
>> Subject: Re: Question on why indexStat deamon is being triggered
>>
>> On 30.03.2012 18:57, Bergquist, Brett wrote:
>> I think there is something wrong with the indexStats. The problem I mentioned happens on a lot of tables. None of these tables are changing however, no inserts or deletes or updates. They are being queried, however.
>> Here is one such table. This is killing performance.
>>
>> Here is the statistics for this table:
>>
>> Table (Index) 2 3
>> ACCOUNTTABLE_CONFIG_BUNDLE (SQL081029110443810) numunique= 38390 numrows= 38390 2012-03-30 13:00:26.84
>> ACCOUNTTABLE_CONFIG_BUNDLE (SQL100922215819290) numunique= 38390 numrows= 38390 2012-03-30 13:00:26.917
>>
>> There are in fact 38390 rows in the table.
>>
>> Here is some of the stats trace:
>>
>> Fri Mar 30 12:47:12 EDT 2012 Thread[DRDAConnThread_43,5,main] {istat} "PKG_9145E_V1"."ACCOUNTTABLE_CONFIG_BUNDLE": update scheduled, reason=[t-est=38390, i-est=2355 => cmp=2.7912562815443245] (queueSize=12) Fri Mar 30 12:47:48 EDT 2012 Thread[index-stat-thread,5,main] {istat} "PKG_9145E_V1"."ACCOUNTTABLE_CONFIG_BUNDLE": wrote stats for index SQL081029110443810 (fc33890d-011d-491f-3d8c-0000376d74d3): rows=38390, card=[38390] Fri Mar 30 12:47:48 EDT 2012 Thread[index-stat-thread,5,main] {istat} "PKG_9145E_V1"."ACCOUNTTABLE_CONFIG_BUNDLE": wrote stats for index SQL100922215819290 (75608675-012b-3c38-b55c-000043ea6398): rows=38390, card=[38390] Fri Mar 30 12:47:48 EDT 2012 Thread[index-stat-thread,5,main] {istat} "PKG_9145E_V1"."ACCOUNTTABLE_CONFIG_BUNDLE": scan durations (c30625=91ms,c30625=98ms) Fri Mar 30 12:47:48 EDT 2012 Thread[index-stat-thread,5,main] {istat} "PKG_9145E_V1"."ACCOUNTTABLE_CONFIG_BUNDLE": generation complete (210 ms)
>>
>> Fri Mar 30 12:47:49 EDT 2012 Thread[DRDAConnThread_44,5,main] {istat} "PKG_9145E_V1"."ACCOUNTTABLE_CONFIG_BUNDLE": update scheduled, reason=[t-est=38390, i-est=2355 => cmp=2.7912562815443245] (queueSize=19) Fri Mar 30 12:48:25 EDT 2012 Thread[index-stat-thread,5,main] {istat} "PKG_9145E_V1"."ACCOUNTTABLE_CONFIG_BUNDLE": wrote stats for index SQL081029110443810 (fc33890d-011d-491f-3d8c-0000376d74d3): rows=38390, card=[38390] Fri Mar 30 12:48:25 EDT 2012 Thread[index-stat-thread,5,main] {istat} "PKG_9145E_V1"."ACCOUNTTABLE_CONFIG_BUNDLE": wrote stats for index SQL100922215819290 (75608675-012b-3c38-b55c-000043ea6398): rows=38390, card=[38390] Fri Mar 30 12:48:25 EDT 2012 Thread[index-stat-thread,5,main] {istat} "PKG_9145E_V1"."ACCOUNTTABLE_CONFIG_BUNDLE": scan durations (c30625=93ms,c30625=95ms) Fri Mar 30 12:48:25 EDT 2012 Thread[index-stat-thread,5,main] {istat} "PKG_9145E_V1"."ACCOUNTTABLE_CONFIG_BUNDLE": generation complete (211 ms) Fri Mar 30 12:48:25 EDT 2012 Thread[D
R
> DAConnThread_50,5,main] {istat} "PKG_9145E_V1"."ACCOUNTTABLE_CONFIG_BUNDLE": update scheduled, reason=[t-est=38390, i-est=2355 => cmp=2.7912562815443245] (queueSize=18)
>> Fri Mar 30 12:48:57 EDT 2012 Thread[index-stat-thread,5,main] {istat} "PKG_9145E_V1"."ACCOUNTTABLE_CONFIG_BUNDLE": wrote stats for index SQL081029110443810 (fc33890d-011d-491f-3d8c-0000376d74d3): rows=38390, card=[38390] Fri Mar 30 12:48:57 EDT 2012 Thread[index-stat-thread,5,main] {istat} "PKG_9145E_V1"."ACCOUNTTABLE_CONFIG_BUNDLE": wrote stats for index SQL100922215819290 (75608675-012b-3c38-b55c-000043ea6398): rows=38390, card=[38390] Fri Mar 30 12:48:57 EDT 2012 Thread[index-stat-thread,5,main] {istat} "PKG_9145E_V1"."ACCOUNTTABLE_CONFIG_BUNDLE": generation complete (243 ms)
>>
>> Fri Mar 30 12:49:27 EDT 2012 Thread[DRDAConnThread_56,5,main] {istat} "PKG_9145E_V1"."ACCOUNTTABLE_CONFIG_BUNDLE": update scheduled, reason=[t-est=38390, i-est=2355 => cmp=2.7912562815443245] (queueSize=20) Fri Mar 30 12:49:36 EDT 2012 Thread[index-stat-thread,5,main] {istat} "PKG_9145E_V1"."ACCOUNTTABLE_CONFIG_BUNDLE": wrote stats for index SQL081029110443810 (fc33890d-011d-491f-3d8c-0000376d74d3): rows=38390, card=[38390] Fri Mar 30 12:49:37 EDT 2012 Thread[index-stat-thread,5,main] {istat} "PKG_9145E_V1"."ACCOUNTTABLE_CONFIG_BUNDLE": wrote stats for index SQL100922215819290 (75608675-012b-3c38-b55c-000043ea6398): rows=38390, card=[38390] Fri Mar 30 12:49:37 EDT 2012 Thread[index-stat-thread,5,main] {istat} "PKG_9145E_V1"."ACCOUNTTABLE_CONFIG_BUNDLE": scan durations (c30625=111ms,c30625=108ms) Fri Mar 30 12:49:37 EDT 2012 Thread[index-stat-thread,5,main] {istat} "PKG_9145E_V1"."ACCOUNTTABLE_CONFIG_BUNDLE": generation complete (238 ms)
>>
>> Fri Mar 30 12:49:37 EDT 2012 Thread[DRDAConnThread_49,5,main] {istat} "PKG_9145E_V1"."ACCOUNTTABLE_CONFIG_BUNDLE": update scheduled, reason=[t-est=38390, i-est=2355 => cmp=2.7912562815443245] (queueSize=18)
>>
>> Any idea where I can look in the code? I would patch Derby if necessary
>>
>> I don't have the code in front of me, but could you maybe trace the creation of the statistics objects, with the goal of finding out where the lower number is coming from?
>> I think if you start looking in maybe CursorNode, possibly TableDescriptor, you should be able to get somewhere.
>>
>> Maybe you'll find that the lower number corresponds with an earlier/older version of the statistics for the index?
>> (a theory being that a stale statistics object is being read)
>>
>>
>> Just some late night ramblings,
>> --
>> Kristian
>>
>>
>> From: Bergquist, Brett [mailto:BBergquist@canoga.com]
>> Sent: Friday, March 30, 2012 10:58 AM
>> To: derby-dev@db.apache.org<ma...@db.apache.org>
>> Subject: RE: Question on why indexStat deamon is being triggered
>>
>> Thanks for taking a look at this. I do think something is wrong with the indexStats on this particular table.
>>
>> From: Kristian Waagan [mailto:kristian.waagan@oracle.com]
>> Sent: Friday, March 30, 2012 8:29 AM
>> To: derby-dev@db.apache.org<ma...@db.apache.org>
>> Subject: Re: Question on why indexStat deamon is being triggered
>>
>> On 30.03.2012 01:02, Bergquist, Brett wrote:
>> Here is the properties:
>>
>> derby.storage.indexStats.auto=true
>> derby.storage.indexStats.debug.lndiffThreshold=4.0
>> derby.storage.indexStats.log=true
>> derby.storage.indexStats.trace=log
>>
>>
>> The application is hitting the table PKG_9145E_V1"."BC01_CONFIGURATION_SET frequently. Many rows are being added and deleted but the total number of rows is not really changing that much if at all.
>>
>> Is the table completely emptied at any point?
>>
>> [bb] No, the table is never empty at any point during this. Basically about 300 rows being deleted and 300 new rows being added about every 30 seconds.
>>
>> Do you run anything else than insert and delete (with predicate) that modifies the table?
>> No, in fact the table has only one column:
>>
>> CREATE TABLE "PKG_9145E_V1"."BC01_CONFIGURATION_SET"
>> (
>> ID int PRIMARY KEY NOT NULL
>> )
>> ;
>> ALTER TABLE "PKG_9145E_V1"."BC01_CONFIGURATION_SET"
>> ADD CONSTRAINT BC01_CONFIGURATION_SET_FK_1 FOREIGN KEY (ID) REFERENCES "CORE_V1"."CONFIGURATION_SET"(ID) ;
>>
>>
>> What I don't understand is the line:
>>
>> Thu Mar 29 18:48:33 EDT 2012 Thread[DRDAConnThread_25,5,main] {istat} "PKG_9145E_V1"."BC01_CONFIGURATION_SET": update scheduled, reason=[t-est=44727, i-est=49 => cmp=6.816512326985881] (queueSize=1)
>>
>> abs(log(49) - log(44727)) = 6.816...
>>
>> t-est is the estimated number of rows as seen by the table [conglomerate], whereas i-est is the estimated number of rows as seen by the current index statistics. These are very different, and based on the output below, it appears t-est is correct when it says the number of rows is 44'727 [1]. So why isn't i-est changing?
>>
>> [bb] exactly my question.
>>
>>
>> What do you see if you look at the results from querying SYS.SYSSTATISTICS?
>> (i.e. columns STATISTICS [2] and CREATIONTIMESTAMP) What's the relevant DDL for the indexes/constraints in question?
>>
>> [bb]
>>
>> Table (Index) 2 3
>> BC01_CONFIGURATION_SET (SQL081029110445920) numunique= 44621 numrows= 44621 2012-03-30 10:17:07.073
>> BC01_CONFIGURATION_SET (SQL100922214723290) numunique= 44621 numrows= 44621 2012-03-30 10:17:07.187
>>
>> >From the log today:
>>
>> Fri Mar 30 10:15:32 EDT 2012 Thread[DRDAConnThread_103,5,main] {istat} "PKG_9145E_V1"."BC01_CONFIGURATION_SET": update scheduled, reason=[t-est=44527, i-est=49 => cmp=6.81203072762349] (queueSize=1) Fri Mar 30 10:15:32 EDT 2012 Thread[index-stat-thread,5,main] {istat,trace@154082288} worker thread started (xid=1705635865) [q/p/s=1/1018/1019,err:k/u/c=0/0/0,rej:f/d/o=0/618/0]
>> Fri Mar 30 10:15:32 EDT 2012 Thread[index-stat-thread,5,main] {istat,trace@154082288} processing "PKG_9145E_V1"."BC01_CONFIGURATION_SET"
>> Fri Mar 30 10:15:32 EDT 2012 Thread[index-stat-thread,5,main] {istat,trace@154082288} writing new stats (xid=1705635875)
>> Fri Mar 30 10:15:32 EDT 2012 Thread[index-stat-thread,5,main] {istat,trace@154082288} invalidation completed
>> Fri Mar 30 10:15:32 EDT 2012 Thread[index-stat-thread,5,main] {istat} "PKG_9145E_V1"."BC01_CONFIGURATION_SET": wrote stats for index SQL081029110445920 (e9a40921-011d-491f-3d8c-0000376d74d3): rows=44527, card=[44527]
>> Fri Mar 30 10:15:32 EDT 2012 Thread[index-stat-thread,5,main] {istat,trace@154082288} writing new stats (xid=1705635891)
>> Fri Mar 30 10:15:32 EDT 2012 Thread[index-stat-thread,5,main] {istat,trace@154082288} invalidation completed
>> Fri Mar 30 10:15:32 EDT 2012 Thread[index-stat-thread,5,main] {istat} "PKG_9145E_V1"."BC01_CONFIGURATION_SET": wrote stats for index SQL100922214723290 (2c5f8294-012b-3c38-b55c-000043ea6398): rows=44527, card=[44527] Fri Mar 30 10:15:32 EDT 2012 Thread[index-stat-thread,5,main] {istat} "PKG_9145E_V1"."BC01_CONFIGURATION_SET": scan durations (c30785=106ms,c30785=100ms) Fri Mar 30 10:15:32 EDT 2012 Thread[index-stat-thread,5,main] {istat} "PKG_9145E_V1"."BC01_CONFIGURATION_SET": generation complete (251 ms)
>> Fri Mar 30 10:15:32 EDT 2012 Thread[index-stat-thread,5,main] {istat,trace@154082288} queue empty
>> Fri Mar 30 10:15:32 EDT 2012 Thread[index-stat-thread,5,main] {istat,trace@154082288} worker thread exit [q/p/s=0/1019/1019,err:k/u/c=0/0/0,rej:f/d/o=0/618/0]
>>
>> So it seems that even just recently this morning, it still thinks that the index only has 49 rows
>>
>> The same values are being shown each time. Is this correct?
>>
>> At least i-est seems off.
>> Do/did you see similar problems with other tables/indexes?
>> You can check the values by doing a select count and looking at the statistics stored in the system table.
>>
>> Today there are 44621 rows. I was running some test over night and did do some deletes that would cause this to go down.
>>
>> I am trying to tune the indexStat daemon so that it will run when needed but not too frequently. With the default value, I was seeing about a 20% penalty when running the application and saw the indexStat daemon nearly non-stop. So I adjusted the lndiffThreshold to be 4.0 an it is not running too frequently but I still would like to understand what the trace/log is telling me.
>>
>> A lndiffThreshold of 4.0 means the table has to grow (or shrink) by a factor of roughly 54.6. In the specific case above, the index statistics for the table shouldn't be generated again before there are ([3]) nearly two and a half million rows in it (or less than 820).
>> I'd say a threshold of 4.0 is pretty relaxed - do you expect the distribution/cardinality of the values to be similar for a table with 50K rows and 2500K rows?
>>
>> [bb] I have other tables that are constantly being inserted into where each record will be unique. The table has 2 indexes on it where one is unique and 2 will have duplicates. This table will end up with about 42M records in a week, will stay around for 2 weeks and then will be empty again and not used for 50 weeks of the year. Basically there is one table per week of the year that starts as empty, is populated for the week, data stays around for 2 weeks for query purposes, and then is purged out. The important thing is that once the week table starts to be populated, queries will start hitting that table so it is important that the queries use the indexes on the table. The table is inserted at a rate of about 60 records/second so after a few thousand records I want the statistics to be generated and the indexes to be used.
>>
>> So maybe 4.0 is too much but 1.0 was generating statistics constantly.
>>
>> I copied a line from below:
>> [q/p/s=0/268/268,err:k/u/c=0/0/0,rej:f/d/o=0/303/0]
>> q = queued
>> p = processed
>> s = scheduled
>> k = known errors (the daemon is prepared for these and can easily recover) u = unknown errors c = consecutive errors (daemon will disable itself if there are too many consecutive errors) f = rejection due to full queue d = rejection due to duplicate request (already in the queue) o = other (currently only tracks scheduling attempts when the daemon has been disabled)
>>
>>
>> FYI, I'm aware that your options to fine-tune the statistics generation is rather limited.
>>
>>
>> Regards,
>> --
>> Kristian
>>
>> [1] "wrote stats for index X (id): rows=44727, card=[44727]"
>> [2] In ij I had to cast this to see everything: cast(STATISTICS as VARCHAR(40)) [3] Or rather before Derby believes there are so many rows in the table - we're working with estimates here.
>>
>>
>> Here is a snippet of the output:
>>
>> Thu Mar 29 18:48:02 EDT 2012 Thread[index-stat-thread,5,main] {istat,trace@154082288} writing new stats (xid=1681453075)
>> Thu Mar 29 18:48:02 EDT 2012 Thread[index-stat-thread,5,main] {istat,trace@154082288} invalidation completed
>> Thu Mar 29 18:48:02 EDT 2012 Thread[index-stat-thread,5,main] {istat} "PKG_9145E_V1"."BC01_CONFIGURATION_SET": wrote stats for index SQL081029110445920 (e9a40921-011d-491f-3d8c-0000376d74d3): rows=44727, card=[44727]
>> Thu Mar 29 18:48:02 EDT 2012 Thread[index-stat-thread,5,main] {istat,trace@154082288} writing new stats (xid=1681453158)
>> Thu Mar 29 18:48:02 EDT 2012 Thread[index-stat-thread,5,main] {istat,trace@154082288} invalidation completed
>> Thu Mar 29 18:48:02 EDT 2012 Thread[index-stat-thread,5,main] {istat} "PKG_9145E_V1"."BC01_CONFIGURATION_SET": wrote stats for index SQL100922214723290 (2c5f8294-012b-3c38-b55c-000043ea6398): rows=44727, card=[44727] Thu Mar 29 18:48:02 EDT 2012 Thread[index-stat-thread,5,main] {istat} "PKG_9145E_V1"."BC01_CONFIGURATION_SET": scan durations (c30785=144ms,c30785=135ms) Thu Mar 29 18:48:02 EDT 2012 Thread[index-stat-thread,5,main] {istat} "PKG_9145E_V1"."BC01_CONFIGURATION_SET": generation complete (300 ms)
>> Thu Mar 29 18:48:02 EDT 2012 Thread[index-stat-thread,5,main] {istat,trace@154082288} queue empty
>> Thu Mar 29 18:48:02 EDT 2012 Thread[index-stat-thread,5,main] {istat,trace@154082288} worker thread exit [q/p/s=0/266/266,err:k/u/c=0/0/0,rej:f/d/o=0/303/0]
>> Thu Mar 29 18:48:12 EDT 2012 Thread[DRDAConnThread_42,5,main] {istat} "PKG_9145E_V1"."BC01_CONFIGURATION_SET": update scheduled, reason=[t-est=44727, i-est=49 => cmp=6.816512326985881] (queueSize=1) Thu Mar 29 18:48:12 EDT 2012 Thread[index-stat-thread,5,main] {istat,trace@154082288} worker thread started (xid=1681453158) [q/p/s=1/266/267,err:k/u/c=0/0/0,rej:f/d/o=0/303/0]
>> Thu Mar 29 18:48:12 EDT 2012 Thread[index-stat-thread,5,main] {istat,trace@154082288} processing "PKG_9145E_V1"."BC01_CONFIGURATION_SET"
>> Thu Mar 29 18:48:12 EDT 2012 Thread[index-stat-thread,5,main] {istat,trace@154082288} writing new stats (xid=1681462384)
>> Thu Mar 29 18:48:12 EDT 2012 Thread[index-stat-thread,5,main] {istat,trace@154082288} invalidation completed
>> Thu Mar 29 18:48:12 EDT 2012 Thread[index-stat-thread,5,main] {istat} "PKG_9145E_V1"."BC01_CONFIGURATION_SET": wrote stats for index SQL081029110445920 (e9a40921-011d-491f-3d8c-0000376d74d3): rows=44727, card=[44727]
>> Thu Mar 29 18:48:12 EDT 2012 Thread[index-stat-thread,5,main] {istat,trace@154082288} writing new stats (xid=1681462622)
>> Thu Mar 29 18:48:12 EDT 2012 Thread[index-stat-thread,5,main] {istat,trace@154082288} invalidation completed
>> Thu Mar 29 18:48:12 EDT 2012 Thread[index-stat-thread,5,main] {istat} "PKG_9145E_V1"."BC01_CONFIGURATION_SET": wrote stats for index SQL100922214723290 (2c5f8294-012b-3c38-b55c-000043ea6398): rows=44727, card=[44727] Thu Mar 29 18:48:12 EDT 2012 Thread[index-stat-thread,5,main] {istat} "PKG_9145E_V1"."BC01_CONFIGURATION_SET": scan durations (c30785=152ms,c30785=138ms) Thu Mar 29 18:48:12 EDT 2012 Thread[index-stat-thread,5,main] {istat} "PKG_9145E_V1"."BC01_CONFIGURATION_SET": generation complete (306 ms)
>> Thu Mar 29 18:48:12 EDT 2012 Thread[index-stat-thread,5,main] {istat,trace@154082288} queue empty
>> Thu Mar 29 18:48:12 EDT 2012 Thread[index-stat-thread,5,main] {istat,trace@154082288} worker thread exit [q/p/s=0/267/267,err:k/u/c=0/0/0,rej:f/d/o=0/303/0]
>> Thu Mar 29 18:48:33 EDT 2012 Thread[DRDAConnThread_25,5,main] {istat} "PKG_9145E_V1"."BC01_CONFIGURATION_SET": update scheduled, reason=[t-est=44727, i-est=49 => cmp=6.816512326985881] (queueSize=1) Thu Mar 29 18:48:33 EDT 2012 Thread[index-stat-thread,5,main] {istat,trace@154082288} worker thread started (xid=1681462622) [q/p/s=1/267/268,err:k/u/c=0/0/0,rej:f/d/o=0/303/0]
>> Thu Mar 29 18:48:33 EDT 2012 Thread[index-stat-thread,5,main] {istat,trace@154082288} processing "PKG_9145E_V1"."BC01_CONFIGURATION_SET"
>> Thu Mar 29 18:48:33 EDT 2012 Thread[index-stat-thread,5,main] {istat,trace@154082288} writing new stats (xid=1681479731)
>> Thu Mar 29 18:48:33 EDT 2012 Thread[index-stat-thread,5,main] {istat,trace@154082288} invalidation completed
>> Thu Mar 29 18:48:33 EDT 2012 Thread[index-stat-thread,5,main] {istat} "PKG_9145E_V1"."BC01_CONFIGURATION_SET": wrote stats for index SQL081029110445920 (e9a40921-011d-491f-3d8c-0000376d74d3): rows=44727, card=[44727]
>> Thu Mar 29 18:48:33 EDT 2012 Thread[index-stat-thread,5,main] {istat,trace@154082288} writing new stats (xid=1681479756)
>> Thu Mar 29 18:48:33 EDT 2012 Thread[index-stat-thread,5,main] {istat,trace@154082288} invalidation completed
>> Thu Mar 29 18:48:33 EDT 2012 Thread[index-stat-thread,5,main] {istat} "PKG_9145E_V1"."BC01_CONFIGURATION_SET": wrote stats for index SQL100922214723290 (2c5f8294-012b-3c38-b55c-000043ea6398): rows=44727, card=[44727] Thu Mar 29 18:48:33 EDT 2012 Thread[index-stat-thread,5,main] {istat} "PKG_9145E_V1"."BC01_CONFIGURATION_SET": scan durations (c30785=95ms,c30785=103ms) Thu Mar 29 18:48:33 EDT 2012 Thread[index-stat-thread,5,main] {istat} "PKG_9145E_V1"."BC01_CONFIGURATION_SET": generation complete (214 ms)
>> Thu Mar 29 18:48:33 EDT 2012 Thread[index-stat-thread,5,main] {istat,trace@154082288} queue empty
>> Thu Mar 29 18:48:33 EDT 2012 Thread[index-stat-thread,5,main] {istat,trace@154082288} worker thread exit [q/p/s=0/268/268,err:k/u/c=0/0/0,rej:f/d/o=0/303/0]
>> Thu Mar 29 18:48:44 EDT 2012 Thread[DRDAConnThread_26,5,main] {istat} "PKG_9145E_V1"."BC01_CONFIGURATION_SET": update scheduled, reason=[t-est=44727, i-est=49 => cmp=6.816512326985881] (queueSize=1) Thu Mar 29 18:48:44 EDT 2012 Thread[index-stat-thread,5,main] {istat,trace@154082288} worker thread started (xid=1681479756) [q/p/s=1/268/269,err:k/u/c=0/0/0,rej:f/d/o=0/303/0]
>> Thu Mar 29 18:48:44 EDT 2012 Thread[index-stat-thread,5,main] {istat,trace@154082288} processing "PKG_9145E_V1"."BC01_CONFIGURATION_SET"
>> Thu Mar 29 18:48:44 EDT 2012 Thread[index-stat-thread,5,main] {istat,trace@154082288} writing new stats (xid=1681487715)
>> Thu Mar 29 18:48:44 EDT 2012 Thread[index-stat-thread,5,main] {istat,trace@154082288} invalidation completed
>> Thu Mar 29 18:48:44 EDT 2012 Thread[index-stat-thread,5,main] {istat} "PKG_9145E_V1"."BC01_CONFIGURATION_SET": wrote stats for index SQL081029110445920 (e9a40921-011d-491f-3d8c-0000376d74d3): rows=44727, card=[44727]
>> Thu Mar 29 18:48:45 EDT 2012 Thread[index-stat-thread,5,main] {istat,trace@154082288} writing new stats (xid=1681487764)
>> Thu Mar 29 18:48:45 EDT 2012 Thread[index-stat-thread,5,main] {istat,trace@154082288} invalidation completed
>> Thu Mar 29 18:48:45 EDT 2012 Thread[index-stat-thread,5,main] {istat} "PKG_9145E_V1"."BC01_CONFIGURATION_SET": wrote stats for index SQL100922214723290 (2c5f8294-012b-3c38-b55c-000043ea6398): rows=44727, card=[44727] Thu Mar 29 18:48:45 EDT 2012 Thread[index-stat-thread,5,main] {istat} "PKG_9145E_V1"."BC01_CONFIGURATION_SET": scan durations (c30785=101ms,c30785=118ms) Thu Mar 29 18:48:45 EDT 2012 Thread[index-stat-thread,5,main] {istat} "PKG_9145E_V1"."BC01_CONFIGURATION_SET": generation complete (231 ms)
>> Thu Mar 29 18:48:45 EDT 2012 Thread[index-stat-thread,5,main] {istat,trace@154082288} queue empty
>> Thu Mar 29 18:48:45 EDT 2012 Thread[index-stat-thread,5,main] {istat,trace@154082288} worker thread exit [q/p/s=0/269/269,err:k/u/c=0/0/0,rej:f/d/o=0/303/0]
>> Thu Mar 29 18:48:46 EDT 2012 Thread[DRDAConnThread_39,5,main] {istat} "PKG_9145E_V1"."BC01_CONFIGURATION_SET": update scheduled, reason=[t-est=44727, i-est=49 => cmp=6.816512326985881] (queueSize=1) Thu Mar 29 18:48:46 EDT 2012 Thread[index-stat-thread,5,main] {istat,trace@154082288} worker thread started (xid=1681487764) [q/p/s=1/269/270,err:k/u/c=0/0/0,rej:f/d/o=0/303/0]
>> Thu Mar 29 18:48:46 EDT 2012 Thread[index-stat-thread,5,main] {istat,trace@154082288} processing "PKG_9145E_V1"."BC01_CONFIGURATION_SET"
>> Thu Mar 29 18:48:46 EDT 2012 Thread[index-stat-thread,5,main] {istat,trace@154082288} writing new stats (xid=1681489467)
>> Thu Mar 29 18:48:46 EDT 2012 Thread[index-stat-thread,5,main] {istat,trace@154082288} invalidation completed
>> Thu Mar 29 18:48:47 EDT 2012 Thread[index-stat-thread,5,main] {istat} "PKG_9145E_V1"."BC01_CONFIGURATION_SET": wrote stats for index SQL081029110445920 (e9a40921-011d-491f-3d8c-0000376d74d3): rows=44727, card=[44727]
>> Thu Mar 29 18:48:47 EDT 2012 Thread[index-stat-thread,5,main] {istat,trace@154082288} writing new stats (xid=1681489541)
>> Thu Mar 29 18:48:47 EDT 2012 Thread[index-stat-thread,5,main] {istat,trace@154082288} invalidation completed
>> Thu Mar 29 18:48:47 EDT 2012 Thread[index-stat-thread,5,main] {istat} "PKG_9145E_V1"."BC01_CONFIGURATION_SET": wrote stats for index SQL100922214723290 (2c5f8294-012b-3c38-b55c-000043ea6398): rows=44727, card=[44727] Thu Mar 29 18:48:47 EDT 2012 Thread[index-stat-thread,5,main] {istat} "PKG_9145E_V1"."BC01_CONFIGURATION_SET": scan durations (c30785=119ms,c30785=130ms) Thu Mar 29 18:48:47 EDT 2012 Thread[index-stat-thread,5,main] {istat} "PKG_9145E_V1"."BC01_CONFIGURATION_SET": generation complete (269 ms)
>> Thu Mar 29 18:48:47 EDT 2012 Thread[index-stat-thread,5,main] {istat,trace@154082288} queue empty
>> Thu Mar 29 18:48:47 EDT 2012 Thread[index-stat-thread,5,main] {istat,trace@154082288} worker thread exit [q/p/s=0/270/270,err:k/u/c=0/0/0,rej:f/d/o=0/303/0]
>> Thu Mar 29 18:48:53 EDT 2012 Thread[DRDAConnThread_22,5,main] {istat} "PKG_9145E_V1"."BC01_CONFIGURATION_SET": update scheduled, reason=[t-est=44727, i-est=49 => cmp=6.816512326985881] (queueSize=1) Thu Mar 29 18:48:53 EDT 2012 Thread[index-stat-thread,5,main] {istat,trace@154082288} worker thread started (xid=1681489541) [q/p/s=1/270/271,err:k/u/c=0/0/0,rej:f/d/o=0/303/0]
>> Thu Mar 29 18:48:53 EDT 2012 Thread[index-stat-thread,5,main] {istat,trace@154082288} processing "PKG_9145E_V1"."BC01_CONFIGURATION_SET"
>> Thu Mar 29 18:48:53 EDT 2012 Thread[index-stat-thread,5,main] {istat,trace@154082288} writing new stats (xid=1681495081)
>> Thu Mar 29 18:48:53 EDT 2012 Thread[index-stat-thread,5,main] {istat,trace@154082288} invalidation completed
>> Thu Mar 29 18:48:53 EDT 2012 Thread[index-stat-thread,5,main] {istat} "PKG_9145E_V1"."BC01_CONFIGURATION_SET": wrote stats for index SQL081029110445920 (e9a40921-011d-491f-3d8c-0000376d74d3): rows=44727, card=[44727]
>> Thu Mar 29 18:48:53 EDT 2012 Thread[index-stat-thread,5,main] {istat,trace@154082288} writing new stats (xid=1681495161)
>> Thu Mar 29 18:48:53 EDT 2012 Thread[index-stat-thread,5,main] {istat,trace@154082288} invalidation completed
>> Thu Mar 29 18:48:53 EDT 2012 Thread[index-stat-thread,5,main] {istat} "PKG_9145E_V1"."BC01_CONFIGURATION_SET": wrote stats for index SQL100922214723290 (2c5f8294-012b-3c38-b55c-000043ea6398): rows=44727, card=[44727] Thu Mar 29 18:48:53 EDT 2012 Thread[index-stat-thread,5,main] {istat} "PKG_9145E_V1"."BC01_CONFIGURATION_SET": scan durations (c30785=200ms,c30785=126ms) Thu Mar 29 18:48:53 EDT 2012 Thread[index-stat-thread,5,main] {istat} "PKG_9145E_V1"."BC01_CONFIGURATION_SET": generation complete (343 ms)
>> Thu Mar 29 18:48:53 EDT 2012 Thread[index-stat-thread,5,main] {istat,trace@154082288} queue empty
>> Thu Mar 29 18:48:53 EDT 2012 Thread[index-stat-thread,5,main] {istat,trace@154082288} worker thread exit [q/p/s=0/271/271,err:k/u/c=0/0/0,rej:f/d/o=0/303/0]
>> Thu Mar 29 18:49:08 EDT 2012 Thread[DRDAConnThread_35,5,main] {istat} "PKG_9145E_V1"."BC01_CONFIGURATION_SET": update scheduled, reason=[t-est=44727, i-est=49 => cmp=6.816512326985881] (queueSize=1) Thu Mar 29 18:49:08 EDT 2012 Thread[index-stat-thread,5,main] {istat,trace@154082288} worker thread started (xid=1681495161) [q/p/s=1/271/272,err:k/u/c=0/0/0,rej:f/d/o=0/303/0]
>> Thu Mar 29 18:49:08 EDT 2012 Thread[index-stat-thread,5,main] {istat,trace@154082288} processing "PKG_9145E_V1"."BC01_CONFIGURATION_SET"
>> Thu Mar 29 18:49:09 EDT 2012 Thread[index-stat-thread,5,main] {istat,trace@154082288} writing new stats (xid=1681510950)
>> Thu Mar 29 18:49:09 EDT 2012 Thread[index-stat-thread,5,main] {istat,trace@154082288} invalidation completed
>> Thu Mar 29 18:49:09 EDT 2012 Thread[index-stat-thread,5,main] {istat} "PKG_9145E_V1"."BC01_CONFIGURATION_SET": wrote stats for index SQL081029110445920 (e9a40921-011d-491f-3d8c-0000376d74d3): rows=44727, card=[44727]
>> Thu Mar 29 18:49:09 EDT 2012 Thread[index-stat-thread,5,main] {istat,trace@154082288} writing new stats (xid=1681511028)
>> Thu Mar 29 18:49:09 EDT 2012 Thread[index-stat-thread,5,main] {istat,trace@154082288} invalidation completed
>> Thu Mar 29 18:49:09 EDT 2012 Thread[index-stat-thread,5,main] {istat} "PKG_9145E_V1"."BC01_CONFIGURATION_SET": wrote stats for index SQL100922214723290 (2c5f8294-012b-3c38-b55c-000043ea6398): rows=44727, card=[44727] Thu Mar 29 18:49:09 EDT 2012 Thread[index-stat-thread,5,main] {istat} "PKG_9145E_V1"."BC01_CONFIGURATION_SET": scan durations (c30785=228ms,c30785=111ms) Thu Mar 29 18:49:09 EDT 2012 Thread[index-stat-thread,5,main] {istat} "PKG_9145E_V1"."BC01_CONFIGURATION_SET": generation complete (358 ms)
>> Thu Mar 29 18:49:09 EDT 2012 Thread[index-stat-thread,5,main] {istat,trace@154082288} queue empty
>> Thu Mar 29 18:49:09 EDT 2012 Thread[index-stat-thread,5,main] {istat,trace@154082288} worker thread exit [q/p/s=0/272/272,err:k/u/c=0/0/0,rej:f/d/o=0/303/0]
>> Thu Mar 29 18:49:11 EDT 2012 Thread[DRDAConnThread_25,5,main] {istat} "PKG_9145E_V1"."BC01_CONFIGURATION_SET": update scheduled, reason=[t-est=44727, i-est=49 => cmp=6.816512326985881] (queueSize=1) Thu Mar 29 18:49:11 EDT 2012 Thread[index-stat-thread,5,main] {istat,trace@154082288} worker thread started (xid=1681511028) [q/p/s=1/272/273,err:k/u/c=0/0/0,rej:f/d/o=0/303/0]
>> Thu Mar 29 18:49:11 EDT 2012 Thread[index-stat-thread,5,main] {istat,trace@154082288} processing "PKG_9145E_V1"."BC01_CONFIGURATION_SET"
>> Thu Mar 29 18:49:11 EDT 2012 Thread[index-stat-thread,5,main] {istat,trace@154082288} writing new stats (xid=1681512771)
>> Thu Mar 29 18:49:11 EDT 2012 Thread[index-stat-thread,5,main] {istat,trace@154082288} invalidation completed
>> Thu Mar 29 18:49:11 EDT 2012 Thread[index-stat-thread,5,main] {istat} "PKG_9145E_V1"."BC01_CONFIGURATION_SET": wrote stats for index SQL081029110445920 (e9a40921-011d-491f-3d8c-0000376d74d3): rows=44727, card=[44727]
>> Thu Mar 29 18:49:11 EDT 2012 Thread[index-stat-thread,5,main] {istat,trace@154082288} writing new stats (xid=1681512851)
>> Thu Mar 29 18:49:11 EDT 2012 Thread[index-stat-thread,5,main] {istat,trace@154082288} invalidation completed
>> Thu Mar 29 18:49:11 EDT 2012 Thread[index-stat-thread,5,main] {istat} "PKG_9145E_V1"."BC01_CONFIGURATION_SET": wrote stats for index SQL100922214723290 (2c5f8294-012b-3c38-b55c-000043ea6398): rows=44727, card=[44727] Thu Mar 29 18:49:11 EDT 2012 Thread[index-stat-thread,5,main] {istat} "PKG_9145E_V1"."BC01_CONFIGURATION_SET": scan durations (c30785=118ms,c30785=118ms) Thu Mar 29 18:49:11 EDT 2012 Thread[index-stat-thread,5,main] {istat} "PKG_9145E_V1"."BC01_CONFIGURATION_SET": generation complete (259 ms)
>> Thu Mar 29 18:49:11 EDT 2012 Thread[index-stat-thread,5,main] {istat,trace@154082288} queue empty
>> Thu Mar 29 18:49:11 EDT 2012 Thread[index-stat-thread,5,main] {istat,trace@154082288} worker thread exit [q/p/s=0/273/273,err:k/u/c=0/0/0,rej:f/d/o=0/303/0]
>> Thu Mar 29 18:49:17 EDT 2012 Thread[DRDAConnThread_38,5,main] {istat} "PKG_9145E_V1"."BC01_CONFIGURATION_SET": update scheduled, reason=[t-est=44727, i-est=49 => cmp=6.816512326985881] (queueSize=1) Thu Mar 29 18:49:17 EDT 2012 Thread[index-stat-thread,5,main] {istat,trace@154082288} worker thread started (xid=1681512851) [q/p/s=1/273/274,err:k/u/c=0/0/0,rej:f/d/o=0/303/0]
>> Thu Mar 29 18:49:17 EDT 2012 Thread[index-stat-thread,5,main] {istat,trace@154082288} processing "PKG_9145E_V1"."BC01_CONFIGURATION_SET"
>> Thu Mar 29 18:49:17 EDT 2012 Thread[index-stat-thread,5,main] {istat,trace@154082288} writing new stats (xid=1681518290)
>> Thu Mar 29 18:49:17 EDT 2012 Thread[index-stat-thread,5,main] {istat,trace@154082288} invalidation completed
>> Thu Mar 29 18:49:17 EDT 2012 Thread[index-stat-thread,5,main] {istat} "PKG_9145E_V1"."BC01_CONFIGURATION_SET": wrote stats for index SQL081029110445920 (e9a40921-011d-491f-3d8c-0000376d74d3): rows=44727, card=[44727]
>> Thu Mar 29 18:49:18 EDT 2012 Thread[index-stat-thread,5,main] {istat,trace@154082288} writing new stats (xid=1681518363)
>> Thu Mar 29 18:49:18 EDT 2012 Thread[index-stat-thread,5,main] {istat,trace@154082288} invalidation completed
>> Thu Mar 29 18:49:18 EDT 2012 Thread[index-stat-thread,5,main] {istat} "PKG_9145E_V1"."BC01_CONFIGURATION_SET": wrote stats for index SQL100922214723290 (2c5f8294-012b-3c38-b55c-000043ea6398): rows=44727, card=[44727] Thu Mar 29 18:49:18 EDT 2012 Thread[index-stat-thread,5,main] {istat} "PKG_9145E_V1"."BC01_CONFIGURATION_SET": scan durations (c30785=118ms,c30785=216ms) Thu Mar 29 18:49:18 EDT 2012 Thread[index-stat-thread,5,main] {istat} "PKG_9145E_V1"."BC01_CONFIGURATION_SET": generation complete (351 ms)
>> Thu Mar 29 18:49:18 EDT 2012 Thread[index-stat-thread,5,main] {istat,trace@154082288} queue empty
>> Thu Mar 29 18:49:18 EDT 2012 Thread[index-stat-thread,5,main] {istat,trace@154082288} worker thread exit [q/p/s=0/274/274,err:k/u/c=0/0/0,rej:f/d/o=0/303/0]
>> Thu Mar 29 18:49:34 EDT 2012 Thread[DRDAConnThread_35,5,main] {istat} "PKG_9145E_V1"."BC01_CONFIGURATION_SET": update scheduled, reason=[t-est=44727, i-est=49 => cmp=6.816512326985881] (queueSize=1) Thu Mar 29 18:49:34 EDT 2012 Thread[index-stat-thread,5,main] {istat,trace@154082288} worker thread started (xid=1681518363) [q/p/s=1/274/275,err:k/u/c=0/0/0,rej:f/d/o=0/303/0]
>> Thu Mar 29 18:49:34 EDT 2012 Thread[index-stat-thread,5,main] {istat,trace@154082288} processing "PKG_9145E_V1"."BC01_CONFIGURATION_SET"
>> Thu Mar 29 18:49:34 EDT 2012 Thread[index-stat-thread,5,main] {istat,trace@154082288} writing new stats (xid=1681534090)
>> Thu Mar 29 18:49:34 EDT 2012 Thread[index-stat-thread,5,main] {istat,trace@154082288} invalidation completed
>> Thu Mar 29 18:49:34 EDT 2012 Thread[index-stat-thread,5,main] {istat} "PKG_9145E_V1"."BC01_CONFIGURATION_SET": wrote stats for index SQL081029110445920 (e9a40921-011d-491f-3d8c-0000376d74d3): rows=44727, card=[44727]
>> Thu Mar 29 18:49:34 EDT 2012 Thread[index-stat-thread,5,main] {istat,trace@154082288} writing new stats (xid=1681534168)
>> Thu Mar 29 18:49:34 EDT 2012 Thread[index-stat-thread,5,main] {istat,trace@154082288} invalidation completed
>> Thu Mar 29 18:49:34 EDT 2012 Thread[index-stat-thread,5,main] {istat} "PKG_9145E_V1"."BC01_CONFIGURATION_SET": wrote stats for index SQL100922214723290 (2c5f8294-012b-3c38-b55c-000043ea6398): rows=44727, card=[44727] Thu Mar 29 18:49:34 EDT 2012 Thread[index-stat-thread,5,main] {istat} "PKG_9145E_V1"."BC01_CONFIGURATION_SET": scan durations (c30785=112ms,c30785=217ms) Thu Mar 29 18:49:34 EDT 2012 Thread[index-stat-thread,5,main] {istat} "PKG_9145E_V1"."BC01_CONFIGURATION_SET": generation complete (352 ms)
>> Thu Mar 29 18:49:34 EDT 2012 Thread[index-stat-thread,5,main] {istat,trace@154082288} queue empty
>> Thu Mar 29 18:49:34 EDT 2012 Thread[index-stat-thread,5,main] {istat,trace@154082288} worker thread exit [q/p/s=0/275/275,err:k/u/c=0/0/0,rej:f/d/o=0/303/0]
>> Thu Mar 29 18:49:36 EDT 2012 Thread[DRDAConnThread_25,5,main] {istat} "PKG_9145E_V1"."BC01_CONFIGURATION_SET": update scheduled, reason=[t-est=44727, i-est=49 => cmp=6.816512326985881] (queueSize=1) Thu Mar 29 18:49:36 EDT 2012 Thread[index-stat-thread,5,main] {istat,trace@154082288} worker thread started (xid=1681534168) [q/p/s=1/275/276,err:k/u/c=0/0/0,rej:f/d/o=0/303/0]
>> Thu Mar 29 18:49:36 EDT 2012 Thread[index-stat-thread,5,main] {istat,trace@154082288} processing "PKG_9145E_V1"."BC01_CONFIGURATION_SET"
>> Thu Mar 29 18:49:37 EDT 2012 Thread[index-stat-thread,5,main] {istat,trace@154082288} writing new stats (xid=1681536662)
>> Thu Mar 29 18:49:37 EDT 2012 Thread[index-stat-thread,5,main] {istat,trace@154082288} invalidation completed
>> Thu Mar 29 18:49:37 EDT 2012 Thread[index-stat-thread,5,main] {istat} "PKG_9145E_V1"."BC01_CONFIGURATION_SET": wrote stats for index SQL081029110445920 (e9a40921-011d-491f-3d8c-0000376d74d3): rows=44727, card=[44727]
>> Thu Mar 29 18:49:37 EDT 2012 Thread[index-stat-thread,5,main] {istat,trace@154082288} writing new stats (xid=1681536775)
>> Thu Mar 29 18:49:37 EDT 2012 Thread[index-stat-thread,5,main] {istat,trace@154082288} invalidation completed
>> Thu Mar 29 18:49:37 EDT 2012 Thread[index-stat-thread,5,main] {istat} "PKG_9145E_V1"."BC01_CONFIGURATION_SET": wrote stats for index SQL100922214723290 (2c5f8294-012b-3c38-b55c-000043ea6398): rows=44727, card=[44727] Thu Mar 29 18:49:37 EDT 2012 Thread[index-stat-thread,5,main] {istat} "PKG_9145E_V1"."BC01_CONFIGURATION_SET": scan durations (c30785=133ms,c30785=127ms) Thu Mar 29 18:49:37 EDT 2012 Thread[index-stat-thread,5,main] {istat} "PKG_9145E_V1"."BC01_CONFIGURATION_SET": generation complete (285 ms)
>> Thu Mar 29 18:49:37 EDT 2012 Thread[index-stat-thread,5,main] {istat,trace@154082288} queue empty
>> Thu Mar 29 18:49:37 EDT 2012 Thread[index-stat-thread,5,main] {istat,trace@154082288} worker thread exit [q/p/s=0/276/276,err:k/u/c=0/0/0,rej:f/d/o=0/303/0]
>> Thu Mar 29 18:49:42 EDT 2012 Thread[DRDAConnThread_29,5,main] {istat} "PKG_9145E_V1"."BC01_CONFIGURATION_SET": update scheduled, reason=[t-est=44727, i-est=49 => cmp=6.816512326985881] (queueSize=1) Thu Mar 29 18:49:42 EDT 2012 Thread[index-stat-thread,5,main] {istat,trace@154082288} worker thread started (xid=1681536775) [q/p/s=1/276/277,err:k/u/c=0/0/0,rej:f/d/o=0/303/0]
>> Thu Mar 29 18:49:42 EDT 2012 Thread[index-stat-thread,5,main] {istat,trace@154082288} processing "PKG_9145E_V1"."BC01_CONFIGURATION_SET"
>> Thu Mar 29 18:49:42 EDT 2012 Thread[index-stat-thread,5,main] {istat,trace@154082288} writing new stats (xid=1681541238)
>> Thu Mar 29 18:49:42 EDT 2012 Thread[index-stat-thread,5,main] {istat,trace@154082288} invalidation completed
>> Thu Mar 29 18:49:42 EDT 2012 Thread[index-stat-thread,5,main] {istat} "PKG_9145E_V1"."BC01_CONFIGURATION_SET": wrote stats for index SQL081029110445920 (e9a40921-011d-491f-3d8c-0000376d74d3): rows=44727, card=[44727]
>> Thu Mar 29 18:49:42 EDT 2012 Thread[index-stat-thread,5,main] {istat,trace@154082288} writing new stats (xid=1681541329)
>> Thu Mar 29 18:49:42 EDT 2012 Thread[index-stat-thread,5,main] {istat,trace@154082288} invalidation completed
>> Thu Mar 29 18:49:42 EDT 2012 Thread[index-stat-thread,5,main] {istat} "PKG_9145E_V1"."BC01_CONFIGURATION_SET": wrote stats for index SQL100922214723290 (2c5f8294-012b-3c38-b55c-000043ea6398): rows=44727, card=[44727] Thu Mar 29 18:49:42 EDT 2012 Thread[index-stat-thread,5,main] {istat} "PKG_9145E_V1"."BC01_CONFIGURATION_SET": scan durations (c30785=132ms,c30785=124ms) Thu Mar 29 18:49:42 EDT 2012 Thread[index-stat-thread,5,main] {istat} "PKG_9145E_V1"."BC01_CONFIGURATION_SET": generation complete (273 ms)
>> Thu Mar 29 18:49:42 EDT 2012 Thread[index-stat-thread,5,main] {istat,trace@154082288} queue empty
>> Thu Mar 29 18:49:42 EDT 2012 Thread[index-stat-thread,5,main] {istat,trace@154082288} worker thread exit [q/p/s=0/277/277,err:k/u/c=0/0/0,rej:f/d/o=0/303/0]
>>
>>
>>
>>
>>
>
>
>
>
Re: Question on why indexStat deamon is being triggered
Posted by Mike Matrigali <mi...@sbcglobal.net>.
Bergquist, Brett wrote:
> I will log a JIRA for this.
>
> The SYSCS_UTIL.SYSCS_COMPRESS_TABLE does not fix the problem. Backing up the database does not fix the problem either although I did not expect it to.
>
> The database cannot be taken down as it is being updated continuously 24x7 and is quite large so export/import or copying to a temporary is not possible. It is not only one table as well, as there are about 50 that have this problem.
>
> So I guess making indexStat work around this going to have to be done. I am going to start looking at that now.
>
I don't have time to look at this more for now.
One possibility would be to make the code path that updates
the statistics on all indexes for the conglomerate to delete
all rows in systatistics first, making it find the orphan
ones also, i think it currently just does it based on existing
indexes and one at a time and thus misses the orphaned one.
There is also a code path that just updates the
statistics for a single index, so that one should not be
changed. I don't know which one the stat daemon calls.
/mikem
RE: Question on why indexStat deamon is being triggered
Posted by "Bergquist, Brett" <BB...@canoga.com>.
I will log a JIRA for this.
The SYSCS_UTIL.SYSCS_COMPRESS_TABLE does not fix the problem. Backing up the database does not fix the problem either although I did not expect it to.
The database cannot be taken down as it is being updated continuously 24x7 and is quite large so export/import or copying to a temporary is not possible. It is not only one table as well, as there are about 50 that have this problem.
So I guess making indexStat work around this going to have to be done. I am going to start looking at that now.
________________________________________
From: Mike Matrigali [mikem_app@sbcglobal.net]
Sent: Saturday, March 31, 2012 6:28 PM
To: derby-dev@db.apache.org
Subject: Re: Question on why indexStat deamon is being triggered
Bergquist, Brett wrote:
> So I guess there are two things going on here. The indexStat is finding the left over rows. The second is that dropping a constraint should drop the statistics for the constraint as well.
>
> I really would like to get a fix going for this as in production I had to turn off indexStat because it was causing about a 20% performance hit. I do have tables that are going to start out empty each week and then be populated and will need the statistics present for queries during the week. I don't know enough yet about Derby to figure out how to determine this is a row for a constraint that does not exist anymore but will look into it.
>
do go ahead and log a JIRA with your info on drop not removing the stat.
But that fix is not going to help you.
I would suggest running an offline compress on your test case to see
if it gets rid of orphan row. If so it is the easiest workaround.
Next would see if drop table gets rid of it. If so, if you can afford
any downtime you could copy the data from the table to a temp table,
drop old table, and copy data back. I don't think derby rename will
help.
I think a code level fix would be in the area I suggested. Make the
update statistics code understand there might be unexpected rows and
delete them at update statistics time.
> ________________________________________
> From: Mike Matrigali [mikem_app@sbcglobal.net]
> Sent: Saturday, March 31, 2012 4:28 PM
> To: derby-dev@db.apache.org
> Subject: Re: Question on why indexStat deamon is being triggered
>
> Bergquist, Brett wrote:
>> I hitched up the debugger and caught the indexStat return "49" for the number of rows. I walked the stack back and found this was for conglomeratename = "f3ec4922-011d-491f-3d8c-0000376d74d3"
>>
>> So I did this query:
>>
>> select
>> c.TABLEID,
>> c.CONGLOMERATENUMBER,
>> c.CONGLOMERATENAME,
>> c.ISINDEX,
>> c.ISCONSTRAINT,
>> c.CONGLOMERATEID,
>> t.TABLEID,
>> t.TABLENAME,
>> t.TABLETYPE,
>> s.STATID,
>> s.REFERENCEID,
>> s.TABLEID,
>> s.CREATIONTIMESTAMP,
>> s.TYPE,
>> s.VALID,
>> s.COLCOUNT,
>> CAST(STATISTICS AS VARCHAR(40)) as STATISTICS
>> from sys.SYSCONGLOMERATES c join sys.SYSTABLES t on c.TABLEID = t.TABLEID join sys.SYSSTATISTICS s on s.TABLEID = t.TABLEID where c.CONGLOMERATENAME = 'f3ec4922-011d-491f-3d8c-0000376d74d3'
>>
>> Which is for one of the tables that I am having problems with. This returned:
>>
>> TABLEID CONGLOMERATENUMBER CONGLOMERATENAME ISINDEX ISCONSTRAINT CONGLOMERATEID TABLEID TABLENAME TABLETYPE STATID REFERENCEID TABLEID CREATIONTIMESTAMP TYPE VALID COLCOUNT STATISTICS
>> f3ec4922-011d-491f-3d8c-0000376d74d3 30768 f3ec4922-011d-491f-3d8c-0000376d74d3 false false 0e34c923-011d-491f-3d8c-0000376d74d3 f3ec4922-011d-491f-3d8c-0000376d74d3 BC01_CONFIGURATION_SET T 645c405f-0136-6999-c1b4-000065089f97 2c5f8294-012b-3c38-b55c-000043ea6398 f3ec4922-011d-491f-3d8c-0000376d74d3 2012-03-31 12:50:05.348 I true 1 numunique= 20334 numrows= 20334
>> f3ec4922-011d-491f-3d8c-0000376d74d3 30768 f3ec4922-011d-491f-3d8c-0000376d74d3 false false 0e34c923-011d-491f-3d8c-0000376d74d3 f3ec4922-011d-491f-3d8c-0000376d74d3 BC01_CONFIGURATION_SET T 49fc4ea2-0129-489a-0a26-00000732b350 592fcc26-011d-491f-3d8c-0000376d74d3 f3ec4922-011d-491f-3d8c-0000376d74d3 2010-06-17 23:16:40.018 I true 1 numunique= 49 numrows= 49
>> f3ec4922-011d-491f-3d8c-0000376d74d3 30768 f3ec4922-011d-491f-3d8c-0000376d74d3 false false 0e34c923-011d-491f-3d8c-0000376d74d3 f3ec4922-011d-491f-3d8c-0000376d74d3 BC01_CONFIGURATION_SET T 2c44c05e-0136-6999-c1b4-000065089f97 e9a40921-011d-491f-3d8c-0000376d74d3 f3ec4922-011d-491f-3d8c-0000376d74d3 2012-03-31 12:50:03.427 I true 1 numunique= 20334 numrows= 20334
>>
>> So there seems to be 3 statistics rows for this table. And low and behold there is the "numrows = 49" which I see the indexStat when I turn on tracing.
>>
> First thought is I didn't think we needed any statistics at all
> for a single column primary key.
>
> There should be entries in this catalog for every index on a table, so
> it is not necessarily expected to be one per table. I think for each
> index there is an entry for each column in the index (actually the stat
> applies to multiple columns so in a 3 column index I think there is an
> entry for (col1), (col1,col2), and (col1, col2, col3). But looking at
> your ddl I would only expect 1 entry, as there is one
> index on the table, and it has one column. I am not sure what the
> expectation is for the foreign key that matches the primary key, maybe
> it is 2 rows?
>
> I do wonder if the foreign key is causing some extra issues. I think
> in the long past we would end up creating 2 indexes in this case and
> they would be exactly the same. So functionality was added to just
> "logically" create the index and it would rely on the underlying
> physical index sort of "shared" by the primary key on id and the foreign
> constraint on id. We have had bugs in this area in the past and wonder
> if it left an "orphan" row in the statistics.
>
> Interesting that the second column it looks like it was created in 2010.
>
> seems like there might be multiple problems here. It would be great to
> figure out how the multiple rows got in there in the first place. I
> would suggest seeing what the system does for ddl in a brand new
> database, turn off index stat thread, run your ddl, add some rows to the
> table, and hand run update statistics procedure.
>
> I would not be surprised if existing code does not expect the number of
> rows you are seeing. If this is really a buggy orphan row, probably
> best zero admin fix is to change the update statistics code to look for
> other rows and delete them.
> you can follow the update statistic code starting at:
> java/engine/org/apache/derby/impl/sql/execute/AlterTableConstantAction/updateStatistics
>
> There may be a index stat daemon bug here too, but I think it might just
> be getting confused by the bad data in the catalog. Maybe it just keeps
> reading all the rows and queueing work, but calling update statistics
> only update 2 of the 3 rows.
>
>
>> I ran:
>>
>> VALUES syscs_util.syscs_check_table('PKG_9145E_V1', 'BC01_CONFIGURATION_SET')
>>
>> And this returns that the table is okay.
>>
>> I ran:
>>
>> VALUES syscs_util.syscs_check_table('SYS', 'SYSSTATISTICS')
>>
>> And this returns that the table is okay but I am not sure this is even valid.
>>
>> So the question is how/why are there 3 sets of statistics for this table. Here is the DDL for the table:
>>
>> CREATE TABLE "PKG_9145E_V1"."BC01_CONFIGURATION_SET"
>> (
>> ID int PRIMARY KEY NOT NULL
>> );
>> ALTER TABLE "PKG_9145E_V1"."BC01_CONFIGURATION_SET"
>> ADD CONSTRAINT BC01_CONFIGURATION_SET_FK_1 FOREIGN KEY (ID) REFERENCES "CORE_V1"."CONFIGURATION_SET"(ID) ;
>>
>>
>>
>> -----Original Message-----
>> From: Bergquist, Brett [mailto:BBergquist@canoga.com]
>> Sent: Friday, March 30, 2012 5:33 PM
>> To: derby-dev@db.apache.org
>> Subject: RE: Question on why indexStat deamon is being triggered
>>
>> I will hitch up the debugger and try to figure this out this weekend. I will keep you posted.
>> ________________________________________
>> From: Kristian Waagan [kristian.waagan@oracle.com]
>> Sent: Friday, March 30, 2012 4:36 PM
>> To: derby-dev@db.apache.org
>> Subject: Re: Question on why indexStat deamon is being triggered
>>
>> On 30.03.2012 18:57, Bergquist, Brett wrote:
>> I think there is something wrong with the indexStats. The problem I mentioned happens on a lot of tables. None of these tables are changing however, no inserts or deletes or updates. They are being queried, however.
>> Here is one such table. This is killing performance.
>>
>> Here is the statistics for this table:
>>
>> Table (Index) 2 3
>> ACCOUNTTABLE_CONFIG_BUNDLE (SQL081029110443810) numunique= 38390 numrows= 38390 2012-03-30 13:00:26.84
>> ACCOUNTTABLE_CONFIG_BUNDLE (SQL100922215819290) numunique= 38390 numrows= 38390 2012-03-30 13:00:26.917
>>
>> There are in fact 38390 rows in the table.
>>
>> Here is some of the stats trace:
>>
>> Fri Mar 30 12:47:12 EDT 2012 Thread[DRDAConnThread_43,5,main] {istat} "PKG_9145E_V1"."ACCOUNTTABLE_CONFIG_BUNDLE": update scheduled, reason=[t-est=38390, i-est=2355 => cmp=2.7912562815443245] (queueSize=12) Fri Mar 30 12:47:48 EDT 2012 Thread[index-stat-thread,5,main] {istat} "PKG_9145E_V1"."ACCOUNTTABLE_CONFIG_BUNDLE": wrote stats for index SQL081029110443810 (fc33890d-011d-491f-3d8c-0000376d74d3): rows=38390, card=[38390] Fri Mar 30 12:47:48 EDT 2012 Thread[index-stat-thread,5,main] {istat} "PKG_9145E_V1"."ACCOUNTTABLE_CONFIG_BUNDLE": wrote stats for index SQL100922215819290 (75608675-012b-3c38-b55c-000043ea6398): rows=38390, card=[38390] Fri Mar 30 12:47:48 EDT 2012 Thread[index-stat-thread,5,main] {istat} "PKG_9145E_V1"."ACCOUNTTABLE_CONFIG_BUNDLE": scan durations (c30625=91ms,c30625=98ms) Fri Mar 30 12:47:48 EDT 2012 Thread[index-stat-thread,5,main] {istat} "PKG_9145E_V1"."ACCOUNTTABLE_CONFIG_BUNDLE": generation complete (210 ms)
>>
>> Fri Mar 30 12:47:49 EDT 2012 Thread[DRDAConnThread_44,5,main] {istat} "PKG_9145E_V1"."ACCOUNTTABLE_CONFIG_BUNDLE": update scheduled, reason=[t-est=38390, i-est=2355 => cmp=2.7912562815443245] (queueSize=19) Fri Mar 30 12:48:25 EDT 2012 Thread[index-stat-thread,5,main] {istat} "PKG_9145E_V1"."ACCOUNTTABLE_CONFIG_BUNDLE": wrote stats for index SQL081029110443810 (fc33890d-011d-491f-3d8c-0000376d74d3): rows=38390, card=[38390] Fri Mar 30 12:48:25 EDT 2012 Thread[index-stat-thread,5,main] {istat} "PKG_9145E_V1"."ACCOUNTTABLE_CONFIG_BUNDLE": wrote stats for index SQL100922215819290 (75608675-012b-3c38-b55c-000043ea6398): rows=38390, card=[38390] Fri Mar 30 12:48:25 EDT 2012 Thread[index-stat-thread,5,main] {istat} "PKG_9145E_V1"."ACCOUNTTABLE_CONFIG_BUNDLE": scan durations (c30625=93ms,c30625=95ms) Fri Mar 30 12:48:25 EDT 2012 Thread[index-stat-thread,5,main] {istat} "PKG_9145E_V1"."ACCOUNTTABLE_CONFIG_BUNDLE": generation complete (211 ms) Fri Mar 30 12:48:25 EDT 2012 Thread[D
R
> DAConnThread_50,5,main] {istat} "PKG_9145E_V1"."ACCOUNTTABLE_CONFIG_BUNDLE": update scheduled, reason=[t-est=38390, i-est=2355 => cmp=2.7912562815443245] (queueSize=18)
>> Fri Mar 30 12:48:57 EDT 2012 Thread[index-stat-thread,5,main] {istat} "PKG_9145E_V1"."ACCOUNTTABLE_CONFIG_BUNDLE": wrote stats for index SQL081029110443810 (fc33890d-011d-491f-3d8c-0000376d74d3): rows=38390, card=[38390] Fri Mar 30 12:48:57 EDT 2012 Thread[index-stat-thread,5,main] {istat} "PKG_9145E_V1"."ACCOUNTTABLE_CONFIG_BUNDLE": wrote stats for index SQL100922215819290 (75608675-012b-3c38-b55c-000043ea6398): rows=38390, card=[38390] Fri Mar 30 12:48:57 EDT 2012 Thread[index-stat-thread,5,main] {istat} "PKG_9145E_V1"."ACCOUNTTABLE_CONFIG_BUNDLE": generation complete (243 ms)
>>
>> Fri Mar 30 12:49:27 EDT 2012 Thread[DRDAConnThread_56,5,main] {istat} "PKG_9145E_V1"."ACCOUNTTABLE_CONFIG_BUNDLE": update scheduled, reason=[t-est=38390, i-est=2355 => cmp=2.7912562815443245] (queueSize=20) Fri Mar 30 12:49:36 EDT 2012 Thread[index-stat-thread,5,main] {istat} "PKG_9145E_V1"."ACCOUNTTABLE_CONFIG_BUNDLE": wrote stats for index SQL081029110443810 (fc33890d-011d-491f-3d8c-0000376d74d3): rows=38390, card=[38390] Fri Mar 30 12:49:37 EDT 2012 Thread[index-stat-thread,5,main] {istat} "PKG_9145E_V1"."ACCOUNTTABLE_CONFIG_BUNDLE": wrote stats for index SQL100922215819290 (75608675-012b-3c38-b55c-000043ea6398): rows=38390, card=[38390] Fri Mar 30 12:49:37 EDT 2012 Thread[index-stat-thread,5,main] {istat} "PKG_9145E_V1"."ACCOUNTTABLE_CONFIG_BUNDLE": scan durations (c30625=111ms,c30625=108ms) Fri Mar 30 12:49:37 EDT 2012 Thread[index-stat-thread,5,main] {istat} "PKG_9145E_V1"."ACCOUNTTABLE_CONFIG_BUNDLE": generation complete (238 ms)
>>
>> Fri Mar 30 12:49:37 EDT 2012 Thread[DRDAConnThread_49,5,main] {istat} "PKG_9145E_V1"."ACCOUNTTABLE_CONFIG_BUNDLE": update scheduled, reason=[t-est=38390, i-est=2355 => cmp=2.7912562815443245] (queueSize=18)
>>
>> Any idea where I can look in the code? I would patch Derby if necessary
>>
>> I don't have the code in front of me, but could you maybe trace the creation of the statistics objects, with the goal of finding out where the lower number is coming from?
>> I think if you start looking in maybe CursorNode, possibly TableDescriptor, you should be able to get somewhere.
>>
>> Maybe you'll find that the lower number corresponds with an earlier/older version of the statistics for the index?
>> (a theory being that a stale statistics object is being read)
>>
>>
>> Just some late night ramblings,
>> --
>> Kristian
>>
>>
>> From: Bergquist, Brett [mailto:BBergquist@canoga.com]
>> Sent: Friday, March 30, 2012 10:58 AM
>> To: derby-dev@db.apache.org<ma...@db.apache.org>
>> Subject: RE: Question on why indexStat deamon is being triggered
>>
>> Thanks for taking a look at this. I do think something is wrong with the indexStats on this particular table.
>>
>> From: Kristian Waagan [mailto:kristian.waagan@oracle.com]
>> Sent: Friday, March 30, 2012 8:29 AM
>> To: derby-dev@db.apache.org<ma...@db.apache.org>
>> Subject: Re: Question on why indexStat deamon is being triggered
>>
>> On 30.03.2012 01:02, Bergquist, Brett wrote:
>> Here is the properties:
>>
>> derby.storage.indexStats.auto=true
>> derby.storage.indexStats.debug.lndiffThreshold=4.0
>> derby.storage.indexStats.log=true
>> derby.storage.indexStats.trace=log
>>
>>
>> The application is hitting the table PKG_9145E_V1"."BC01_CONFIGURATION_SET frequently. Many rows are being added and deleted but the total number of rows is not really changing that much if at all.
>>
>> Is the table completely emptied at any point?
>>
>> [bb] No, the table is never empty at any point during this. Basically about 300 rows being deleted and 300 new rows being added about every 30 seconds.
>>
>> Do you run anything else than insert and delete (with predicate) that modifies the table?
>> No, in fact the table has only one column:
>>
>> CREATE TABLE "PKG_9145E_V1"."BC01_CONFIGURATION_SET"
>> (
>> ID int PRIMARY KEY NOT NULL
>> )
>> ;
>> ALTER TABLE "PKG_9145E_V1"."BC01_CONFIGURATION_SET"
>> ADD CONSTRAINT BC01_CONFIGURATION_SET_FK_1 FOREIGN KEY (ID) REFERENCES "CORE_V1"."CONFIGURATION_SET"(ID) ;
>>
>>
>> What I don't understand is the line:
>>
>> Thu Mar 29 18:48:33 EDT 2012 Thread[DRDAConnThread_25,5,main] {istat} "PKG_9145E_V1"."BC01_CONFIGURATION_SET": update scheduled, reason=[t-est=44727, i-est=49 => cmp=6.816512326985881] (queueSize=1)
>>
>> abs(log(49) - log(44727)) = 6.816...
>>
>> t-est is the estimated number of rows as seen by the table [conglomerate], whereas i-est is the estimated number of rows as seen by the current index statistics. These are very different, and based on the output below, it appears t-est is correct when it says the number of rows is 44'727 [1]. So why isn't i-est changing?
>>
>> [bb] exactly my question.
>>
>>
>> What do you see if you look at the results from querying SYS.SYSSTATISTICS?
>> (i.e. columns STATISTICS [2] and CREATIONTIMESTAMP) What's the relevant DDL for the indexes/constraints in question?
>>
>> [bb]
>>
>> Table (Index) 2 3
>> BC01_CONFIGURATION_SET (SQL081029110445920) numunique= 44621 numrows= 44621 2012-03-30 10:17:07.073
>> BC01_CONFIGURATION_SET (SQL100922214723290) numunique= 44621 numrows= 44621 2012-03-30 10:17:07.187
>>
>> >From the log today:
>>
>> Fri Mar 30 10:15:32 EDT 2012 Thread[DRDAConnThread_103,5,main] {istat} "PKG_9145E_V1"."BC01_CONFIGURATION_SET": update scheduled, reason=[t-est=44527, i-est=49 => cmp=6.81203072762349] (queueSize=1) Fri Mar 30 10:15:32 EDT 2012 Thread[index-stat-thread,5,main] {istat,trace@154082288} worker thread started (xid=1705635865) [q/p/s=1/1018/1019,err:k/u/c=0/0/0,rej:f/d/o=0/618/0]
>> Fri Mar 30 10:15:32 EDT 2012 Thread[index-stat-thread,5,main] {istat,trace@154082288} processing "PKG_9145E_V1"."BC01_CONFIGURATION_SET"
>> Fri Mar 30 10:15:32 EDT 2012 Thread[index-stat-thread,5,main] {istat,trace@154082288} writing new stats (xid=1705635875)
>> Fri Mar 30 10:15:32 EDT 2012 Thread[index-stat-thread,5,main] {istat,trace@154082288} invalidation completed
>> Fri Mar 30 10:15:32 EDT 2012 Thread[index-stat-thread,5,main] {istat} "PKG_9145E_V1"."BC01_CONFIGURATION_SET": wrote stats for index SQL081029110445920 (e9a40921-011d-491f-3d8c-0000376d74d3): rows=44527, card=[44527]
>> Fri Mar 30 10:15:32 EDT 2012 Thread[index-stat-thread,5,main] {istat,trace@154082288} writing new stats (xid=1705635891)
>> Fri Mar 30 10:15:32 EDT 2012 Thread[index-stat-thread,5,main] {istat,trace@154082288} invalidation completed
>> Fri Mar 30 10:15:32 EDT 2012 Thread[index-stat-thread,5,main] {istat} "PKG_9145E_V1"."BC01_CONFIGURATION_SET": wrote stats for index SQL100922214723290 (2c5f8294-012b-3c38-b55c-000043ea6398): rows=44527, card=[44527] Fri Mar 30 10:15:32 EDT 2012 Thread[index-stat-thread,5,main] {istat} "PKG_9145E_V1"."BC01_CONFIGURATION_SET": scan durations (c30785=106ms,c30785=100ms) Fri Mar 30 10:15:32 EDT 2012 Thread[index-stat-thread,5,main] {istat} "PKG_9145E_V1"."BC01_CONFIGURATION_SET": generation complete (251 ms)
>> Fri Mar 30 10:15:32 EDT 2012 Thread[index-stat-thread,5,main] {istat,trace@154082288} queue empty
>> Fri Mar 30 10:15:32 EDT 2012 Thread[index-stat-thread,5,main] {istat,trace@154082288} worker thread exit [q/p/s=0/1019/1019,err:k/u/c=0/0/0,rej:f/d/o=0/618/0]
>>
>> So it seems that even just recently this morning, it still thinks that the index only has 49 rows
>>
>> The same values are being shown each time. Is this correct?
>>
>> At least i-est seems off.
>> Do/did you see similar problems with other tables/indexes?
>> You can check the values by doing a select count and looking at the statistics stored in the system table.
>>
>> Today there are 44621 rows. I was running some test over night and did do some deletes that would cause this to go down.
>>
>> I am trying to tune the indexStat daemon so that it will run when needed but not too frequently. With the default value, I was seeing about a 20% penalty when running the application and saw the indexStat daemon nearly non-stop. So I adjusted the lndiffThreshold to be 4.0 an it is not running too frequently but I still would like to understand what the trace/log is telling me.
>>
>> A lndiffThreshold of 4.0 means the table has to grow (or shrink) by a factor of roughly 54.6. In the specific case above, the index statistics for the table shouldn't be generated again before there are ([3]) nearly two and a half million rows in it (or less than 820).
>> I'd say a threshold of 4.0 is pretty relaxed - do you expect the distribution/cardinality of the values to be similar for a table with 50K rows and 2500K rows?
>>
>> [bb] I have other tables that are constantly being inserted into where each record will be unique. The table has 2 indexes on it where one is unique and 2 will have duplicates. This table will end up with about 42M records in a week, will stay around for 2 weeks and then will be empty again and not used for 50 weeks of the year. Basically there is one table per week of the year that starts as empty, is populated for the week, data stays around for 2 weeks for query purposes, and then is purged out. The important thing is that once the week table starts to be populated, queries will start hitting that table so it is important that the queries use the indexes on the table. The table is inserted at a rate of about 60 records/second so after a few thousand records I want the statistics to be generated and the indexes to be used.
>>
>> So maybe 4.0 is too much but 1.0 was generating statistics constantly.
>>
>> I copied a line from below:
>> [q/p/s=0/268/268,err:k/u/c=0/0/0,rej:f/d/o=0/303/0]
>> q = queued
>> p = processed
>> s = scheduled
>> k = known errors (the daemon is prepared for these and can easily recover) u = unknown errors c = consecutive errors (daemon will disable itself if there are too many consecutive errors) f = rejection due to full queue d = rejection due to duplicate request (already in the queue) o = other (currently only tracks scheduling attempts when the daemon has been disabled)
>>
>>
>> FYI, I'm aware that your options to fine-tune the statistics generation is rather limited.
>>
>>
>> Regards,
>> --
>> Kristian
>>
>> [1] "wrote stats for index X (id): rows=44727, card=[44727]"
>> [2] In ij I had to cast this to see everything: cast(STATISTICS as VARCHAR(40)) [3] Or rather before Derby believes there are so many rows in the table - we're working with estimates here.
>>
>>
>> Here is a snippet of the output:
>>
>> Thu Mar 29 18:48:02 EDT 2012 Thread[index-stat-thread,5,main] {istat,trace@154082288} writing new stats (xid=1681453075)
>> Thu Mar 29 18:48:02 EDT 2012 Thread[index-stat-thread,5,main] {istat,trace@154082288} invalidation completed
>> Thu Mar 29 18:48:02 EDT 2012 Thread[index-stat-thread,5,main] {istat} "PKG_9145E_V1"."BC01_CONFIGURATION_SET": wrote stats for index SQL081029110445920 (e9a40921-011d-491f-3d8c-0000376d74d3): rows=44727, card=[44727]
>> Thu Mar 29 18:48:02 EDT 2012 Thread[index-stat-thread,5,main] {istat,trace@154082288} writing new stats (xid=1681453158)
>> Thu Mar 29 18:48:02 EDT 2012 Thread[index-stat-thread,5,main] {istat,trace@154082288} invalidation completed
>> Thu Mar 29 18:48:02 EDT 2012 Thread[index-stat-thread,5,main] {istat} "PKG_9145E_V1"."BC01_CONFIGURATION_SET": wrote stats for index SQL100922214723290 (2c5f8294-012b-3c38-b55c-000043ea6398): rows=44727, card=[44727] Thu Mar 29 18:48:02 EDT 2012 Thread[index-stat-thread,5,main] {istat} "PKG_9145E_V1"."BC01_CONFIGURATION_SET": scan durations (c30785=144ms,c30785=135ms) Thu Mar 29 18:48:02 EDT 2012 Thread[index-stat-thread,5,main] {istat} "PKG_9145E_V1"."BC01_CONFIGURATION_SET": generation complete (300 ms)
>> Thu Mar 29 18:48:02 EDT 2012 Thread[index-stat-thread,5,main] {istat,trace@154082288} queue empty
>> Thu Mar 29 18:48:02 EDT 2012 Thread[index-stat-thread,5,main] {istat,trace@154082288} worker thread exit [q/p/s=0/266/266,err:k/u/c=0/0/0,rej:f/d/o=0/303/0]
>> Thu Mar 29 18:48:12 EDT 2012 Thread[DRDAConnThread_42,5,main] {istat} "PKG_9145E_V1"."BC01_CONFIGURATION_SET": update scheduled, reason=[t-est=44727, i-est=49 => cmp=6.816512326985881] (queueSize=1) Thu Mar 29 18:48:12 EDT 2012 Thread[index-stat-thread,5,main] {istat,trace@154082288} worker thread started (xid=1681453158) [q/p/s=1/266/267,err:k/u/c=0/0/0,rej:f/d/o=0/303/0]
>> Thu Mar 29 18:48:12 EDT 2012 Thread[index-stat-thread,5,main] {istat,trace@154082288} processing "PKG_9145E_V1"."BC01_CONFIGURATION_SET"
>> Thu Mar 29 18:48:12 EDT 2012 Thread[index-stat-thread,5,main] {istat,trace@154082288} writing new stats (xid=1681462384)
>> Thu Mar 29 18:48:12 EDT 2012 Thread[index-stat-thread,5,main] {istat,trace@154082288} invalidation completed
>> Thu Mar 29 18:48:12 EDT 2012 Thread[index-stat-thread,5,main] {istat} "PKG_9145E_V1"."BC01_CONFIGURATION_SET": wrote stats for index SQL081029110445920 (e9a40921-011d-491f-3d8c-0000376d74d3): rows=44727, card=[44727]
>> Thu Mar 29 18:48:12 EDT 2012 Thread[index-stat-thread,5,main] {istat,trace@154082288} writing new stats (xid=1681462622)
>> Thu Mar 29 18:48:12 EDT 2012 Thread[index-stat-thread,5,main] {istat,trace@154082288} invalidation completed
>> Thu Mar 29 18:48:12 EDT 2012 Thread[index-stat-thread,5,main] {istat} "PKG_9145E_V1"."BC01_CONFIGURATION_SET": wrote stats for index SQL100922214723290 (2c5f8294-012b-3c38-b55c-000043ea6398): rows=44727, card=[44727] Thu Mar 29 18:48:12 EDT 2012 Thread[index-stat-thread,5,main] {istat} "PKG_9145E_V1"."BC01_CONFIGURATION_SET": scan durations (c30785=152ms,c30785=138ms) Thu Mar 29 18:48:12 EDT 2012 Thread[index-stat-thread,5,main] {istat} "PKG_9145E_V1"."BC01_CONFIGURATION_SET": generation complete (306 ms)
>> Thu Mar 29 18:48:12 EDT 2012 Thread[index-stat-thread,5,main] {istat,trace@154082288} queue empty
>> Thu Mar 29 18:48:12 EDT 2012 Thread[index-stat-thread,5,main] {istat,trace@154082288} worker thread exit [q/p/s=0/267/267,err:k/u/c=0/0/0,rej:f/d/o=0/303/0]
>> Thu Mar 29 18:48:33 EDT 2012 Thread[DRDAConnThread_25,5,main] {istat} "PKG_9145E_V1"."BC01_CONFIGURATION_SET": update scheduled, reason=[t-est=44727, i-est=49 => cmp=6.816512326985881] (queueSize=1) Thu Mar 29 18:48:33 EDT 2012 Thread[index-stat-thread,5,main] {istat,trace@154082288} worker thread started (xid=1681462622) [q/p/s=1/267/268,err:k/u/c=0/0/0,rej:f/d/o=0/303/0]
>> Thu Mar 29 18:48:33 EDT 2012 Thread[index-stat-thread,5,main] {istat,trace@154082288} processing "PKG_9145E_V1"."BC01_CONFIGURATION_SET"
>> Thu Mar 29 18:48:33 EDT 2012 Thread[index-stat-thread,5,main] {istat,trace@154082288} writing new stats (xid=1681479731)
>> Thu Mar 29 18:48:33 EDT 2012 Thread[index-stat-thread,5,main] {istat,trace@154082288} invalidation completed
>> Thu Mar 29 18:48:33 EDT 2012 Thread[index-stat-thread,5,main] {istat} "PKG_9145E_V1"."BC01_CONFIGURATION_SET": wrote stats for index SQL081029110445920 (e9a40921-011d-491f-3d8c-0000376d74d3): rows=44727, card=[44727]
>> Thu Mar 29 18:48:33 EDT 2012 Thread[index-stat-thread,5,main] {istat,trace@154082288} writing new stats (xid=1681479756)
>> Thu Mar 29 18:48:33 EDT 2012 Thread[index-stat-thread,5,main] {istat,trace@154082288} invalidation completed
>> Thu Mar 29 18:48:33 EDT 2012 Thread[index-stat-thread,5,main] {istat} "PKG_9145E_V1"."BC01_CONFIGURATION_SET": wrote stats for index SQL100922214723290 (2c5f8294-012b-3c38-b55c-000043ea6398): rows=44727, card=[44727] Thu Mar 29 18:48:33 EDT 2012 Thread[index-stat-thread,5,main] {istat} "PKG_9145E_V1"."BC01_CONFIGURATION_SET": scan durations (c30785=95ms,c30785=103ms) Thu Mar 29 18:48:33 EDT 2012 Thread[index-stat-thread,5,main] {istat} "PKG_9145E_V1"."BC01_CONFIGURATION_SET": generation complete (214 ms)
>> Thu Mar 29 18:48:33 EDT 2012 Thread[index-stat-thread,5,main] {istat,trace@154082288} queue empty
>> Thu Mar 29 18:48:33 EDT 2012 Thread[index-stat-thread,5,main] {istat,trace@154082288} worker thread exit [q/p/s=0/268/268,err:k/u/c=0/0/0,rej:f/d/o=0/303/0]
>> Thu Mar 29 18:48:44 EDT 2012 Thread[DRDAConnThread_26,5,main] {istat} "PKG_9145E_V1"."BC01_CONFIGURATION_SET": update scheduled, reason=[t-est=44727, i-est=49 => cmp=6.816512326985881] (queueSize=1) Thu Mar 29 18:48:44 EDT 2012 Thread[index-stat-thread,5,main] {istat,trace@154082288} worker thread started (xid=1681479756) [q/p/s=1/268/269,err:k/u/c=0/0/0,rej:f/d/o=0/303/0]
>> Thu Mar 29 18:48:44 EDT 2012 Thread[index-stat-thread,5,main] {istat,trace@154082288} processing "PKG_9145E_V1"."BC01_CONFIGURATION_SET"
>> Thu Mar 29 18:48:44 EDT 2012 Thread[index-stat-thread,5,main] {istat,trace@154082288} writing new stats (xid=1681487715)
>> Thu Mar 29 18:48:44 EDT 2012 Thread[index-stat-thread,5,main] {istat,trace@154082288} invalidation completed
>> Thu Mar 29 18:48:44 EDT 2012 Thread[index-stat-thread,5,main] {istat} "PKG_9145E_V1"."BC01_CONFIGURATION_SET": wrote stats for index SQL081029110445920 (e9a40921-011d-491f-3d8c-0000376d74d3): rows=44727, card=[44727]
>> Thu Mar 29 18:48:45 EDT 2012 Thread[index-stat-thread,5,main] {istat,trace@154082288} writing new stats (xid=1681487764)
>> Thu Mar 29 18:48:45 EDT 2012 Thread[index-stat-thread,5,main] {istat,trace@154082288} invalidation completed
>> Thu Mar 29 18:48:45 EDT 2012 Thread[index-stat-thread,5,main] {istat} "PKG_9145E_V1"."BC01_CONFIGURATION_SET": wrote stats for index SQL100922214723290 (2c5f8294-012b-3c38-b55c-000043ea6398): rows=44727, card=[44727] Thu Mar 29 18:48:45 EDT 2012 Thread[index-stat-thread,5,main] {istat} "PKG_9145E_V1"."BC01_CONFIGURATION_SET": scan durations (c30785=101ms,c30785=118ms) Thu Mar 29 18:48:45 EDT 2012 Thread[index-stat-thread,5,main] {istat} "PKG_9145E_V1"."BC01_CONFIGURATION_SET": generation complete (231 ms)
>> Thu Mar 29 18:48:45 EDT 2012 Thread[index-stat-thread,5,main] {istat,trace@154082288} queue empty
>> Thu Mar 29 18:48:45 EDT 2012 Thread[index-stat-thread,5,main] {istat,trace@154082288} worker thread exit [q/p/s=0/269/269,err:k/u/c=0/0/0,rej:f/d/o=0/303/0]
>> Thu Mar 29 18:48:46 EDT 2012 Thread[DRDAConnThread_39,5,main] {istat} "PKG_9145E_V1"."BC01_CONFIGURATION_SET": update scheduled, reason=[t-est=44727, i-est=49 => cmp=6.816512326985881] (queueSize=1) Thu Mar 29 18:48:46 EDT 2012 Thread[index-stat-thread,5,main] {istat,trace@154082288} worker thread started (xid=1681487764) [q/p/s=1/269/270,err:k/u/c=0/0/0,rej:f/d/o=0/303/0]
>> Thu Mar 29 18:48:46 EDT 2012 Thread[index-stat-thread,5,main] {istat,trace@154082288} processing "PKG_9145E_V1"."BC01_CONFIGURATION_SET"
>> Thu Mar 29 18:48:46 EDT 2012 Thread[index-stat-thread,5,main] {istat,trace@154082288} writing new stats (xid=1681489467)
>> Thu Mar 29 18:48:46 EDT 2012 Thread[index-stat-thread,5,main] {istat,trace@154082288} invalidation completed
>> Thu Mar 29 18:48:47 EDT 2012 Thread[index-stat-thread,5,main] {istat} "PKG_9145E_V1"."BC01_CONFIGURATION_SET": wrote stats for index SQL081029110445920 (e9a40921-011d-491f-3d8c-0000376d74d3): rows=44727, card=[44727]
>> Thu Mar 29 18:48:47 EDT 2012 Thread[index-stat-thread,5,main] {istat,trace@154082288} writing new stats (xid=1681489541)
>> Thu Mar 29 18:48:47 EDT 2012 Thread[index-stat-thread,5,main] {istat,trace@154082288} invalidation completed
>> Thu Mar 29 18:48:47 EDT 2012 Thread[index-stat-thread,5,main] {istat} "PKG_9145E_V1"."BC01_CONFIGURATION_SET": wrote stats for index SQL100922214723290 (2c5f8294-012b-3c38-b55c-000043ea6398): rows=44727, card=[44727] Thu Mar 29 18:48:47 EDT 2012 Thread[index-stat-thread,5,main] {istat} "PKG_9145E_V1"."BC01_CONFIGURATION_SET": scan durations (c30785=119ms,c30785=130ms) Thu Mar 29 18:48:47 EDT 2012 Thread[index-stat-thread,5,main] {istat} "PKG_9145E_V1"."BC01_CONFIGURATION_SET": generation complete (269 ms)
>> Thu Mar 29 18:48:47 EDT 2012 Thread[index-stat-thread,5,main] {istat,trace@154082288} queue empty
>> Thu Mar 29 18:48:47 EDT 2012 Thread[index-stat-thread,5,main] {istat,trace@154082288} worker thread exit [q/p/s=0/270/270,err:k/u/c=0/0/0,rej:f/d/o=0/303/0]
>> Thu Mar 29 18:48:53 EDT 2012 Thread[DRDAConnThread_22,5,main] {istat} "PKG_9145E_V1"."BC01_CONFIGURATION_SET": update scheduled, reason=[t-est=44727, i-est=49 => cmp=6.816512326985881] (queueSize=1) Thu Mar 29 18:48:53 EDT 2012 Thread[index-stat-thread,5,main] {istat,trace@154082288} worker thread started (xid=1681489541) [q/p/s=1/270/271,err:k/u/c=0/0/0,rej:f/d/o=0/303/0]
>> Thu Mar 29 18:48:53 EDT 2012 Thread[index-stat-thread,5,main] {istat,trace@154082288} processing "PKG_9145E_V1"."BC01_CONFIGURATION_SET"
>> Thu Mar 29 18:48:53 EDT 2012 Thread[index-stat-thread,5,main] {istat,trace@154082288} writing new stats (xid=1681495081)
>> Thu Mar 29 18:48:53 EDT 2012 Thread[index-stat-thread,5,main] {istat,trace@154082288} invalidation completed
>> Thu Mar 29 18:48:53 EDT 2012 Thread[index-stat-thread,5,main] {istat} "PKG_9145E_V1"."BC01_CONFIGURATION_SET": wrote stats for index SQL081029110445920 (e9a40921-011d-491f-3d8c-0000376d74d3): rows=44727, card=[44727]
>> Thu Mar 29 18:48:53 EDT 2012 Thread[index-stat-thread,5,main] {istat,trace@154082288} writing new stats (xid=1681495161)
>> Thu Mar 29 18:48:53 EDT 2012 Thread[index-stat-thread,5,main] {istat,trace@154082288} invalidation completed
>> Thu Mar 29 18:48:53 EDT 2012 Thread[index-stat-thread,5,main] {istat} "PKG_9145E_V1"."BC01_CONFIGURATION_SET": wrote stats for index SQL100922214723290 (2c5f8294-012b-3c38-b55c-000043ea6398): rows=44727, card=[44727] Thu Mar 29 18:48:53 EDT 2012 Thread[index-stat-thread,5,main] {istat} "PKG_9145E_V1"."BC01_CONFIGURATION_SET": scan durations (c30785=200ms,c30785=126ms) Thu Mar 29 18:48:53 EDT 2012 Thread[index-stat-thread,5,main] {istat} "PKG_9145E_V1"."BC01_CONFIGURATION_SET": generation complete (343 ms)
>> Thu Mar 29 18:48:53 EDT 2012 Thread[index-stat-thread,5,main] {istat,trace@154082288} queue empty
>> Thu Mar 29 18:48:53 EDT 2012 Thread[index-stat-thread,5,main] {istat,trace@154082288} worker thread exit [q/p/s=0/271/271,err:k/u/c=0/0/0,rej:f/d/o=0/303/0]
>> Thu Mar 29 18:49:08 EDT 2012 Thread[DRDAConnThread_35,5,main] {istat} "PKG_9145E_V1"."BC01_CONFIGURATION_SET": update scheduled, reason=[t-est=44727, i-est=49 => cmp=6.816512326985881] (queueSize=1) Thu Mar 29 18:49:08 EDT 2012 Thread[index-stat-thread,5,main] {istat,trace@154082288} worker thread started (xid=1681495161) [q/p/s=1/271/272,err:k/u/c=0/0/0,rej:f/d/o=0/303/0]
>> Thu Mar 29 18:49:08 EDT 2012 Thread[index-stat-thread,5,main] {istat,trace@154082288} processing "PKG_9145E_V1"."BC01_CONFIGURATION_SET"
>> Thu Mar 29 18:49:09 EDT 2012 Thread[index-stat-thread,5,main] {istat,trace@154082288} writing new stats (xid=1681510950)
>> Thu Mar 29 18:49:09 EDT 2012 Thread[index-stat-thread,5,main] {istat,trace@154082288} invalidation completed
>> Thu Mar 29 18:49:09 EDT 2012 Thread[index-stat-thread,5,main] {istat} "PKG_9145E_V1"."BC01_CONFIGURATION_SET": wrote stats for index SQL081029110445920 (e9a40921-011d-491f-3d8c-0000376d74d3): rows=44727, card=[44727]
>> Thu Mar 29 18:49:09 EDT 2012 Thread[index-stat-thread,5,main] {istat,trace@154082288} writing new stats (xid=1681511028)
>> Thu Mar 29 18:49:09 EDT 2012 Thread[index-stat-thread,5,main] {istat,trace@154082288} invalidation completed
>> Thu Mar 29 18:49:09 EDT 2012 Thread[index-stat-thread,5,main] {istat} "PKG_9145E_V1"."BC01_CONFIGURATION_SET": wrote stats for index SQL100922214723290 (2c5f8294-012b-3c38-b55c-000043ea6398): rows=44727, card=[44727] Thu Mar 29 18:49:09 EDT 2012 Thread[index-stat-thread,5,main] {istat} "PKG_9145E_V1"."BC01_CONFIGURATION_SET": scan durations (c30785=228ms,c30785=111ms) Thu Mar 29 18:49:09 EDT 2012 Thread[index-stat-thread,5,main] {istat} "PKG_9145E_V1"."BC01_CONFIGURATION_SET": generation complete (358 ms)
>> Thu Mar 29 18:49:09 EDT 2012 Thread[index-stat-thread,5,main] {istat,trace@154082288} queue empty
>> Thu Mar 29 18:49:09 EDT 2012 Thread[index-stat-thread,5,main] {istat,trace@154082288} worker thread exit [q/p/s=0/272/272,err:k/u/c=0/0/0,rej:f/d/o=0/303/0]
>> Thu Mar 29 18:49:11 EDT 2012 Thread[DRDAConnThread_25,5,main] {istat} "PKG_9145E_V1"."BC01_CONFIGURATION_SET": update scheduled, reason=[t-est=44727, i-est=49 => cmp=6.816512326985881] (queueSize=1) Thu Mar 29 18:49:11 EDT 2012 Thread[index-stat-thread,5,main] {istat,trace@154082288} worker thread started (xid=1681511028) [q/p/s=1/272/273,err:k/u/c=0/0/0,rej:f/d/o=0/303/0]
>> Thu Mar 29 18:49:11 EDT 2012 Thread[index-stat-thread,5,main] {istat,trace@154082288} processing "PKG_9145E_V1"."BC01_CONFIGURATION_SET"
>> Thu Mar 29 18:49:11 EDT 2012 Thread[index-stat-thread,5,main] {istat,trace@154082288} writing new stats (xid=1681512771)
>> Thu Mar 29 18:49:11 EDT 2012 Thread[index-stat-thread,5,main] {istat,trace@154082288} invalidation completed
>> Thu Mar 29 18:49:11 EDT 2012 Thread[index-stat-thread,5,main] {istat} "PKG_9145E_V1"."BC01_CONFIGURATION_SET": wrote stats for index SQL081029110445920 (e9a40921-011d-491f-3d8c-0000376d74d3): rows=44727, card=[44727]
>> Thu Mar 29 18:49:11 EDT 2012 Thread[index-stat-thread,5,main] {istat,trace@154082288} writing new stats (xid=1681512851)
>> Thu Mar 29 18:49:11 EDT 2012 Thread[index-stat-thread,5,main] {istat,trace@154082288} invalidation completed
>> Thu Mar 29 18:49:11 EDT 2012 Thread[index-stat-thread,5,main] {istat} "PKG_9145E_V1"."BC01_CONFIGURATION_SET": wrote stats for index SQL100922214723290 (2c5f8294-012b-3c38-b55c-000043ea6398): rows=44727, card=[44727] Thu Mar 29 18:49:11 EDT 2012 Thread[index-stat-thread,5,main] {istat} "PKG_9145E_V1"."BC01_CONFIGURATION_SET": scan durations (c30785=118ms,c30785=118ms) Thu Mar 29 18:49:11 EDT 2012 Thread[index-stat-thread,5,main] {istat} "PKG_9145E_V1"."BC01_CONFIGURATION_SET": generation complete (259 ms)
>> Thu Mar 29 18:49:11 EDT 2012 Thread[index-stat-thread,5,main] {istat,trace@154082288} queue empty
>> Thu Mar 29 18:49:11 EDT 2012 Thread[index-stat-thread,5,main] {istat,trace@154082288} worker thread exit [q/p/s=0/273/273,err:k/u/c=0/0/0,rej:f/d/o=0/303/0]
>> Thu Mar 29 18:49:17 EDT 2012 Thread[DRDAConnThread_38,5,main] {istat} "PKG_9145E_V1"."BC01_CONFIGURATION_SET": update scheduled, reason=[t-est=44727, i-est=49 => cmp=6.816512326985881] (queueSize=1) Thu Mar 29 18:49:17 EDT 2012 Thread[index-stat-thread,5,main] {istat,trace@154082288} worker thread started (xid=1681512851) [q/p/s=1/273/274,err:k/u/c=0/0/0,rej:f/d/o=0/303/0]
>> Thu Mar 29 18:49:17 EDT 2012 Thread[index-stat-thread,5,main] {istat,trace@154082288} processing "PKG_9145E_V1"."BC01_CONFIGURATION_SET"
>> Thu Mar 29 18:49:17 EDT 2012 Thread[index-stat-thread,5,main] {istat,trace@154082288} writing new stats (xid=1681518290)
>> Thu Mar 29 18:49:17 EDT 2012 Thread[index-stat-thread,5,main] {istat,trace@154082288} invalidation completed
>> Thu Mar 29 18:49:17 EDT 2012 Thread[index-stat-thread,5,main] {istat} "PKG_9145E_V1"."BC01_CONFIGURATION_SET": wrote stats for index SQL081029110445920 (e9a40921-011d-491f-3d8c-0000376d74d3): rows=44727, card=[44727]
>> Thu Mar 29 18:49:18 EDT 2012 Thread[index-stat-thread,5,main] {istat,trace@154082288} writing new stats (xid=1681518363)
>> Thu Mar 29 18:49:18 EDT 2012 Thread[index-stat-thread,5,main] {istat,trace@154082288} invalidation completed
>> Thu Mar 29 18:49:18 EDT 2012 Thread[index-stat-thread,5,main] {istat} "PKG_9145E_V1"."BC01_CONFIGURATION_SET": wrote stats for index SQL100922214723290 (2c5f8294-012b-3c38-b55c-000043ea6398): rows=44727, card=[44727] Thu Mar 29 18:49:18 EDT 2012 Thread[index-stat-thread,5,main] {istat} "PKG_9145E_V1"."BC01_CONFIGURATION_SET": scan durations (c30785=118ms,c30785=216ms) Thu Mar 29 18:49:18 EDT 2012 Thread[index-stat-thread,5,main] {istat} "PKG_9145E_V1"."BC01_CONFIGURATION_SET": generation complete (351 ms)
>> Thu Mar 29 18:49:18 EDT 2012 Thread[index-stat-thread,5,main] {istat,trace@154082288} queue empty
>> Thu Mar 29 18:49:18 EDT 2012 Thread[index-stat-thread,5,main] {istat,trace@154082288} worker thread exit [q/p/s=0/274/274,err:k/u/c=0/0/0,rej:f/d/o=0/303/0]
>> Thu Mar 29 18:49:34 EDT 2012 Thread[DRDAConnThread_35,5,main] {istat} "PKG_9145E_V1"."BC01_CONFIGURATION_SET": update scheduled, reason=[t-est=44727, i-est=49 => cmp=6.816512326985881] (queueSize=1) Thu Mar 29 18:49:34 EDT 2012 Thread[index-stat-thread,5,main] {istat,trace@154082288} worker thread started (xid=1681518363) [q/p/s=1/274/275,err:k/u/c=0/0/0,rej:f/d/o=0/303/0]
>> Thu Mar 29 18:49:34 EDT 2012 Thread[index-stat-thread,5,main] {istat,trace@154082288} processing "PKG_9145E_V1"."BC01_CONFIGURATION_SET"
>> Thu Mar 29 18:49:34 EDT 2012 Thread[index-stat-thread,5,main] {istat,trace@154082288} writing new stats (xid=1681534090)
>> Thu Mar 29 18:49:34 EDT 2012 Thread[index-stat-thread,5,main] {istat,trace@154082288} invalidation completed
>> Thu Mar 29 18:49:34 EDT 2012 Thread[index-stat-thread,5,main] {istat} "PKG_9145E_V1"."BC01_CONFIGURATION_SET": wrote stats for index SQL081029110445920 (e9a40921-011d-491f-3d8c-0000376d74d3): rows=44727, card=[44727]
>> Thu Mar 29 18:49:34 EDT 2012 Thread[index-stat-thread,5,main] {istat,trace@154082288} writing new stats (xid=1681534168)
>> Thu Mar 29 18:49:34 EDT 2012 Thread[index-stat-thread,5,main] {istat,trace@154082288} invalidation completed
>> Thu Mar 29 18:49:34 EDT 2012 Thread[index-stat-thread,5,main] {istat} "PKG_9145E_V1"."BC01_CONFIGURATION_SET": wrote stats for index SQL100922214723290 (2c5f8294-012b-3c38-b55c-000043ea6398): rows=44727, card=[44727] Thu Mar 29 18:49:34 EDT 2012 Thread[index-stat-thread,5,main] {istat} "PKG_9145E_V1"."BC01_CONFIGURATION_SET": scan durations (c30785=112ms,c30785=217ms) Thu Mar 29 18:49:34 EDT 2012 Thread[index-stat-thread,5,main] {istat} "PKG_9145E_V1"."BC01_CONFIGURATION_SET": generation complete (352 ms)
>> Thu Mar 29 18:49:34 EDT 2012 Thread[index-stat-thread,5,main] {istat,trace@154082288} queue empty
>> Thu Mar 29 18:49:34 EDT 2012 Thread[index-stat-thread,5,main] {istat,trace@154082288} worker thread exit [q/p/s=0/275/275,err:k/u/c=0/0/0,rej:f/d/o=0/303/0]
>> Thu Mar 29 18:49:36 EDT 2012 Thread[DRDAConnThread_25,5,main] {istat} "PKG_9145E_V1"."BC01_CONFIGURATION_SET": update scheduled, reason=[t-est=44727, i-est=49 => cmp=6.816512326985881] (queueSize=1) Thu Mar 29 18:49:36 EDT 2012 Thread[index-stat-thread,5,main] {istat,trace@154082288} worker thread started (xid=1681534168) [q/p/s=1/275/276,err:k/u/c=0/0/0,rej:f/d/o=0/303/0]
>> Thu Mar 29 18:49:36 EDT 2012 Thread[index-stat-thread,5,main] {istat,trace@154082288} processing "PKG_9145E_V1"."BC01_CONFIGURATION_SET"
>> Thu Mar 29 18:49:37 EDT 2012 Thread[index-stat-thread,5,main] {istat,trace@154082288} writing new stats (xid=1681536662)
>> Thu Mar 29 18:49:37 EDT 2012 Thread[index-stat-thread,5,main] {istat,trace@154082288} invalidation completed
>> Thu Mar 29 18:49:37 EDT 2012 Thread[index-stat-thread,5,main] {istat} "PKG_9145E_V1"."BC01_CONFIGURATION_SET": wrote stats for index SQL081029110445920 (e9a40921-011d-491f-3d8c-0000376d74d3): rows=44727, card=[44727]
>> Thu Mar 29 18:49:37 EDT 2012 Thread[index-stat-thread,5,main] {istat,trace@154082288} writing new stats (xid=1681536775)
>> Thu Mar 29 18:49:37 EDT 2012 Thread[index-stat-thread,5,main] {istat,trace@154082288} invalidation completed
>> Thu Mar 29 18:49:37 EDT 2012 Thread[index-stat-thread,5,main] {istat} "PKG_9145E_V1"."BC01_CONFIGURATION_SET": wrote stats for index SQL100922214723290 (2c5f8294-012b-3c38-b55c-000043ea6398): rows=44727, card=[44727] Thu Mar 29 18:49:37 EDT 2012 Thread[index-stat-thread,5,main] {istat} "PKG_9145E_V1"."BC01_CONFIGURATION_SET": scan durations (c30785=133ms,c30785=127ms) Thu Mar 29 18:49:37 EDT 2012 Thread[index-stat-thread,5,main] {istat} "PKG_9145E_V1"."BC01_CONFIGURATION_SET": generation complete (285 ms)
>> Thu Mar 29 18:49:37 EDT 2012 Thread[index-stat-thread,5,main] {istat,trace@154082288} queue empty
>> Thu Mar 29 18:49:37 EDT 2012 Thread[index-stat-thread,5,main] {istat,trace@154082288} worker thread exit [q/p/s=0/276/276,err:k/u/c=0/0/0,rej:f/d/o=0/303/0]
>> Thu Mar 29 18:49:42 EDT 2012 Thread[DRDAConnThread_29,5,main] {istat} "PKG_9145E_V1"."BC01_CONFIGURATION_SET": update scheduled, reason=[t-est=44727, i-est=49 => cmp=6.816512326985881] (queueSize=1) Thu Mar 29 18:49:42 EDT 2012 Thread[index-stat-thread,5,main] {istat,trace@154082288} worker thread started (xid=1681536775) [q/p/s=1/276/277,err:k/u/c=0/0/0,rej:f/d/o=0/303/0]
>> Thu Mar 29 18:49:42 EDT 2012 Thread[index-stat-thread,5,main] {istat,trace@154082288} processing "PKG_9145E_V1"."BC01_CONFIGURATION_SET"
>> Thu Mar 29 18:49:42 EDT 2012 Thread[index-stat-thread,5,main] {istat,trace@154082288} writing new stats (xid=1681541238)
>> Thu Mar 29 18:49:42 EDT 2012 Thread[index-stat-thread,5,main] {istat,trace@154082288} invalidation completed
>> Thu Mar 29 18:49:42 EDT 2012 Thread[index-stat-thread,5,main] {istat} "PKG_9145E_V1"."BC01_CONFIGURATION_SET": wrote stats for index SQL081029110445920 (e9a40921-011d-491f-3d8c-0000376d74d3): rows=44727, card=[44727]
>> Thu Mar 29 18:49:42 EDT 2012 Thread[index-stat-thread,5,main] {istat,trace@154082288} writing new stats (xid=1681541329)
>> Thu Mar 29 18:49:42 EDT 2012 Thread[index-stat-thread,5,main] {istat,trace@154082288} invalidation completed
>> Thu Mar 29 18:49:42 EDT 2012 Thread[index-stat-thread,5,main] {istat} "PKG_9145E_V1"."BC01_CONFIGURATION_SET": wrote stats for index SQL100922214723290 (2c5f8294-012b-3c38-b55c-000043ea6398): rows=44727, card=[44727] Thu Mar 29 18:49:42 EDT 2012 Thread[index-stat-thread,5,main] {istat} "PKG_9145E_V1"."BC01_CONFIGURATION_SET": scan durations (c30785=132ms,c30785=124ms) Thu Mar 29 18:49:42 EDT 2012 Thread[index-stat-thread,5,main] {istat} "PKG_9145E_V1"."BC01_CONFIGURATION_SET": generation complete (273 ms)
>> Thu Mar 29 18:49:42 EDT 2012 Thread[index-stat-thread,5,main] {istat,trace@154082288} queue empty
>> Thu Mar 29 18:49:42 EDT 2012 Thread[index-stat-thread,5,main] {istat,trace@154082288} worker thread exit [q/p/s=0/277/277,err:k/u/c=0/0/0,rej:f/d/o=0/303/0]
>>
>>
>>
>>
>>
>
>
>
>