Return-Path: X-Original-To: apmail-db-derby-dev-archive@www.apache.org Delivered-To: apmail-db-derby-dev-archive@www.apache.org Received: from mail.apache.org (hermes.apache.org [140.211.11.3]) by minotaur.apache.org (Postfix) with SMTP id A8D60965D for ; Sat, 31 Mar 2012 17:31:40 +0000 (UTC) Received: (qmail 72819 invoked by uid 500); 31 Mar 2012 17:31:40 -0000 Delivered-To: apmail-db-derby-dev-archive@db.apache.org Received: (qmail 72792 invoked by uid 500); 31 Mar 2012 17:31:40 -0000 Mailing-List: contact derby-dev-help@db.apache.org; run by ezmlm Precedence: bulk List-Help: List-Unsubscribe: List-Post: List-Id: Reply-To: Delivered-To: mailing list derby-dev@db.apache.org Received: (qmail 72784 invoked by uid 99); 31 Mar 2012 17:31:40 -0000 Received: from athena.apache.org (HELO athena.apache.org) (140.211.11.136) by apache.org (qpsmtpd/0.29) with ESMTP; Sat, 31 Mar 2012 17:31:40 +0000 X-ASF-Spam-Status: No, hits=-0.7 required=5.0 tests=RCVD_IN_DNSWL_LOW,SPF_PASS X-Spam-Check-By: apache.org Received-SPF: pass (athena.apache.org: local policy) Received: from [216.32.181.185] (HELO ch1outboundpool.messaging.microsoft.com) (216.32.181.185) by apache.org (qpsmtpd/0.29) with ESMTP; Sat, 31 Mar 2012 17:31:34 +0000 Received: from mail218-ch1-R.bigfish.com (10.43.68.246) by CH1EHSOBE014.bigfish.com (10.43.70.64) with Microsoft SMTP Server id 14.1.225.23; Sat, 31 Mar 2012 17:31:13 +0000 Received: from mail218-ch1 (localhost [127.0.0.1]) by mail218-ch1-R.bigfish.com (Postfix) with ESMTP id 43CCE2C04DE for ; Sat, 31 Mar 2012 17:31:13 +0000 (UTC) X-SpamScore: -33 X-BigFish: VPS-33(zzbb2dI9371I936eK13dbM11fbM1b0bM542M98dK148cMzz1202hzz8275dhz2dh2a8h668h839h944hd25h) X-Forefront-Antispam-Report: CIP:74.62.37.82;KIP:(null);UIP:(null);IPV:NLI;H:CPHUB1.canoga.com;RD:rrcs-74-62-37-82.west.biz.rr.com;EFVD:NLI Received: from mail218-ch1 (localhost.localdomain [127.0.0.1]) by mail218-ch1 (MessageSwitch) id 1333215070426541_13553; Sat, 31 Mar 2012 17:31:10 +0000 (UTC) Received: from CH1EHSMHS014.bigfish.com (snatpool3.int.messaging.microsoft.com [10.43.68.229]) by mail218-ch1.bigfish.com (Postfix) with ESMTP id 62064C008A for ; Sat, 31 Mar 2012 17:31:10 +0000 (UTC) Received: from CPHUB1.canoga.com (74.62.37.82) by CH1EHSMHS014.bigfish.com (10.43.70.14) with Microsoft SMTP Server (TLS) id 14.1.225.23; Sat, 31 Mar 2012 17:31:09 +0000 Received: from CPHUB2.canoga.com (172.16.1.94) by CPHUB1.canoga.com (172.16.1.93) with Microsoft SMTP Server (TLS) id 8.2.213.0; Sat, 31 Mar 2012 10:32:45 -0700 Received: from vserver1.canoga.com ([169.254.2.24]) by CPHUB2.canoga.com ([172.16.1.94]) with mapi; Sat, 31 Mar 2012 10:32:45 -0700 From: "Bergquist, Brett" To: "derby-dev@db.apache.org" Date: Sat, 31 Mar 2012 10:31:07 -0700 Subject: RE: Question on why indexStat deamon is being triggered Thread-Topic: Question on why indexStat deamon is being triggered Thread-Index: Ac0OtS3UGlLpptuCT+uLSvgiLyCG0wAB4nZKACihweA= Message-ID: <97EB699F861AD841B5908C7CA9C9565602065E174CE7@VSERVER1.canoga.com> References: <97EB699F861AD841B5908C7CA9C9565602065E174BD4@VSERVER1.canoga.com> <4F75A707.5080404@oracle.com> <97EB699F861AD841B5908C7CA9C9565602065E174C03@VSERVER1.canoga.com> <97EB699F861AD841B5908C7CA9C9565602065E174C3B@VSERVER1.canoga.com>,<4F761949.6030009@oracle.com> <97EB699F861AD841B5908C7CA9C95656020656A1096A@VSERVER1.canoga.com> In-Reply-To: <97EB699F861AD841B5908C7CA9C95656020656A1096A@VSERVER1.canoga.com> Accept-Language: en-US Content-Language: en-US X-MS-Has-Attach: X-MS-TNEF-Correlator: acceptlanguage: en-US X-TM-AS-Product-Ver: SMEX-8.0.0.1307-6.500.1024-18808.005 X-TM-AS-Result: No--31.255200-0.000000-31 X-TM-AS-User-Approved-Sender: Yes X-TM-AS-User-Blocked-Sender: No Content-Type: text/plain; charset="us-ascii" Content-Transfer-Encoding: quoted-printable MIME-Version: 1.0 X-OriginatorOrg: canoga.com X-Virus-Checked: Checked by ClamAV on apache.org I hitched up the debugger and caught the indexStat return "49" for the numb= er of rows. I walked the stack back and found this was for conglomeratenam= e =3D "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 =3D t.TABLEID= join sys.SYSSTATISTICS s on s.TABLEID =3D t.TABLEID where c.CONGLOMERATENA= ME =3D 'f3ec4922-011d-491f-3d8c-0000376d74d3' Which is for one of the tables that I am having problems with. This retu= rned: TABLEID CONGLOMERATENUMBER CONGLOMERATENAME ISINDEX ISCONSTRAIN= T CONGLOMERATEID TABLEID TABLENAME TABLETYPE STATID REFERE= NCEID TABLEID CREATIONTIMESTAMP TYPE VALID COLCOUNT S= TATISTICS f3ec4922-011d-491f-3d8c-0000376d74d3 30768 f3ec4922-011d-491f-3d8c-000= 0376d74d3 false false 0e34c923-011d-491f-3d8c-0000376d74d3 f3ec49= 22-011d-491f-3d8c-0000376d74d3 BC01_CONFIGURATION_SET T 645c405f-= 0136-6999-c1b4-000065089f97 2c5f8294-012b-3c38-b55c-000043ea6398 f3ec= 4922-011d-491f-3d8c-0000376d74d3 2012-03-31 12:50:05.348 I true = 1 numunique=3D 20334 numrows=3D 20334 f3ec4922-011d-491f-3d8c-0000376d74d3 30768 f3ec4922-011d-491f-3d8c-000= 0376d74d3 false false 0e34c923-011d-491f-3d8c-0000376d74d3 f3ec49= 22-011d-491f-3d8c-0000376d74d3 BC01_CONFIGURATION_SET T 49fc4ea2-= 0129-489a-0a26-00000732b350 592fcc26-011d-491f-3d8c-0000376d74d3 f3ec= 4922-011d-491f-3d8c-0000376d74d3 2010-06-17 23:16:40.018 I true = 1 numunique=3D 49 numrows=3D 49 f3ec4922-011d-491f-3d8c-0000376d74d3 30768 f3ec4922-011d-491f-3d8c-000= 0376d74d3 false false 0e34c923-011d-491f-3d8c-0000376d74d3 f3ec49= 22-011d-491f-3d8c-0000376d74d3 BC01_CONFIGURATION_SET T 2c44c05e-= 0136-6999-c1b4-000065089f97 e9a40921-011d-491f-3d8c-0000376d74d3 f3ec= 4922-011d-491f-3d8c-0000376d74d3 2012-03-31 12:50:03.427 I true = 1 numunique=3D 20334 numrows=3D 20334 So there seems to be 3 statistics rows for this table. And low and behold= there is the "numrows =3D 49" which I see the indexStat when I turn on tra= cing. 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 vali= d. 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 wi= ll 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 men= tioned happens on a lot of tables. None of these tables are changing howe= ver, 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=3D 38390= numrows=3D 38390 2012-03-30 13:00:26.84 ACCOUNTTABLE_CONFIG_BUNDLE (SQL100922215819290) numunique=3D 38390= numrows=3D 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=3D[t-est= =3D38390, i-est=3D2355 =3D> cmp=3D2.7912562815443245] (queueSize=3D12) Fri = Mar 30 12:47:48 EDT 2012 Thread[index-stat-thread,5,main] {istat} "PKG_9145= E_V1"."ACCOUNTTABLE_CONFIG_BUNDLE": wrote stats for index SQL08102911044381= 0 (fc33890d-011d-491f-3d8c-0000376d74d3): rows=3D38390, card=3D[38390] Fri = Mar 30 12:47:48 EDT 2012 Thread[index-stat-thread,5,main] {istat} "PKG_9145= E_V1"."ACCOUNTTABLE_CONFIG_BUNDLE": wrote stats for index SQL10092221581929= 0 (75608675-012b-3c38-b55c-000043ea6398): rows=3D38390, card=3D[38390] Fri = Mar 30 12:47:48 EDT 2012 Thread[index-stat-thread,5,main] {istat} "PKG_9145= E_V1"."ACCOUNTTABLE_CONFIG_BUNDLE": scan durations (c30625=3D91ms,c30625=3D= 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=3D[t-est= =3D38390, i-est=3D2355 =3D> cmp=3D2.7912562815443245] (queueSize=3D19) Fri = Mar 30 12:48:25 EDT 2012 Thread[index-stat-thread,5,main] {istat} "PKG_9145= E_V1"."ACCOUNTTABLE_CONFIG_BUNDLE": wrote stats for index SQL08102911044381= 0 (fc33890d-011d-491f-3d8c-0000376d74d3): rows=3D38390, card=3D[38390] Fri = Mar 30 12:48:25 EDT 2012 Thread[index-stat-thread,5,main] {istat} "PKG_9145= E_V1"."ACCOUNTTABLE_CONFIG_BUNDLE": wrote stats for index SQL10092221581929= 0 (75608675-012b-3c38-b55c-000043ea6398): rows=3D38390, card=3D[38390] Fri = Mar 30 12:48:25 EDT 2012 Thread[index-stat-thread,5,main] {istat} "PKG_9145= E_V1"."ACCOUNTTABLE_CONFIG_BUNDLE": scan durations (c30625=3D93ms,c30625=3D= 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[DRDAConnThread_50,5,main] {istat} "PKG_= 9145E_V1"."ACCOUNTTABLE_CONFIG_BUNDLE": update scheduled, reason=3D[t-est= =3D38390, i-est=3D2355 =3D> cmp=3D2.7912562815443245] (queueSize=3D18) 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 SQL0810291104= 43810 (fc33890d-011d-491f-3d8c-0000376d74d3): rows=3D38390, card=3D[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 SQL1009222158= 19290 (75608675-012b-3c38-b55c-000043ea6398): rows=3D38390, card=3D[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=3D[t-est= =3D38390, i-est=3D2355 =3D> cmp=3D2.7912562815443245] (queueSize=3D20) Fri = Mar 30 12:49:36 EDT 2012 Thread[index-stat-thread,5,main] {istat} "PKG_9145= E_V1"."ACCOUNTTABLE_CONFIG_BUNDLE": wrote stats for index SQL08102911044381= 0 (fc33890d-011d-491f-3d8c-0000376d74d3): rows=3D38390, card=3D[38390] Fri = Mar 30 12:49:37 EDT 2012 Thread[index-stat-thread,5,main] {istat} "PKG_9145= E_V1"."ACCOUNTTABLE_CONFIG_BUNDLE": wrote stats for index SQL10092221581929= 0 (75608675-012b-3c38-b55c-000043ea6398): rows=3D38390, card=3D[38390] Fri = Mar 30 12:49:37 EDT 2012 Thread[index-stat-thread,5,main] {istat} "PKG_9145= E_V1"."ACCOUNTTABLE_CONFIG_BUNDLE": scan durations (c30625=3D111ms,c30625= =3D108ms) Fri Mar 30 12:49:37 EDT 2012 Thread[index-stat-thread,5,main] {is= tat} "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=3D[t-est= =3D38390, i-est=3D2355 =3D> cmp=3D2.7912562815443245] (queueSize=3D18) 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 creatio= n of the statistics objects, with the goal of finding out where the lower n= umber 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 v= ersion 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 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 i= ndexStats 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 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=3Dtrue derby.storage.indexStats.debug.lndiffThreshold=3D4.0 derby.storage.indexStats.log=3Dtrue derby.storage.indexStats.trace=3Dlog 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 ab= out 300 rows being deleted and 300 new rows being added about every 30 seco= nds. Do you run anything else than insert and delete (with predicate) that modif= ies 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 "COR= E_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=3D[t-est=3D447= 27, i-est=3D49 =3D> cmp=3D6.816512326985881] (queueSize=3D1) abs(log(49) - log(44727)) =3D 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 app= ears 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=3D 44621 numrow= s=3D 44621 2012-03-30 10:17:07.073 BC01_CONFIGURATION_SET (SQL100922214723290) numunique=3D 44621 numrow= s=3D 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=3D[t-est=3D44= 527, i-est=3D49 =3D> cmp=3D6.81203072762349] (queueSize=3D1) Fri Mar 30 10:= 15:32 EDT 2012 Thread[index-stat-thread,5,main] {istat,trace@154082288} wor= ker thread started (xid=3D1705635865) [q/p/s=3D1/1018/1019,err:k/u/c=3D0/0/= 0,rej:f/d/o=3D0/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=3D1705635875) 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 SQL08102911044592= 0 (e9a40921-011d-491f-3d8c-0000376d74d3): rows=3D44527, card=3D[44527] Fri Mar 30 10:15:32 EDT 2012 Thread[index-stat-thread,5,main] {istat,trace@= 154082288} writing new stats (xid=3D1705635891) 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 SQL10092221472329= 0 (2c5f8294-012b-3c38-b55c-000043ea6398): rows=3D44527, card=3D[44527] Fri = Mar 30 10:15:32 EDT 2012 Thread[index-stat-thread,5,main] {istat} "PKG_9145= E_V1"."BC01_CONFIGURATION_SET": scan durations (c30785=3D106ms,c30785=3D100= ms) 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=3D0/1019/1019,err:k/u/c=3D0/0/0,rej:f/= d/o=3D0/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 statist= ics 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 bu= t not too frequently. With the default value, I was seeing about a 20% p= enalty 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 t= oo frequently but I still would like to understand what the trace/log is te= lling me. A lndiffThreshold of 4.0 means the table has to grow (or shrink) by a facto= r 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 distributi= on/cardinality of the values to be similar for a table with 50K rows and 25= 00K 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 n= ot used for 50 weeks of the year. Basically there is one table per week o= f the year that starts as empty, is populated for the week, data stays arou= nd 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 star= t 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=3D0/268/268,err:k/u/c=3D0/0/0,rej:f/d/o=3D0/303/0] q =3D queued p =3D processed s =3D scheduled k =3D known errors (the daemon is prepared for these and can easily recover= ) u =3D unknown errors c =3D consecutive errors (daemon will disable itself= if there are too many consecutive errors) f =3D rejection due to full queu= e d =3D rejection due to duplicate request (already in the queue) o =3D oth= er (currently only tracks scheduling attempts when the daemon has been disa= bled) 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=3D44727, card=3D[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 tabl= e - 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=3D1681453075) 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 SQL08102911044592= 0 (e9a40921-011d-491f-3d8c-0000376d74d3): rows=3D44727, card=3D[44727] Thu Mar 29 18:48:02 EDT 2012 Thread[index-stat-thread,5,main] {istat,trace@= 154082288} writing new stats (xid=3D1681453158) 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 SQL10092221472329= 0 (2c5f8294-012b-3c38-b55c-000043ea6398): rows=3D44727, card=3D[44727] Thu = Mar 29 18:48:02 EDT 2012 Thread[index-stat-thread,5,main] {istat} "PKG_9145= E_V1"."BC01_CONFIGURATION_SET": scan durations (c30785=3D144ms,c30785=3D135= ms) 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=3D0/266/266,err:k/u/c=3D0/0/0,rej:f/d/= o=3D0/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=3D[t-est=3D447= 27, i-est=3D49 =3D> cmp=3D6.816512326985881] (queueSize=3D1) Thu Mar 29 18:= 48:12 EDT 2012 Thread[index-stat-thread,5,main] {istat,trace@154082288} wor= ker thread started (xid=3D1681453158) [q/p/s=3D1/266/267,err:k/u/c=3D0/0/0,= rej:f/d/o=3D0/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=3D1681462384) 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 SQL08102911044592= 0 (e9a40921-011d-491f-3d8c-0000376d74d3): rows=3D44727, card=3D[44727] Thu Mar 29 18:48:12 EDT 2012 Thread[index-stat-thread,5,main] {istat,trace@= 154082288} writing new stats (xid=3D1681462622) 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 SQL10092221472329= 0 (2c5f8294-012b-3c38-b55c-000043ea6398): rows=3D44727, card=3D[44727] Thu = Mar 29 18:48:12 EDT 2012 Thread[index-stat-thread,5,main] {istat} "PKG_9145= E_V1"."BC01_CONFIGURATION_SET": scan durations (c30785=3D152ms,c30785=3D138= ms) 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=3D0/267/267,err:k/u/c=3D0/0/0,rej:f/d/= o=3D0/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=3D[t-est=3D447= 27, i-est=3D49 =3D> cmp=3D6.816512326985881] (queueSize=3D1) Thu Mar 29 18:= 48:33 EDT 2012 Thread[index-stat-thread,5,main] {istat,trace@154082288} wor= ker thread started (xid=3D1681462622) [q/p/s=3D1/267/268,err:k/u/c=3D0/0/0,= rej:f/d/o=3D0/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=3D1681479731) 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 SQL08102911044592= 0 (e9a40921-011d-491f-3d8c-0000376d74d3): rows=3D44727, card=3D[44727] Thu Mar 29 18:48:33 EDT 2012 Thread[index-stat-thread,5,main] {istat,trace@= 154082288} writing new stats (xid=3D1681479756) 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 SQL10092221472329= 0 (2c5f8294-012b-3c38-b55c-000043ea6398): rows=3D44727, card=3D[44727] Thu = Mar 29 18:48:33 EDT 2012 Thread[index-stat-thread,5,main] {istat} "PKG_9145= E_V1"."BC01_CONFIGURATION_SET": scan durations (c30785=3D95ms,c30785=3D103m= s) Thu Mar 29 18:48:33 EDT 2012 Thread[index-stat-thread,5,main] {istat} "P= KG_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=3D0/268/268,err:k/u/c=3D0/0/0,rej:f/d/= o=3D0/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=3D[t-est=3D447= 27, i-est=3D49 =3D> cmp=3D6.816512326985881] (queueSize=3D1) Thu Mar 29 18:= 48:44 EDT 2012 Thread[index-stat-thread,5,main] {istat,trace@154082288} wor= ker thread started (xid=3D1681479756) [q/p/s=3D1/268/269,err:k/u/c=3D0/0/0,= rej:f/d/o=3D0/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=3D1681487715) 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 SQL08102911044592= 0 (e9a40921-011d-491f-3d8c-0000376d74d3): rows=3D44727, card=3D[44727] Thu Mar 29 18:48:45 EDT 2012 Thread[index-stat-thread,5,main] {istat,trace@= 154082288} writing new stats (xid=3D1681487764) 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 SQL10092221472329= 0 (2c5f8294-012b-3c38-b55c-000043ea6398): rows=3D44727, card=3D[44727] Thu = Mar 29 18:48:45 EDT 2012 Thread[index-stat-thread,5,main] {istat} "PKG_9145= E_V1"."BC01_CONFIGURATION_SET": scan durations (c30785=3D101ms,c30785=3D118= ms) 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=3D0/269/269,err:k/u/c=3D0/0/0,rej:f/d/= o=3D0/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=3D[t-est=3D447= 27, i-est=3D49 =3D> cmp=3D6.816512326985881] (queueSize=3D1) Thu Mar 29 18:= 48:46 EDT 2012 Thread[index-stat-thread,5,main] {istat,trace@154082288} wor= ker thread started (xid=3D1681487764) [q/p/s=3D1/269/270,err:k/u/c=3D0/0/0,= rej:f/d/o=3D0/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=3D1681489467) 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 SQL08102911044592= 0 (e9a40921-011d-491f-3d8c-0000376d74d3): rows=3D44727, card=3D[44727] Thu Mar 29 18:48:47 EDT 2012 Thread[index-stat-thread,5,main] {istat,trace@= 154082288} writing new stats (xid=3D1681489541) 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 SQL10092221472329= 0 (2c5f8294-012b-3c38-b55c-000043ea6398): rows=3D44727, card=3D[44727] Thu = Mar 29 18:48:47 EDT 2012 Thread[index-stat-thread,5,main] {istat} "PKG_9145= E_V1"."BC01_CONFIGURATION_SET": scan durations (c30785=3D119ms,c30785=3D130= ms) 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=3D0/270/270,err:k/u/c=3D0/0/0,rej:f/d/= o=3D0/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=3D[t-est=3D447= 27, i-est=3D49 =3D> cmp=3D6.816512326985881] (queueSize=3D1) Thu Mar 29 18:= 48:53 EDT 2012 Thread[index-stat-thread,5,main] {istat,trace@154082288} wor= ker thread started (xid=3D1681489541) [q/p/s=3D1/270/271,err:k/u/c=3D0/0/0,= rej:f/d/o=3D0/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=3D1681495081) 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 SQL08102911044592= 0 (e9a40921-011d-491f-3d8c-0000376d74d3): rows=3D44727, card=3D[44727] Thu Mar 29 18:48:53 EDT 2012 Thread[index-stat-thread,5,main] {istat,trace@= 154082288} writing new stats (xid=3D1681495161) 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 SQL10092221472329= 0 (2c5f8294-012b-3c38-b55c-000043ea6398): rows=3D44727, card=3D[44727] Thu = Mar 29 18:48:53 EDT 2012 Thread[index-stat-thread,5,main] {istat} "PKG_9145= E_V1"."BC01_CONFIGURATION_SET": scan durations (c30785=3D200ms,c30785=3D126= ms) 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=3D0/271/271,err:k/u/c=3D0/0/0,rej:f/d/= o=3D0/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=3D[t-est=3D447= 27, i-est=3D49 =3D> cmp=3D6.816512326985881] (queueSize=3D1) Thu Mar 29 18:= 49:08 EDT 2012 Thread[index-stat-thread,5,main] {istat,trace@154082288} wor= ker thread started (xid=3D1681495161) [q/p/s=3D1/271/272,err:k/u/c=3D0/0/0,= rej:f/d/o=3D0/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=3D1681510950) 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 SQL08102911044592= 0 (e9a40921-011d-491f-3d8c-0000376d74d3): rows=3D44727, card=3D[44727] Thu Mar 29 18:49:09 EDT 2012 Thread[index-stat-thread,5,main] {istat,trace@= 154082288} writing new stats (xid=3D1681511028) 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 SQL10092221472329= 0 (2c5f8294-012b-3c38-b55c-000043ea6398): rows=3D44727, card=3D[44727] Thu = Mar 29 18:49:09 EDT 2012 Thread[index-stat-thread,5,main] {istat} "PKG_9145= E_V1"."BC01_CONFIGURATION_SET": scan durations (c30785=3D228ms,c30785=3D111= ms) 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=3D0/272/272,err:k/u/c=3D0/0/0,rej:f/d/= o=3D0/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=3D[t-est=3D447= 27, i-est=3D49 =3D> cmp=3D6.816512326985881] (queueSize=3D1) Thu Mar 29 18:= 49:11 EDT 2012 Thread[index-stat-thread,5,main] {istat,trace@154082288} wor= ker thread started (xid=3D1681511028) [q/p/s=3D1/272/273,err:k/u/c=3D0/0/0,= rej:f/d/o=3D0/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=3D1681512771) 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 SQL08102911044592= 0 (e9a40921-011d-491f-3d8c-0000376d74d3): rows=3D44727, card=3D[44727] Thu Mar 29 18:49:11 EDT 2012 Thread[index-stat-thread,5,main] {istat,trace@= 154082288} writing new stats (xid=3D1681512851) 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 SQL10092221472329= 0 (2c5f8294-012b-3c38-b55c-000043ea6398): rows=3D44727, card=3D[44727] Thu = Mar 29 18:49:11 EDT 2012 Thread[index-stat-thread,5,main] {istat} "PKG_9145= E_V1"."BC01_CONFIGURATION_SET": scan durations (c30785=3D118ms,c30785=3D118= ms) 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=3D0/273/273,err:k/u/c=3D0/0/0,rej:f/d/= o=3D0/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=3D[t-est=3D447= 27, i-est=3D49 =3D> cmp=3D6.816512326985881] (queueSize=3D1) Thu Mar 29 18:= 49:17 EDT 2012 Thread[index-stat-thread,5,main] {istat,trace@154082288} wor= ker thread started (xid=3D1681512851) [q/p/s=3D1/273/274,err:k/u/c=3D0/0/0,= rej:f/d/o=3D0/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=3D1681518290) 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 SQL08102911044592= 0 (e9a40921-011d-491f-3d8c-0000376d74d3): rows=3D44727, card=3D[44727] Thu Mar 29 18:49:18 EDT 2012 Thread[index-stat-thread,5,main] {istat,trace@= 154082288} writing new stats (xid=3D1681518363) 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 SQL10092221472329= 0 (2c5f8294-012b-3c38-b55c-000043ea6398): rows=3D44727, card=3D[44727] Thu = Mar 29 18:49:18 EDT 2012 Thread[index-stat-thread,5,main] {istat} "PKG_9145= E_V1"."BC01_CONFIGURATION_SET": scan durations (c30785=3D118ms,c30785=3D216= ms) 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=3D0/274/274,err:k/u/c=3D0/0/0,rej:f/d/= o=3D0/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=3D[t-est=3D447= 27, i-est=3D49 =3D> cmp=3D6.816512326985881] (queueSize=3D1) Thu Mar 29 18:= 49:34 EDT 2012 Thread[index-stat-thread,5,main] {istat,trace@154082288} wor= ker thread started (xid=3D1681518363) [q/p/s=3D1/274/275,err:k/u/c=3D0/0/0,= rej:f/d/o=3D0/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=3D1681534090) 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 SQL08102911044592= 0 (e9a40921-011d-491f-3d8c-0000376d74d3): rows=3D44727, card=3D[44727] Thu Mar 29 18:49:34 EDT 2012 Thread[index-stat-thread,5,main] {istat,trace@= 154082288} writing new stats (xid=3D1681534168) 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 SQL10092221472329= 0 (2c5f8294-012b-3c38-b55c-000043ea6398): rows=3D44727, card=3D[44727] Thu = Mar 29 18:49:34 EDT 2012 Thread[index-stat-thread,5,main] {istat} "PKG_9145= E_V1"."BC01_CONFIGURATION_SET": scan durations (c30785=3D112ms,c30785=3D217= ms) 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=3D0/275/275,err:k/u/c=3D0/0/0,rej:f/d/= o=3D0/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=3D[t-est=3D447= 27, i-est=3D49 =3D> cmp=3D6.816512326985881] (queueSize=3D1) Thu Mar 29 18:= 49:36 EDT 2012 Thread[index-stat-thread,5,main] {istat,trace@154082288} wor= ker thread started (xid=3D1681534168) [q/p/s=3D1/275/276,err:k/u/c=3D0/0/0,= rej:f/d/o=3D0/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=3D1681536662) 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 SQL08102911044592= 0 (e9a40921-011d-491f-3d8c-0000376d74d3): rows=3D44727, card=3D[44727] Thu Mar 29 18:49:37 EDT 2012 Thread[index-stat-thread,5,main] {istat,trace@= 154082288} writing new stats (xid=3D1681536775) 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 SQL10092221472329= 0 (2c5f8294-012b-3c38-b55c-000043ea6398): rows=3D44727, card=3D[44727] Thu = Mar 29 18:49:37 EDT 2012 Thread[index-stat-thread,5,main] {istat} "PKG_9145= E_V1"."BC01_CONFIGURATION_SET": scan durations (c30785=3D133ms,c30785=3D127= ms) 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=3D0/276/276,err:k/u/c=3D0/0/0,rej:f/d/= o=3D0/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=3D[t-est=3D447= 27, i-est=3D49 =3D> cmp=3D6.816512326985881] (queueSize=3D1) Thu Mar 29 18:= 49:42 EDT 2012 Thread[index-stat-thread,5,main] {istat,trace@154082288} wor= ker thread started (xid=3D1681536775) [q/p/s=3D1/276/277,err:k/u/c=3D0/0/0,= rej:f/d/o=3D0/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=3D1681541238) 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 SQL08102911044592= 0 (e9a40921-011d-491f-3d8c-0000376d74d3): rows=3D44727, card=3D[44727] Thu Mar 29 18:49:42 EDT 2012 Thread[index-stat-thread,5,main] {istat,trace@= 154082288} writing new stats (xid=3D1681541329) 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 SQL10092221472329= 0 (2c5f8294-012b-3c38-b55c-000043ea6398): rows=3D44727, card=3D[44727] Thu = Mar 29 18:49:42 EDT 2012 Thread[index-stat-thread,5,main] {istat} "PKG_9145= E_V1"."BC01_CONFIGURATION_SET": scan durations (c30785=3D132ms,c30785=3D124= ms) 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=3D0/277/277,err:k/u/c=3D0/0/0,rej:f/d/= o=3D0/303/0]