db-derby-dev mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From "Bergquist, Brett" <BBergqu...@canoga.com>
Subject RE: Question on why indexStat deamon is being triggered
Date Fri, 30 Mar 2012 14:58:20 GMT
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
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]

Mime
View raw message