long running select min(timestamp) query

bobd...@gmail.com

unread,

Jan 28, 2008, 10:40:11 AM1/28/08

to

Hi,

I have a basic event table in my 10g database, primary integer key,
and a nonnull timestamp "eventdate" field. When executing the
following command:

select min(eventdate) from events;

It can occasionally take a VERY long time. There is a standard btree
index on "eventdate", and roughly 20 other columns, a few of which
also have basic btree indexes.

In my current scenario, the table has less than a million records, and
the query seems to be taking upwards of 10 minutes!!! Here's what the
console says the plan is:

Operation Object Object Type Order Rows Size (KB) Cost Time (sec) CPU
Cost I/O Cost
SELECT STATEMENT 3 4
SORT AGGREGATE 2 1 0.011
INDEX FULL SCAN (MIN/MAX) EVENTS_EVENTDATE INDEX 1 736195 7,908.345
4 1 28686 4

I've run the ADDM, it updated the stats, but that doesn't seem to help
(i run it again it has no recommendations). Am i doing something
silly with this table or is there some better way for me to phrase
this query?

Thanks,
Bob

Charles Hooper

unread,

Jan 28, 2008, 11:39:13 AM1/28/08

to

Try a simple test:
First, create a table with a single column and an index on that
column:
CREATE TABLE T1 (EVENTDATE TIMESTAMP NOT NULL);
CREATE INDEX T1_IND1 ON T1(EVENTDATE);

Now, insert 900,000 rows into the table, commit and gather table and
index stats:
INSERT INTO
T1
SELECT
TRUNC(SYSDATE-3000)+ROWNUM/100
FROM
DUAL
CONNECT BY
LEVEL<=900000;

COMMIT;

EXEC
DBMS_STATS.GATHER_TABLE_STATS(OWNNAME=>USER,TABNAME=>'T1',CASCADE=>TRUE)

Finally, run a simple query:
SELECT
MIN(EVENTDATE)
FROM
T1;

From a 10046 trace, only 3 blocks read, all by consistent read:
EXEC #12:c=0,e=352,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,tim=7550820123
FETCH #12:c=0,e=86,p=0,cr=3,cu=0,mis=0,r=1,dep=0,og=1,tim=7550820562

The DBMS XPLAN:
------------------------------------------------------------------------------------------------
| Id | Operation | Name | Starts | E-Rows | A-
Rows | A-Time | Buffers |
------------------------------------------------------------------------------------------------
| 1 | SORT AGGREGATE | | 1 | 1 |
1 |00:00:00.01 | 3 |
| 2 | INDEX FULL SCAN (MIN/MAX)| T1_IND1 | 1 | 904K|
1 |00:00:00.01 | 3 |
------------------------------------------------------------------------------------------------

Does the above experiment execute quickly, and read only 3 blocks on
your system?

Charles Hooper
IT Manager/Oracle DBA
K&M Machine-Fabricating, Inc.

fitzj...@cox.net

unread,

Jan 28, 2008, 12:49:08 PM1/28/08

to

Sorry to say, but '10g' doesn't say much about which release of Oracle
you're using, as that covers releases 10.1.0.2 through 10.2.0.3, and
the optimizer changed between those two base versions.

My suggestion is you configure the PLUSTRACE role, grant it to the
user in question then set autotrace on and run your query. The query
plan itself won't tell you nearly as much as the resulting statistics
reported by autotrace. As an example:

Statistics
----------------------------------------------------------
0 recursive calls
0 db block gets
0 consistent gets
0 physical reads
0 redo size
293 bytes sent via SQL*Net to client
245 bytes received via SQL*Net from client
2 SQL*Net roundtrips to/from client
0 sorts (memory)
0 sorts (disk)
7 rows processed

SQL>

The db block gets, consistent gets and physical reads can reveal much
about what Oracle is doing with your query. Another example shows
this:

Statistics
----------------------------------------------------------
4 recursive calls
0 db block gets
7944 consistent gets
239 physical reads
0 redo size
867354 bytes sent via SQL*Net to client
53760 bytes received via SQL*Net from client
7647 SQL*Net roundtrips to/from client
0 sorts (memory)
0 sorts (disk)
114688 rows processed

SQL>

Such information can be of great help in diagnosing and tuning a
query.

Another excellent resource is 'Cost-Based Oracle Fundamentals', by
Jonathan Lewis ( a semi-regular poster to this newsgroup ). I
strongly suggest you purchase a copy, read it and work through the
examples provided. A wealth of information is packed inside those
pages.

With what you have supplied it's difficult to know where this query is
going awry. Please post the autotrace output for a sluggish run of
this query so we can see what else Oracle may be doing that isn't
apparent from the bare query plan.

David Fitzjarrell

bobd...@gmail.com

unread,

Jan 28, 2008, 6:26:22 PM1/28/08

to

Thank you for your replies, i'll do this one first.

I tried your experiment, and achieved similar responses - i'm a
complete novice and don't know exactly how you got the 10046 trace
output, but i did do the explain stuff:

--------------------------------------------------------------------------------------
| Id | Operation | Name | Rows | Bytes | Cost
(%CPU)| Time |
--------------------------------------------------------------------------------------
| 0 | SELECT STATEMENT | | 1 | 11 | 3
(0)| 00:00:01 |
| 1 | SORT AGGREGATE | | 1 | 11
| | |
| 2 | INDEX FULL SCAN (MIN/MAX)| T1_IND1 | 901K| 9685K| 3
(0)| 00:00:01 |
--------------------------------------------------------------------------------------

I think this is comparable, but please advise if not.

2nd question - my oracle web console tells me i'm running 10.2.0.1.0.
I attempted to enable the plustrace role, and do as suggested, here's
what i got:

SQL> select min(eventdate) from events;

MIN(EVENTDATE)
---------------------------------------------------------------------------
21-JAN-08 04.51.45.525000 PM

Execution Plan
----------------------------------------------------------
Plan hash value: 116994577

--------------------------------------------------------------------------------

-----------------

%CPU)| Time |

--------------------------------------------------------------------------------

-----------------

| 0 | SELECT STATEMENT | | 1 |
11 | 4
(0)| 00:00:01 |

| 1 | SORT AGGREGATE | | 1 |
11 |
| |

| 2 | INDEX FULL SCAN (MIN/MAX)| EVENTS_EVENTDATE | 736K|
7908K| 4
(0)| 00:00:01 |

--------------------------------------------------------------------------------

-----------------

Statistics
----------------------------------------------------------
901 recursive calls
0 db block gets
118525 consistent gets
118248 physical reads
0 redo size
424 bytes sent via SQL*Net to client
381 bytes received via SQL*Net from client

2 SQL*Net roundtrips to/from client

18 sorts (memory)
0 sorts (disk)
1 rows processed

Does this explain anything? Here's the same output using the "new"
table, which for whatever reason is much better:
SQL> select min(eventdate) from t1;

MIN(EVENTDATE)
---------------------------------------------------------------------------
11-NOV-99 12.14.24.000000 AM

Execution Plan
----------------------------------------------------------
Plan hash value: 3630964933

--------------------------------------------------------------------------------

------

|

--------------------------------------------------------------------------------

------

| 0 | SELECT STATEMENT | | 1 | 11 | 3
(0)| 00:0

0:01 |

| 1 | SORT AGGREGATE | | 1 | 11
| |
|

| 2 | INDEX FULL SCAN (MIN/MAX)| T1_IND1 | 901K| 9685K| 3
(0)| 00:0

0:01 |

--------------------------------------------------------------------------------

------

Statistics
----------------------------------------------------------
676 recursive calls
0 db block gets
132 consistent gets
6 physical reads
0 redo size
422 bytes sent via SQL*Net to client
381 bytes received via SQL*Net from client

2 SQL*Net roundtrips to/from client

22 sorts (memory)
0 sorts (disk)
1 rows processed

The data in my table is likely mucked up in some capacity, i just
don't know what to do to fix it.

I will definitely get that book. I'm new to all this, so any
obligatory text's you can recommend i'll be all over.

Thanks!

joel garry

unread,

Jan 28, 2008, 7:17:52 PM1/28/08

to

On Jan 28, 7:40 am, "bobdu...@gmail.com" <bobdu...@gmail.com> wrote:
> Hi,
>
> I have a basic event table in my 10g database, primary integer key,
> and a nonnull timestamp "eventdate" field. When executing the
> following command:
>
> select min(eventdate) from events;
>
> It can occasionally take a VERY long time. There is a standard btree
> index on "eventdate", and roughly 20 other columns, a few of which
> also have basic btree indexes.

Well, I'm guessing that your 20 column index is just not the best one
for your min. What happens if you make a btree index on just that
eventdate column? It's been my experience that any table with more
than a few columns in an index isn't properly normalized.

There might be bug/patch issues, too. timestamp is relatively new,
and you are using an unpatched base release.

How are you loading this table? What is the exact definition of the
index?

jg
--
@home.com is bogus.
http://www.spacefem.com/hydrox/

Charles Hooper

unread,

Jan 28, 2008, 9:37:37 PM1/28/08

to

Responses inline:

> > ------------------------------------------------------------------------------------------------

> > ------------------------------------------------------------------------------------------------

> > | 1 | SORT AGGREGATE | | 1 | 1 |
> > 1 |00:00:00.01 | 3 |
> > | 2 | INDEX FULL SCAN (MIN/MAX)| T1_IND1 | 1 | 904K|
> > 1 |00:00:00.01 | 3 |

> > ------------------------------------------------------------------------------------------------

>
> > Does the above experiment execute quickly, and read only 3 blocks on
> > your system?
>

> I tried your experiment, and achieved similar responses - i'm a
> complete novice and don't know exactly how you got the 10046 trace
> output, but i did do the explain stuff:
>

> --------------------------------------------------------------------------------------

> --------------------------------------------------------------------------------------

> | 0 | SELECT STATEMENT | | 1 | 11 | 3
> (0)| 00:00:01 |
> | 1 | SORT AGGREGATE | | 1 | 11
> | | |
> | 2 | INDEX FULL SCAN (MIN/MAX)| T1_IND1 | 901K| 9685K| 3
> (0)| 00:00:01 |

> --------------------------------------------------------------------------------------

>
> I think this is comparable, but please advise if not.

What you posted above are the estimates, and do not include the actual
execution statistics. But for this comparison, that will work just as
well. See the following for an example of how to use DBMS_XPLAN to
retrieve the actual execution statistics:
http://jonathanlewis.wordpress.com/2006/11/09/dbms_xplan-in-10g/

Your explain plan (of my query example) above shows a prediction of
901K rows, while on my system Oracle was predicting 904K rows. My
explain plan shows that the actual number of rows were 1, and that 3
buffers were used (the 10046 plan showed that these were consistent
reads - logical in-memory reads). Your explain plan shows a cost of
3, implying that 3 blocks will be read.

Now, let's look at the explain plan that you posted for your original
query and compare it to the explain plan that you posted of my query
example:
736K rows predicted, with a cost of 4 - your query is expected to
perform one more logical or physical read than my query example. This
implies that your query should execute roughly as fast as my query
example (in roughly 0.01 seconds or less).

To enable a 10046 trace for your session with wait events:
ALTER SESSION SET EVENTS '10046 TRACE NAME CONTEXT FOREVER, LEVEL 8';

To disable the trace for your session:
ALTER SESSION SET EVENTS '10046 TRACE NAME CONTEXT OFF';

You can find the trace file that is generated in the udump directory
on the server. As you take a look at the 10046 trace files, you will
see lines containing a series of values, such as:
c=0,e=352,p=0,cr=0,cu=0

The above reads as: 0 CPU seconds, 352/1000000 second elapsed time, 0
physical reads, 0 consistent reads (logical, in-memory), 0 current
mode reads (similar to consistent reads, but typically more
efficient).

You will likely also find various wait events which may help identify
the source of any delays.

Please post a DBMS_XPLAN for your query using the technique described
on the above link.

bobd...@gmail.com

unread,

Jan 29, 2008, 9:39:16 AM1/29/08

to

All the indexes on the table only span ONE column, not all! Here's
the ddl (i've modified some names, none of the content has been
changed):

CREATE TABLE "MYSCHEMA"."EVENTS"
( "EVENTID" NUMBER,
"EVENTDATE" TIMESTAMP(6) NOT NULL ,
"HOSTID" NUMBER NOT NULL ,
"DIRECTION" NUMBER NOT NULL ,
"INTERFACE" NVARCHAR2(17),
"FRAME" NUMBER NOT NULL ,
"SOURCEMAC" NVARCHAR2(17),
"DESTINATIONMAC" NVARCHAR2(17),
"PROTOCOL" NUMBER NOT NULL ,
"FLAGS" NVARCHAR2(64),
"SOURCEIP" NVARCHAR2(15),
"SOURCEPORT" NUMBER NOT NULL ,
"DESTINATIONIP" NVARCHAR2(15),
"DESTINATIONPORT" NUMBER NOT NULL ,
"PACKETSIZE" NUMBER NOT NULL ,
"TYPE" NUMBER NOT NULL ,
"ACTION" NUMBER NOT NULL ,
"ITEMID" NUMBER,
"REPEATCOUNT" NUMBER NOT NULL ,
"ENDEVENTDATE" TIMESTAMP(6),
"RANK" NUMBER,
"HOSTASSETVALUE" NUMBER(5),
"FILTERSEVERITYVALUE" NUMBER(5),
PRIMARY KEY ("EVENTID") VALIDATE )
TABLESPACE "USERS" PCTFREE 10 INITRANS 1 MAXTRANS 255 STORAGE
( INITIAL 64K BUFFER_POOL DEFAULT) LOGGING

CREATE INDEX "MYSCHEMA"."EVENTS_EVENTDATE" ON
"MYSCHEMA"."EVENTS" ("EVENTDATE") TABLESPACE "USERS" PCTFREE 10
INITRANS 2 MAXTRANS 255 STORAGE ( INITIAL 64K BUFFER_POOL DEFAULT)
LOGGING LOCAL

Then there's a bunch of other indexes, 8 total, with the one above and
the one PK, 6 more look similar to the one below:

CREATE INDEX "MYSCHEMA"."EVENTS_ACTION" ON
"MYSCHEMA"."EVENTS" ("ACTION") TABLESPACE "USERS" PCTFREE 10 INITRANS
2 MAXTRANS 255 STORAGE ( INITIAL 64K BUFFER_POOL DEFAULT) LOGGING
LOCAL

bobd...@gmail.com

unread,

Jan 29, 2008, 9:55:33 AM1/29/08

to

Thanks again for all your help!

I enabled the trace as described, but think perhaps i had it enabled
globally already :) Anyways, i found the statement in the 12mb trace
file, it starts out like this:

=====================
PARSING IN CURSOR #14 len=45 dep=0 uid=5 oct=3 lid=5 tim=3655566168
hv=2521884448 ad='1cdca248'
select min(eventdate) from myschema.events
END OF STMT
PARSE
#14:c=31250,e=68246,p=2,cr=199,cu=0,mis=1,r=0,dep=0,og=1,tim=3655566161
EXEC #14:c=0,e=50,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,tim=3655566330
WAIT #14: nam='SQL*Net message to client' ela= 4 driver id=1111838976
#bytes=1 p3=0 obj#=355 tim=3655566374
WAIT #14: nam='db file sequential read' ela= 12382 file#=4
block#=1918069 blocks=1 obj#=92627 tim=3655578822
WAIT #14: nam='db file sequential read' ela= 11811 file#=4
block#=1596398 blocks=1 obj#=92627 tim=3655590677
WAIT #14: nam='db file sequential read' ela= 2206 file#=4
block#=1596792 blocks=1 obj#=92627 tim=3655592922
WAIT #14: nam='db file sequential read' ela= 6319 file#=4
block#=1596715 blocks=1 obj#=92627 tim=3655599285
WAIT #14: nam='db file sequential read' ela= 9718 file#=4
block#=1596788 blocks=1 obj#=92627 tim=3655609061
....
.... (snipsnip - vast majority of file looks like this, roughly 10mb
worth)
....
WAIT #14: nam='db file sequential read' ela= 9378 file#=4 block#=31781
blocks=1 obj#=92627 tim=4600466358
WAIT #14: nam='db file sequential read' ela= 149 file#=4 block#=20220
blocks=1 obj#=92627 tim=4600466544
WAIT #14: nam='db file sequential read' ela= 9970 file#=4 block#=31820
blocks=1 obj#=92627 tim=4600476550
FETCH
#14:c=7906250,e=944910345,p=118910,cr=118953,cu=0,mis=0,r=1,dep=0,og=1,tim=4600476756
WAIT #14: nam='SQL*Net message from client' ela= 191 driver
id=1111838976 #bytes=1 p3=0 obj#=92627 tim=4600477050
FETCH #14:c=0,e=1,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=0,tim=4600477098
WAIT #14: nam='SQL*Net message to client' ela= 1 driver id=1111838976
#bytes=1 p3=0 obj#=92627 tim=4600477129
WAIT #14: nam='SQL*Net message from client' ela= 625 driver
id=1111838976 #bytes=1 p3=0 obj#=92627 tim=4600477781
*** SESSION ID:(106.29859) 2008-01-29 09:32:42.976
STAT #14 id=1 cnt=1 pid=0 pos=1 obj=0 op='SORT AGGREGATE (cr=118953
pr=118910 pw=0 time=305509471 us)'
STAT #14 id=2 cnt=1 pid=1 pos=1 obj=92627 op='INDEX FULL SCAN (MIN/
MAX) EVENTS_EVENTDATE (cr=118953 pr=118910 pw=0 time=305509450 us)'
WAIT #0: nam='SQL*Net message to client' ela= 2 driver id=1111838976
#bytes=1 p3=0 obj#=92627 tim=4600526669
WAIT #0: nam='SQL*Net message from client' ela= 95 driver
id=1111838976 #bytes=1 p3=0 obj#=92627 tim=4600526796
=====================
PARSING IN CURSOR #7 len=789 dep=1 uid=0 oct=3 lid=0 tim=4600527186
hv=3159716790 ad='20ae3d74'
select
i.obj#,i.ts#,i.file#,i.block#,i.intcols,i.type#,i.flags,i.property,i.pctfree
$,i.initrans,i.maxtrans,i.blevel,i.leafcnt,i.distkey,i.lblkkey,i.dblkkey,i.clufac,i.cols,i.analyzetime,i.samplesize,i.dataobj#,nvl(i.degree,
1),nvl(i.instances,1),i.rowcnt,mod(i.pctthres$,
256),i.indmethod#,i.trunccnt,nvl(c.unicols,0),nvl(c.deferrable#
+c.valid#,
0),nvl(i.spare1,i.intcols),i.spare4,i.spare2,i.spare6,decode(i.pctthres
$,null,null,mod(trunc(i.pctthres$/256),
256)),ist.cachedblk,ist.cachehit,ist.logicalread from ind$ i, ind_stats
$ ist, (select enabled, min(cols) unicols,min(to_number(bitand(defer,
1))) deferrable#,min(to_number(bitand(defer,4))) valid# from cdef$
where obj#=:1 and enabled > 1 group by enabled) c where
i.obj#=c.enabled(+) and i.obj# = ist.obj#(+) and i.bo#=:1 order by
i.obj#
END OF STMT
PARSE #7:c=0,e=23,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,tim=4600527182
EXEC #7:c=0,e=79,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,tim=4600527482
FETCH #7:c=0,e=403,p=0,cr=7,cu=0,mis=0,r=1,dep=1,og=4,tim=4600527920

(snipsnip - a whole bunch more, 1.5mb worth or so, exceeded googles
190000 char limit so i clipped it)

FETCH
#8:c=78125,e=262061,p=38,cr=1566,cu=14,mis=0,r=9,dep=1,og=1,tim=4601143193
FETCH
#7:c=203125,e=487298,p=85,cr=2335,cu=46,mis=0,r=1,dep=0,og=1,tim=4601143310
WAIT #7: nam='SQL*Net message from client' ela= 210 driver
id=1111838976 #bytes=1 p3=0 obj#=355 tim=4601143694
WAIT #7: nam='SQL*Net message to client' ela= 1 driver id=1111838976
#bytes=1 p3=0 obj#=355 tim=4601143770
STAT #14 id=1 cnt=3 pid=0 pos=1 obj=0 op='SORT ORDER BY (cr=6 pr=3
pw=0 time=9196 us)'
STAT #14 id=2 cnt=3 pid=1 pos=1 obj=95137 op='TABLE ACCESS FULL
PLAN_TABLE (cr=6 pr=0 pw=0 time=107 us)'
STAT #14 id=3 cnt=1 pid=2 pos=1 obj=0 op='SORT AGGREGATE (cr=3 pr=0
pw=0 time=42 us)'
STAT #14 id=4 cnt=1 pid=3 pos=1 obj=95137 op='TABLE ACCESS FULL
PLAN_TABLE (cr=3 pr=0 pw=0 time=27 us)'
FETCH #7:c=0,e=283,p=0,cr=0,cu=0,mis=0,r=8,dep=0,og=1,tim=4601144021
WAIT #7: nam='SQL*Net message from client' ela= 2162 driver
id=1111838976 #bytes=1 p3=0 obj#=355 tim=4601146239
STAT #7 id=1 cnt=9 pid=0 pos=1 obj=0 op='COLLECTION ITERATOR PICKLER
FETCH DISPLAY (cr=2335 pr=85 pw=0 time=487284 us)'
WAIT #0: nam='SQL*Net message to client' ela= 2 driver id=1111838976
#bytes=1 p3=0 obj#=355 tim=4601146360
WAIT #0: nam='SQL*Net message from client' ela= 131 driver
id=1111838976 #bytes=1 p3=0 obj#=355 tim=4601146517
=====================
PARSING IN CURSOR #13 len=45 dep=0 uid=5 oct=7 lid=5 tim=4601146608
hv=349105966 ad='1ce642a4'
DELETE FROM PLAN_TABLE WHERE STATEMENT_ID=:1
END OF STMT
PARSE #13:c=0,e=43,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,tim=4601146604
EXEC #13:c=0,e=203,p=0,cr=3,cu=3,mis=0,r=3,dep=0,og=1,tim=4601146912
WAIT #13: nam='SQL*Net message to client' ela= 1 driver id=1111838976
#bytes=1 p3=0 obj#=355 tim=4601146969
WAIT #13: nam='SQL*Net message from client' ela= 65 driver
id=1111838976 #bytes=1 p3=0 obj#=355 tim=4601147066
STAT #13 id=1 cnt=0 pid=0 pos=1 obj=0 op='DELETE PLAN_TABLE (cr=3
pr=0 pw=0 time=167 us)'
STAT #13 id=2 cnt=3 pid=1 pos=1 obj=95137 op='TABLE ACCESS FULL
PLAN_TABLE (cr=3 pr=0 pw=0 time=45 us)'
WAIT #0: nam='SQL*Net message to client' ela= 1 driver id=1111838976
#bytes=1 p3=0 obj#=355 tim=4601147205
*** 2008-01-29 09:39:33.937
WAIT #0: nam='SQL*Net message from client' ela= 410325557 driver
id=1111838976 #bytes=1 p3=0 obj#=355 tim=5011472799
*** SESSION ID:(106.29859) 2008-01-29 09:39:33.953
XCTEND rlbk=0, rd_only=0

Sorry about the clipping - let me know if i can send the 13mb file
directly.

Why is it stuck waiting? Normally there are a bunch of sessions
accessing this table, but to run these tests i shut down the
application and am ONLY touching oracle with sqlplus. What could it
be waiting on? Is it doing maintenance perhaps?

Thanks again for any help you can provide,
Bob

Charles Hooper

unread,

Jan 29, 2008, 10:48:15 AM1/29/08

to

> #14:c=7906250,e=944910345,p=118910,cr=118953,cu=0,mis=0,r=1,dep=0,og=1,tim=4600476756

> WAIT #14: nam='SQL*Net message from client' ela= 191 driver
> id=1111838976 #bytes=1 p3=0 obj#=92627 tim=4600477050
> FETCH #14:c=0,e=1,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=0,tim=4600477098
> WAIT #14: nam='SQL*Net message to client' ela= 1 driver id=1111838976
> #bytes=1 p3=0 obj#=92627 tim=4600477129
> WAIT #14: nam='SQL*Net message from client' ela= 625 driver
> id=1111838976 #bytes=1 p3=0 obj#=92627 tim=4600477781
> *** SESSION ID:(106.29859) 2008-01-29 09:32:42.976
> STAT #14 id=1 cnt=1 pid=0 pos=1 obj=0 op='SORT AGGREGATE (cr=118953
> pr=118910 pw=0 time=305509471 us)'
> STAT #14 id=2 cnt=1 pid=1 pos=1 obj=92627 op='INDEX FULL SCAN (MIN/
> MAX) EVENTS_EVENTDATE (cr=118953 pr=118910 pw=0 time=305509450 us)'
>

> Why is it stuck waiting? Normally there are a bunch of sessions
> accessing this table, but to run these tests i shut down the
> application and am ONLY touching oracle with sqlplus. What could it
> be waiting on? Is it doing maintenance perhaps?
>
> Thanks again for any help you can provide,
> Bob

It is hard to tell from the small snippet that you posted. My guess
is that Oracle is attempting to apply undo to build a consistent image
of the index blocks based on the last commit. It appears that the
server has a slow single block read time, which could mean that you
need to spread out the I/O over a greater number of spindles (but that
might not be the case).
Wait events:
Trace Time Wait Time Wait Event
0.000206 0.000s SQL*Net message to client
0.012654 0.012s db file sequential read
0.024509 0.012s db file sequential read
0.026754 0.002s db file sequential read
0.033117 0.006s db file sequential read
0.042893 0.010s db file sequential read
...
944.90019 0.009s db file sequential read
944.900376 0.000s db file sequential read
944.910382 0.010s db file sequential read

Actual execution plan: 118,953 consistent reads (in memory), 118910
physical reads (from disk):

SORT AGGREGATE (cr=118953 pr=118910 pw=0 time=305509471 us

INDEX FULL SCAN (MIN/ MAX) EVENTS_EVENTDATE (cr=118953 pr=118910
pw=0 time=305509450 us)

Do you have a session that has made a lot of changes to the table, but
not committed?

bobd...@gmail.com

unread,

Jan 29, 2008, 12:25:17 PM1/29/08

to

There is certainly no CURRENT session in the database that has a large
number of uncommitted operations, but it is certainly possible there
was one in the past, and perhaps it never finished properly. A
typical operation on the database involves doing a "DELETE FROM EVENTS
WHERE EVENTDATE < ?" - its possible one of these happenned in the past
and didn't finish properly.

Is there some way i can get evidence of something like this? I'm
searching the sessions as we speak and see none of my application
sessions lingering. When i look at top activity when the query is not
running, it doesn't look like anything else is happenning - how can i
tell if oracle IS busy with a crapped out session, or maintenance (no
other jobs running either).

Thanks AGAIN!!!
Bob

fitzj...@cox.net

unread,

Jan 29, 2008, 12:34:02 PM1/29/08

to

Comments embedded.

> > ------------------------------------------------------------------------------------------------

> > ------------------------------------------------------------------------------------------------

> > | 1 | SORT AGGREGATE | | 1 | 1 |
> > 1 |00:00:00.01 | 3 |
> > | 2 | INDEX FULL SCAN (MIN/MAX)| T1_IND1 | 1 | 904K|
> > 1 |00:00:00.01 | 3 |

> > ------------------------------------------------------------------------------------------------

>
> > Does the above experiment execute quickly, and read only 3 blocks on
> > your system?
>
> > Charles Hooper
> > IT Manager/Oracle DBA
> > K&M Machine-Fabricating, Inc.
>
> Thank you for your replies, i'll do this one first.
>
> I tried your experiment, and achieved similar responses - i'm a
> complete novice and don't know exactly how you got the 10046 trace
> output, but i did do the explain stuff:
>

> --------------------------------------------------------------------------------------

> --------------------------------------------------------------------------------------

> | 0 | SELECT STATEMENT | | 1 | 11 | 3
> (0)| 00:00:01 |
> | 1 | SORT AGGREGATE | | 1 | 11
> | | |
> | 2 | INDEX FULL SCAN (MIN/MAX)| T1_IND1 | 901K| 9685K| 3
> (0)| 00:00:01 |

> --------------------------------------------------------------------------------------

>
> I think this is comparable, but please advise if not.
>
> 2nd question - my oracle web console tells me i'm running 10.2.0.1.0.
> I attempted to enable the plustrace role, and do as suggested, here's
> what i got:
>
> SQL> select min(eventdate) from events;
>
> MIN(EVENTDATE)
> ---------------------------------------------------------------------------
> 21-JAN-08 04.51.45.525000 PM
>
> Execution Plan
> ----------------------------------------------------------
> Plan hash value: 116994577
>

> --------------------------------------------------------------------------------

> --------------------------------------------------------------------------------

>
> -----------------
>
> | 0 | SELECT STATEMENT | | 1 |
> 11 | 4
> (0)| 00:00:01 |
>
> | 1 | SORT AGGREGATE | | 1 |
> 11 |
> | |
>
> | 2 | INDEX FULL SCAN (MIN/MAX)| EVENTS_EVENTDATE | 736K|
> 7908K| 4
> (0)| 00:00:01 |
>

> --------------------------------------------------------------------------------

>
> -----------------
>
> Statistics
> ----------------------------------------------------------
> 901 recursive calls
> 0 db block gets
> 118525 consistent gets
> 118248 physical reads
> 0 redo size
> 424 bytes sent via SQL*Net to client
> 381 bytes received via SQL*Net from client
> 2 SQL*Net roundtrips to/from client
> 18 sorts (memory)
> 0 sorts (disk)
> 1 rows processed
>

118525 consistent gets and 118248 physical reads to return one row
from an index full scan is a bit much, I think, and explains why this
is taking so long to complete. You've hit the buffer cache for 118525
blocks, and you've also loaded the buffer cache with 118248 blocks
from disk; this is a lot of I/O in my opinion. Reducing this is the
goal in my estimation, as it should then speed up the query (wading
through less data gets you through the 'swamp' faster).

You may be experiencing the effects of row migration, where one data
row has two or more 'pointers' because it's been relocated one or
more times due to block space issues.
Creating the CHAINED_ROWS table ($ORACLE_HOME/rdbms/admin/
utlchain.sql) and running

analyze table events list chained rows;

would populate the CHAINED_ROWS table and could provide some
additional information. Querying CHAINED_ROWS:

select owner_name, table_name, count(*)
from chained_rows
group by owner_name, table_name;

You may have nothing returned, or you may have a large number of
chained/migrated rows with which to deal. Looking at your table
definition and presuming an 8k block size I can't expect you'd have
any actual chained rows (rows that, no matter what, will not fit into
a single data block), but I can expect you may have any number of
migrated rows, which can be fixed by increasing the PCTFREE for the
table (currently set at 10). An alter table events move pctfree 25;
could fix the migrated row issue and may improve your query response
time. Notice I said 'may'; nothing, including the advice offered
here, is guaranteed. You can see if the migrated rows are fixed by
truncating the CHAINED_ROWS table and executing the same analyze table
statement as before:

analyze table events list chained rows;

Hopefully if you had any migrated rows before they would now be gone.
Executing your query against the now cleansed' table might show
different statistics through autotrace. And those statistics might be
an improvement over the original run. And again, this is somewhat
guesswork.

> Does this explain anything? Here's the same output using the "new"
> table, which for whatever reason is much better:
> SQL> select min(eventdate) from t1;
>
> MIN(EVENTDATE)
> ---------------------------------------------------------------------------
> 11-NOV-99 12.14.24.000000 AM
>
> Execution Plan
> ----------------------------------------------------------
> Plan hash value: 3630964933
>

> --------------------------------------------------------------------------------

> --------------------------------------------------------------------------------

>
> ------
>
> | 0 | SELECT STATEMENT | | 1 | 11 | 3
> (0)| 00:0
>
> 0:01 |
>
> | 1 | SORT AGGREGATE | | 1 | 11
> | |
> |
>
> | 2 | INDEX FULL SCAN (MIN/MAX)| T1_IND1 | 901K| 9685K| 3
> (0)| 00:0
>
> 0:01 |
>

> --------------------------------------------------------------------------------

>
> ------
>
> Statistics
> ----------------------------------------------------------
> 676 recursive calls
> 0 db block gets
> 132 consistent gets
> 6 physical reads
> 0 redo size
> 422 bytes sent via SQL*Net to client
> 381 bytes received via SQL*Net from client
> 2 SQL*Net roundtrips to/from client
> 22 sorts (memory)
> 0 sorts (disk)
> 1 rows processed

Here you have a completely different story: 132 blocks read from the
buffer cache and 6 reads from disk to help populate the buffer cache.
Of course thisis on your single-column table, but the response should
be similar (depending upon your data) for your events table.
You generate the same type of execution plan (INDEX FULL SCAN) yet
the index for the EVENTS table is undergoing a tremendous amount of I/
O to return your single-row result.

I'll ask if the statistics for the EVENTS table are computed or
estimated? Sometimes estimating statistics can 'overlook' anomolies
in the data distribution (depending upon the percent of the data is
used for the estimate) that computing would reveal. There are many
other areas which could be affecting this query (although you are
ending up with an index full scan as an access path). Not knowing the
data is a hindrance when offering suggestions for improvement.

>
> The data in my table is likely mucked up in some capacity,

And, on the surface of it, I tend to agree.

> i just
> don't know what to do to fix it.
>

You will when/if you find out how it's 'mucked up'. You have some
suggestions here, and others may be in order depending upon the state
of your data.

> I will definitely get that book. I'm new to all this, so any
> obligatory text's you can recommend i'll be all over.
>

> Thanks!- Hide quoted text -
>
> - Show quoted text -

David Fitzjarrell

Charles Hooper

unread,

Jan 29, 2008, 1:33:15 PM1/29/08

to

On Jan 29, 12:25 pm, "bobdu...@gmail.com" <bobdu...@gmail.com> wrote:
> There is certainly no CURRENT session in the database that has a large
> number of uncommitted operations, but it is certainly possible there
> was one in the past, and perhaps it never finished properly. A
> typical operation on the database involves doing a "DELETE FROM EVENTS
> WHERE EVENTDATE < ?" - its possible one of these happenned in the past
> and didn't finish properly.
>
> Is there some way i can get evidence of something like this? I'm
> searching the sessions as we speak and see none of my application
> sessions lingering. When i look at top activity when the query is not
> running, it doesn't look like anything else is happenning - how can i
> tell if oracle IS busy with a crapped out session, or maintenance (no
> other jobs running either).
>
> Thanks AGAIN!!!

Test runs with sample data may be helpful. Back to the original
sample that I posted:

CREATE TABLE T1 (EVENTDATE TIMESTAMP NOT NULL);
CREATE INDEX T1_IND1 ON T1(EVENTDATE);

INSERT INTO

T1
SELECT
TRUNC(SYSDATE-3000)+ROWNUM/100
FROM
DUAL
CONNECT BY
LEVEL<=900000;

COMMIT;

EXEC
DBMS_STATS.GATHER_TABLE_STATS(OWNNAME=>USER,TABNAME=>'T1',CASCADE=>TRUE);

SELECT
MIN(EVENTDATE)
FROM
T1;

The DBMS Xplan
------------------------------------------------------------------------------------------------

------------------------------------------------------------------------------------------------

| 1 | SORT AGGREGATE | | 1 | 1 |
1 |00:00:00.01 | 3 |
| 2 | INDEX FULL SCAN (MIN/MAX)| T1_IND1 | 1 | 904K|
1 |00:00:00.01 | 3 |

------------------------------------------------------------------------------------------------

From the 10046 trace file:
PARSE #1:c=0,e=6954,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=1,tim=5794606730
EXEC #1:c=0,e=107,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,tim=5794608342
WAIT #1: nam='SQL*Net message to client' ela= 7 driver id=1413697536
#bytes=1 p3=0 obj#=-1 tim=5794608829
FETCH #1:c=0,e=91,p=0,cr=3,cu=0,mis=0,r=1,dep=0,og=1,tim=5794609296
WAIT #1: nam='SQL*Net message from client' ela= 10946 driver
id=1413697536 #bytes=1 p3=0 obj#=-1 tim=5794620734
STAT #1 id=1 cnt=1 pid=0 pos=1 obj=0 op='SORT AGGREGATE (cr=3 pr=0
pw=0 time=93 us)'
STAT #1 id=2 cnt=1 pid=1 pos=1 obj=32286 op='INDEX FULL SCAN (MIN/MAX)
T1_IND1 (cr=3 pr=0 pw=0 time=55 us)'

In the above, Oracle used an INDEX FULL SCAN (MIN/MAX) to find the
minimum using an optimization, requiring only 3 consistent reads (cr=3
and Buffers = 3), rather than having to scan all of the blocks in the
index. Oracle required 91/1000000 of a second to fetch the result.

Now, let's see what happens when other sessions are involved. In a
second session:
DELETE FROM
T1
WHERE
EVENTDATE<SYSDATE-1000;

200,053 ROWS DELETED

(no commit performed)

Back to the first session to see how the query is affected:
SELECT
MIN(EVENTDATE)
FROM
T1;

The DBMS Xplan
------------------------------------------------------------------------------------------------

------------------------------------------------------------------------------------------------

| 1 | SORT AGGREGATE | | 1 | 1 |

1 |00:00:00.01 | 6 |

| 2 | INDEX FULL SCAN (MIN/MAX)| T1_IND1 | 1 | 904K|

1 |00:00:00.01 | 6 |
------------------------------------------------------------------------------------------------

From the 10046 trace file:
PARSE #1:c=0,e=140,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,tim=5929305668
EXEC #1:c=0,e=106,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,tim=5929307277
WAIT #1: nam='SQL*Net message to client' ela= 6 driver id=1413697536
#bytes=1 p3=0 obj#=-1 tim=5929307728
FETCH #1:c=0,e=7540,p=0,cr=6,cu=0,mis=0,r=1,dep=0,og=1,tim=5929315743
WAIT #1: nam='SQL*Net message from client' ela= 1728 driver
id=1413697536 #bytes=1 p3=0 obj#=-1 tim=5929318030
STAT #1 id=1 cnt=1 pid=0 pos=1 obj=0 op='SORT AGGREGATE (cr=6 pr=0
pw=0 time=7540 us)'
STAT #1 id=2 cnt=1 pid=1 pos=1 obj=32286 op='INDEX FULL SCAN (MIN/MAX)
T1_IND1 (cr=6 pr=0 pw=0 time=7501 us)'

Note that there are now 6 consistent reads, rather than 3, and that
the elapsed time for the FETCH has increased from 91 to 7540.

In a third session:
DELETE FROM
T1
WHERE
EVENTDATE>SYSDATE+400;

559,947 ROWS DELETED

Back to the first session:
SELECT
MIN(EVENTDATE)
FROM
T1;

------------------------------------------------------------------------------------------------

------------------------------------------------------------------------------------------------

| 1 | SORT AGGREGATE | | 1 | 1 |

1 |00:00:00.01 | 6 |

| 2 | INDEX FULL SCAN (MIN/MAX)| T1_IND1 | 1 | 904K|

1 |00:00:00.01 | 6 |
------------------------------------------------------------------------------------------------

PARSE #3:c=0,e=89,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,tim=6311133836
EXEC #3:c=0,e=167,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,tim=6311135482
WAIT #3: nam='SQL*Net message to client' ela= 6 driver id=1413697536
#bytes=1 p3=0 obj#=-1 tim=6311135920
FETCH #3:c=0,e=565,p=0,cr=6,cu=0,mis=0,r=1,dep=0,og=1,tim=6311136874
WAIT #3: nam='SQL*Net message from client' ela= 1520 driver
id=1413697536 #bytes=1 p3=0 obj#=-1 tim=6311138894
STAT #3 id=1 cnt=1 pid=0 pos=1 obj=0 op='SORT AGGREGATE (cr=6 pr=0
pw=0 time=568 us)'
STAT #3 id=2 cnt=1 pid=1 pos=1 obj=32286 op='INDEX FULL SCAN (MIN/MAX)
T1_IND1 (cr=6 pr=0 pw=0 time=530 us)'

No change, other than the elapsed time decreasing.

In the third session:
ROLLBACK;

INSERT INTO
T1
SELECT
TRUNC(SYSDATE-3001)+ROWNUM/100
FROM
DUAL
CONNECT BY
LEVEL<=2;

INSERT INTO
T1
SELECT
TRUNC(SYSDATE-3030)+ROWNUM/100
FROM
DUAL
CONNECT BY
LEVEL<=3000;

DELETE FROM
T1
WHERE
EVENTDATE>SYSDATE+4000;

Back to the first session:
SELECT
MIN(EVENTDATE)
FROM
T1;

------------------------------------------------------------------------------------------------

------------------------------------------------------------------------------------------------

| 1 | SORT AGGREGATE | | 1 | 1 |

1 |00:00:00.04 | 365 |

| 2 | INDEX FULL SCAN (MIN/MAX)| T1_IND1 | 1 | 904K|

1 |00:00:00.04 | 365 |
------------------------------------------------------------------------------------------------

PARSE #7:c=0,e=54,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,tim=6738688175
EXEC #7:c=0,e=103,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,tim=6738689672
WAIT #7: nam='SQL*Net message to client' ela= 6 driver id=1413697536
#bytes=1 p3=0 obj#=-1 tim=6738690122
FETCH
#7:c=0,e=44496,p=0,cr=365,cu=0,mis=0,r=1,dep=0,og=1,tim=6738734984
WAIT #7: nam='SQL*Net message from client' ela= 1605 driver
id=1413697536 #bytes=1 p3=0 obj#=-1 tim=6738737134
STAT #7 id=1 cnt=1 pid=0 pos=1 obj=0 op='SORT AGGREGATE (cr=365 pr=0
pw=0 time=44494 us)'
STAT #7 id=2 cnt=1 pid=1 pos=1 obj=32286 op='INDEX FULL SCAN (MIN/MAX)
T1_IND1 (cr=365 pr=0 pw=0 time=44453 us)'

Note now that Oracle performed 365 consistent reads, and that the
elapsed time has increased from 565 to 44496. Actual time in the DBMS
Xplan reports an increase from 0.01 seconds to 0.04 seconds.

You might take a look at the output of the following to help determine
if Oracle is having to rollback uncommitted data to provide a
consistent view of the data due to an in-process transaction:
SELECT
*
FROM
V$TRANSACTION;

SELECT
*
FROM
V$LOCK;

joel garry

unread,

Jan 29, 2008, 2:53:57 PM1/29/08

to

Sorry 'bout that!

Charles has bought up a good point about concurrency, and it makes me
wonder if you've done mass deletes on this table. Have you tried
recreating the index? (See Richard Foote's blog about indices, the
general advice is you don't need to rebuild indices, but there are
certain odd situations which you can and should check for if you are
seeing noticeable issues. I'm wondering if you've made a realllllly
sparse index, and why Oracle wouldn't be smart enough to find the min
right away.).

I'm also idly wondering if delayed block cleanout can be involved
(google for details). Postulating a mass delete, followed by a simple
inquiry that has to traverse all the deleted blocks and write them
out. If you are getting consistent results doing Charles' traces, it
wouldn't be this. But I'm focused on the description of "It can
occasionally take a VERY long time" and am wondering what is different
at those occasions. Have you checked wait states at those times?
Maybe there's more than one thing wrong here - for example, slow disks
plus disks overwhelmed with with I/O while archiving logs plus
concurrency issues. Also, I have a vague thought of some process like
MMON going nuts, are you seeing unexplained extremely high processor
usage at times?

jg
--
@home.com is bogus.
"Weather forecasts are horoscopes with numbers."

bobd...@gmail.com

unread,

Jan 29, 2008, 3:47:30 PM1/29/08

to

I've done as you suggested, and the CHAINED_ROWS table is empty - so i
did not attempt to change the PCTFREE parameter.

I haven't configured how statistics are generated, but i believe that
our java application occasionally asks (via oracle's JDBC driver) to
estimate statistics in order to get index information. I can't find
an obvious pointer in the UI that indicates if the statistics it's
presenting are estimated or computed. I will see if i can "compute"
the statistics now and try again.

bobd...@gmail.com

unread,

Jan 29, 2008, 4:36:01 PM1/29/08

to

I definitely have done some large scale deletes. When i say
occasionally, there have been times when the query has been fast, but
it hasn't been fast in a long time... likely since the last large
scale delete operation actually. The CPU never spikes on the oracle
box, its definitely always blocking on IO. Mind you, the disk is
slow, but since it is occasionally speedy, i can't blame it all on
disk (can i?).

I just tried to get more stats via the following call, and then
checked again for chained rows (not sure if it would've affected, but
tried anyways):

SQL> exec
DBMS_STATS.GATHER_TABLE_STATS(OWNNAME=>USER,TABNAME=>'EVENTS,CASCADE=>TRUE);

PL/SQL procedure successfully completed.

SQL> analyze table events list chained rows;

Table analyzed.

SQL> select owner_name, table_name, count(*)
2 from chained_rows
3 group by owner_name, table_name;

no rows selected

joel garry

unread,

Jan 29, 2008, 5:54:29 PM1/29/08

to

Sure, when all else fails blame the hardware! :-) (There are people
who don't tune and just throw hardware at it - I've done that myself,
it can work - but it is generally stupid without figuring out what is
really going on). I have seen failing hardware be slow and sometimes
fast.

I think we've ruled out the delayed block cleanout issue if it hasn't
been fast in a long time, that would be an occasional thing, anything
that touches all blocks, like getting stats without sampling, would
clean it out. And we've ruled out chaining.

So: http://richardfoote.wordpress.com/2007/12/11/index-internals-rebuilding-the-truth/

Also, please post your top waits, and continue on the path Charles has
started, it may very well also lead to the solution(s). I/O binding
can be caused by many things, from actually needing lots of data to
tuning to bad code. It's most often bad code. Mass deletes can be
done many ways, some of which may be considered bad at times. Search
http://asktom.oracle.com for mass delete. Sometimes a better way is
to create a new table with what you want to keep, then rename.

>
> I just tried to get more stats via the following call, and then
> checked again for chained rows (not sure if it would've affected, but
> tried anyways):
>
> SQL> exec
> DBMS_STATS.GATHER_TABLE_STATS(OWNNAME=>USER,TABNAME=>'EVENTS,CASCADE=>TRUE);
>
> PL/SQL procedure successfully completed.
>
> SQL> analyze table events list chained rows;
>
> Table analyzed.
>
> SQL> select owner_name, table_name, count(*)
> 2 from chained_rows
> 3 group by owner_name, table_name;
>
> no rows selected

jg
--
@home.com is bogus.
http://www.signonsandiego.com/uniontrib/20080129/news_1b29lazar.html

Charles Hooper

unread,

Jan 29, 2008, 6:17:10 PM1/29/08

to

> So: http://richardfoote.wordpress.com/2007/12/11/index-internals-rebuildi...

>
> Also, please post your top waits, and continue on the path Charles has
> started, it may very well also lead to the solution(s). I/O binding
> can be caused by many things, from actually needing lots of data to
> tuning to bad code. It's most often bad code. Mass deletes can be

> done many ways, some of which may be considered bad at times. Searchhttp://asktom.oracle.comfor mass delete. Sometimes a better way is

> to create a new table with what you want to keep, then rename.
>
> > I just tried to get more stats via the following call, and then
> > checked again for chained rows (not sure if it would've affected, but
> > tried anyways):
>
> > SQL> exec
> > DBMS_STATS.GATHER_TABLE_STATS(OWNNAME=>USER,TABNAME=>'EVENTS,CASCADE=>TRUE);
>
> > PL/SQL procedure successfully completed.
>
> > SQL> analyze table events list chained rows;
>
> > Table analyzed.
>
> > SQL> select owner_name, table_name, count(*)
> > 2 from chained_rows
> > 3 group by owner_name, table_name;
>
> > no rows selected
>
> jg
> --

> @home.com is bogus.http://www.signonsandiego.com/uniontrib/20080129/news_1b29lazar.html- Hide quoted text -

In addition to looking at the wait events, you may also want to
further investigate session level statistics to see if undo blocks are
being applied to produce a consistent view of the data. For example,
before running your query, execute the following to obtain a beginning
snapshot of the statistics:
SELECT
SN.NAME,
MS.VALUE
FROM
V$STATNAME SN,
V$MYSTAT MS
WHERE
SN.NAME IN (
'consistent changes',
'data blocks consistent reads - undo records applied',
'consistent gets',
'cleanouts and rollbacks - consistent read gets')
AND SN.STATISTIC#=MS.STATISTIC#;

Then, execute your query:
select min(eventdate) from events;

Then execute the statistics query again:
SELECT
SN.NAME,
MS.VALUE
FROM
V$STATNAME SN,
V$MYSTAT MS
WHERE
SN.NAME IN (
'consistent changes',
'data blocks consistent reads - undo records applied',
'consistent gets',
'cleanouts and rollbacks - consistent read gets')
AND SN.STATISTIC#=MS.STATISTIC#;

Finally, manually subtract the beginning values from the ending
values.

For example:
NAME VALUE
--------------------------------------------------- ----------
consistent gets 409934
consistent changes 1520
data blocks consistent reads - undo records applied 1468
cleanouts and rollbacks - consistent read gets 1

---

NAME VALUE
-------------------------------------------------- ----------
consistent gets 409940
consistent changes 1522
data blocks consistent reads - undo records applied 1470
cleanouts and rollbacks - consistent read gets 2

The 10046 trace for the query that I executed showed 8 consistent
reads.

CONSISTENT GETS: Requests for a Block Consistent Read - Statistic
counts the number of logical reads in consistent mode.

CONSISTENT CHANGES: Undo Records Applied to Provide Consistent Read -
Statistic indicates the number of times a database block has rollback
entries applied to perform a consistent read of the block. Work
loads that produce a great deal of consistent changes can consume a
great deal of resources. The value of this statistic should be small
in relation to the 'consistent gets' statistic.

DATA BLOCKS CONSISTENT READS - UNDO RECORDS APPLIED: Undo Applied to
Block for a Consistent Read - Number of undo records applied to data
blocks that have been rolled back for consistent read purposes.

CLEANOUTS AND ROLLBACKS - CONSISTENT READ GETS: Undo/Block Cleanout
Required for Cons. Read - Number of consistent gets that require both
block rollbacks and block cleanouts.

Robert Klemme

unread,

Jan 30, 2008, 5:02:11 AM1/30/08

to

On Jan 29, 10:36 pm, "bobdu...@gmail.com" <bobdu...@gmail.com> wrote:
> I definitely have done some large scale deletes. When i say
> occasionally, there have been times when the query has been fast, but
> it hasn't been fast in a long time... likely since the last large
> scale delete operation actually.

I doubt it makes a difference for the min/max types of queries but do
you update statistics on a regular basis, or at least after such mass
deletes? There *may* be an impact if concurrently running queries are
less efficient because of stale statistics and your IO becomes slower
just because of increased concurrent IO load.

> I just tried to get more stats via the following call, and then
> checked again for chained rows (not sure if it would've affected, but
> tried anyways):
>
> SQL> exec
> DBMS_STATS.GATHER_TABLE_STATS(OWNNAME=>USER,TABNAME=>'EVENTS,CASCADE=>TRUE);

Maybe you can even update the whole schema's statistics if you haven't
done in a time or on a regular basis.

Do you have system statistics set?

Kind regards

bobd...@gmail.com

unread,

Jan 30, 2008, 12:12:58 PM1/30/08

to

I'm afraid i don't know how to calculate what the top waits are - i've
seen references to it, but nothing conclusive. That udump file i had
contains MANY waits, is there a tool that will go through it and
summarize?

I think i finally figured out how to get the xplan, although i'm not
sure what it tells me:
SQL> select
2 /*+
3 gather_plan_statistics
4 ordered use_nl(events) index(events)
5 */
6 min(eventdate)
7 from
8 events
9 ;

MIN(eventdate)
---------------------------------------------------------------------------
22-JAN-08 08.44.55.912000 AM

SQL> select * from table(dbms_xplan.display_cursor(null,null,'ALLSTATS
LAST'));

PLAN_TABLE_OUTPUT
--------------------------------------------------------------------------------
SQL_ID 797v1v1tbvp6s, child number 0
-------------------------------------
select /*+ gather_plan_statistics ordered use_nl(events) inde
x(events) */

min(eventdate) from events

Plan hash value: 116994577

--------------------------------------------------------------------------------------------------------------------

PLAN_TABLE_OUTPUT

--------------------------------------------------------------------------------
| Id | Operation | Name | Starts | E-

Rows | A-Rows | A-Time | Buffers | Reads |
--------------------------------------------------------------------------------------------------------------------
| 1 | SORT AGGREGATE | | 1 |
1 | 1 |00:14:53.92 | 118K| 118K|
| 2 | INDEX FULL SCAN (MIN/MAX)| EVENTS_EVENTDATE | 1 |
516K|

PLAN_TABLE_OUTPUT
--------------------------------------------------------------------------------
1 |00:14:53.92 | 118K| 118K|

--------------------------------------------------------------------------------------------------------------------

14 rows selected.

This indicates that there are tons of estimated rows - i'm not sure
what else this really tells me... i'm still digging on the other
responses, thanks for all your prolonged support!

bobd...@gmail.com

unread,

Jan 30, 2008, 12:24:16 PM1/30/08

to

I performed this test, heres what i got:

BEFORE:
NAME
VALUE
----------------------------------------------------------------
----------
consistent gets
1656576
consistent
changes 49

data blocks consistent reads - undo records

applied 43

cleanouts and rollbacks - consistent read

gets 0

AFTER:
NAME
VALUE
----------------------------------------------------------------
----------
consistent gets
1775792
consistent
changes 49

data blocks consistent reads - undo records

applied 43

cleanouts and rollbacks - consistent read

gets 0

DIFF:
NAME
VALUE
----------------------------------------------------------------
----------
consistent gets
119216
consistent
changes 0

data blocks consistent reads - undo records

applied 0

cleanouts and rollbacks - consistent read

gets 0

Looks like a lot of consistent gets...

bobd...@gmail.com

unread,

Jan 30, 2008, 12:26:48 PM1/30/08

to

On Jan 30, 5:02 am, Robert Klemme <shortcut...@googlemail.com> wrote:
> On Jan 29, 10:36 pm, "bobdu...@gmail.com" <bobdu...@gmail.com> wrote:
>
> > I definitely have done some large scale deletes. When i say
> > occasionally, there have been times when the query has been fast, but
> > it hasn't been fast in a long time... likely since the last large
> > scale delete operation actually.
>
> I doubt it makes a difference for the min/max types of queries but do
> you update statistics on a regular basis, or at least after such mass
> deletes? There *may* be an impact if concurrently running queries are
> less efficient because of stale statistics and your IO becomes slower
> just because of increased concurrent IO load.

I don't do anything regularily, which is bad yes, but ianaodba, so i
don't even know what to do, i try to let this intelligent system
handle itself :) In any event, i have updated the statistics via the
command described in an earlier post, there are still no active
clients to the db, and the query is still uberslow.

>
> > I just tried to get more stats via the following call, and then
> > checked again for chained rows (not sure if it would've affected, but
> > tried anyways):
>
> > SQL> exec
> > DBMS_STATS.GATHER_TABLE_STATS(OWNNAME=>USER,TABNAME=>'EVENTS,CASCADE=>TRUE);
>
> Maybe you can even update the whole schema's statistics if you haven't
> done in a time or on a regular basis.
>
> Do you have system statistics set?
>
> Kind regards

Not a bad idea - perhaps i'll get the whole schema statistics now and
see what happens. How do i know if i have system statistics set?

Thanks again!

Charles Hooper

unread,

Jan 30, 2008, 1:16:13 PM1/30/08

to

A lot of consistent gets, and likely also a lot of physical reads, and
0 undo blocks. That certainly is not what I expected. The wait
events that you posted looked similar to the following:

WAIT #14: nam='db file sequential read' ela= 12382 file#=4
block#=1918069 blocks=1 obj#=92627 tim=3655578822

The above indicates that Oracle is performing a single block read in
file number 4 starting at block 1918069. What object is at that
location?
SELECT
DE.OWNER,
DE.SEGMENT_NAME,
DE.SEGMENT_TYPE,
DE.TABLESPACE_NAME,
DE.BLOCK_ID,
DE.BLOCKSFROM
DBA_EXTENTS DE
WHERE
DE.FILE_ID= 4
AND 1918069 BETWEEN BLOCK_ID AND BLOCK_ID+BLOCKS-1;

The DBMS Xplan is showing that Oracle is performing roughly 118,000
reads, while the plan that you originally posted indicated that Oracle
predicted that it would perform roughly 4 reads. The DBMS XPlan is
also indicating that the query required nearly 15 minutes to execute,
rather than 0.01 seconds. I wonder if the extra hints that you are
providing:
ordered use_nl(events) index(events)
Are affecting whether or not Oracle is able to use the MIN/MAX
optimization, so instead of Oracle visiting 3 or 4 blocks, it is
actually scanning 118,000 blocks in the index? Maybe you can try
flushing the shared pool and re-executing the query without the extra
hints.

To determine if system statistics have been gathered:
SELECT
*
FROM
SYS.AUX_STATS$;

If system statistics have not been gathered, there might be entries in
a couple of the statistics. If system statistics have been gathered,
you will see entries for SREADTIM (single block read time) and
MREADTIM (multi-block read time). Collect statistics when the system
is relatively busy.

bobd...@gmail.com

unread,

Jan 30, 2008, 1:41:10 PM1/30/08

to

OK!!! Note - i've given up on masking the table/index/schema name,
table events=packetlogs, column logdate=eventdate - i was trying to
solve the problem generally, but now am getting lazy:

SQL> SELECT
2 DE.OWNER,
3 DE.SEGMENT_NAME,
4 DE.SEGMENT_TYPE,
5 DE.TABLESPACE_NAME,
6 DE.BLOCK_ID,
7 DE.BLOCKS
8 FROM
9 DBA_EXTENTS DE
10 WHERE
11 DE.FILE_ID= 4
12 AND 1918069 BETWEEN BLOCK_ID AND BLOCK_ID+BLOCKS-1;

OWNER
------------------------------
SEGMENT_NAME
--------------------------------------------------------------------------------
SEGMENT_TYPE TABLESPACE_NAME BLOCK_ID
BLOCKS
------------------ ------------------------------ ----------
----------
DSM_JAN08
PACKETLOGS_LOGDATE
INDEX USERS 1917321
1024

So that is the spot in the index in question, as expected i guess.

I did as you said, ran:
ALTER SYSTEM FLUSH SHARED_POOL;

Reran with only the gather statistics hint, and same result - its
taking a darn long time.

I selected system stats, its pretty sparse, those SREADTIM and
MREADTIM are blank, and the one date is from 2005 (before this
instance of oracle was installed!). So i think my next step will be
to gather system statistics, but i'm not clear on how that will help
this one lowly query. What hint can i give to tell it to NOT use the
index?

Looking in the console, this is what it says about the index:

Last Analyzed 2008-01-30 10:02:07
Blevel 3
Distinct Keys 870
Clustering Factor 455854
Leaf Blocks 2947
Average Leaf Blocks Per Key 3
Average Data Blocks Per Key 523
Number of Rows 523030
Sample Size 523030

Charles Hooper

unread,

Jan 30, 2008, 2:01:12 PM1/30/08

to

> --------------------------------------------------------------------------------

No problem with masking the table and index names if needed.

A minor correction to a previous statement to avoid confusion with
table or index statistics:
Collect <system> statistics when the system is relatively busy.

System statistics will help Oracle determine the correct (optimal)
execution plan based on the actual performance characteristics of the
server. As best I can tell, Oracle is coming up with the best plan,
but is apparently not using the MIN/MAX optimization.

To prevent the use of the one index currently being used:
/*+ NO_INDEX(packetlogs PACKETLOGS_LOGDATE) */

Do not use any index:
/*+ FULL(packetlogs) */

You can forward the 12MB trace file to my Yahoo email address, and I
will try to pass it through a program I wrote for analysis.

Robert Klemme

unread,

Jan 31, 2008, 3:09:56 AM1/31/08

to

On Jan 30, 6:26 pm, "bobdu...@gmail.com" <bobdu...@gmail.com> wrote:
> On Jan 30, 5:02 am, Robert Klemme <shortcut...@googlemail.com> wrote:
> > I doubt it makes a difference for the min/max types of queries but do
> > you update statistics on a regular basis, or at least after such mass
> > deletes? There *may* be an impact if concurrently running queries are
> > less efficient because of stale statistics and your IO becomes slower
> > just because of increased concurrent IO load.
>
> I don't do anything regularily, which is bad yes, but ianaodba,

Then please do yourself a favor ask whoever is responsible for the
database to set up statistics gathering.

> so i
> don't even know what to do, i try to let this intelligent system
> handle itself :)

Oracle is getting better with manageability IMHO but you cannot let a
DB left unattended.

> How do i know if i have system statistics set?

From an earlier posting in this group:

select pname, pval1, sname
from sys.aux_stats$
where sname = 'SYSSTATS_MAIN'

Btw, http://tahiti.oracle.com is your friend. It's even searchable.

Kind regards

robert

bobd...@gmail.com

unread,

Jan 31, 2008, 8:49:43 AM1/31/08

to

> Btw,http://tahiti.oracle.comis your friend. It's even searchable.
>
> Kind regards
>
> robert

I probably should've prefaced this entire thread with - I'm an
applications developer, not a dba :) I know this is a lame excuse,
but i simply don't have the time nor mandate to become an oracle guru,
i'm simply tasked with getting an application to work with oracle (and
a variety of other db's). Every once in a while i get cycles to deal
with issues like this, but i certainly don't spend enough time doing
it.

Anyways, Charles has helped me out bigtime by pointing me in the right
direction:
>> http://richardfoote.files.wordpress.com/2007/12/index-internals-rebuilding-the-truth.pdf
>> Pages 133-135 show what is happening in your situation. It appears that this is one of the few cases where an index may need to be rebuilt...

I rebuilt the index, performed the search, got a result instantly,
only 3 consistent gets!!!

One followup question, that you'll all likely laugh at. I got into
this "mess" by having a table that we frequently perform delete from
TABLE where DATE < ? - this situation is going to continue to arise.
Should i simply schedule frequent index rebuilds? I understand
partitioning the data is probably the way to go, but what is frequent
rebuilds the simplest solution here (by simple, i mean least knowledge/
testing/sql involved)?

Thanks again to all your help!!! Sincerely,
Bob

Robert Klemme

unread,

Jan 31, 2008, 12:36:21 PM1/31/08

to

On 31.01.2008 14:49, bobd...@gmail.com wrote:
> I probably should've prefaced this entire thread with - I'm an
> applications developer, not a dba :) I know this is a lame excuse,
> but i simply don't have the time nor mandate to become an oracle guru,
> i'm simply tasked with getting an application to work with oracle (and
> a variety of other db's). Every once in a while i get cycles to deal
> with issues like this, but i certainly don't spend enough time doing
> it.

No worries, it will just take a bit longer to become an Oracle guru.
Eventually you'll get there. :-)

> Anyways, Charles has helped me out bigtime by pointing me in the right
> direction:
>>> http://richardfoote.files.wordpress.com/2007/12/index-internals-rebuilding-the-truth.pdf
>>> Pages 133-135 show what is happening in your situation. It appears that this is one of the few cases where an index may need to be rebuilt...
>
> I rebuilt the index, performed the search, got a result instantly,
> only 3 consistent gets!!!
>
> One followup question, that you'll all likely laugh at. I got into
> this "mess" by having a table that we frequently perform delete from
> TABLE where DATE < ? - this situation is going to continue to arise.
> Should i simply schedule frequent index rebuilds? I understand
> partitioning the data is probably the way to go, but what is frequent
> rebuilds the simplest solution here (by simple, i mean least knowledge/
> testing/sql involved)?

If your deletion is part of a batch job that is run infrequently then
it's probably easiest to just add the index rebuild to the batch. Note
the ONLINE flag which will slow down the rebuild a bit but do not
require locking of the whole table. So your app can continue almost
normally.

If you use partitioning in pre Oracle 11 you need to set up a job that
will create partitions properly. And in all versions you need another
job for the deletions (again assuming they are done on a regular basis).

For this not too uncommon scenario of data coming and going time based
this MIN issue is really annoying. IMHO Oracle should do something
about it - at least it would be nice if there was an option during index
creation that would enable automatic index tree pruning at the cost of a
bit of performance.

Kind regards

robert

Jonathan Lewis

unread,

Feb 2, 2008, 6:01:21 AM2/2/08

to

<bobd...@gmail.com> wrote in message
news:805c5d03-8e41-4fa9...@v67g2000hse.googlegroups.com...

> Anyways, Charles has helped me out bigtime by pointing me in the right
> direction:
>>> http://richardfoote.files.wordpress.com/2007/12/index-internals-rebuilding-the-truth.pdf
>>> Pages 133-135 show what is happening in your situation. It appears
>>> that this is one of the few cases where an index may need to be
>>> rebuilt...
>
> I rebuilt the index, performed the search, got a result instantly,
> only 3 consistent gets!!!
>
> One followup question, that you'll all likely laugh at. I got into
> this "mess" by having a table that we frequently perform delete from
> TABLE where DATE < ? - this situation is going to continue to arise.
> Should i simply schedule frequent index rebuilds? I understand
> partitioning the data is probably the way to go, but what is frequent
> rebuilds the simplest solution here (by simple, i mean least knowledge/
> testing/sql involved)?
>
> Thanks again to all your help!!! Sincerely,
> Bob

Sorry about getting into this so late - but your problem is
a classic 'delete the left hand end' issue, and one of the
reasons why you want to use the COALESCE command
after a big delete.

It's probably somewhere in Richard's presentation, but
when an index leaf block is emptied, it is linked to the
free list, but also stays in place in the index structure.

Your min() query was doing a '(min/max)' full scan, which
means it was going directly to the left (low) end of the index
in expectation of finding the value there. However, since
you've done a thorough delete of a lot of low-value rows,
the run-time engine got to the bottom block, and had to
walk a long walk through a lot of leaf blocks before finding
the first leaf block with any data in it.

A call to coalesce will collapse together adjacent leaf blocks
to reduce leaf block counts, and detach empty leaf blocks
from the structure so that subsequent queries don't have to
walk through them.

The cost / benefit balance is:
each coalesce requires a full walk of the index - so don't do
it when you have a large index with only a small amount of
recoverable space.

failing to coalesce (for your query) requires a lot of empty
leaf blocks to be walked - how many times do you want
to let this happen, and how slow can the query be, before
you coalesce.

--
Regards

Jonathan Lewis
http://jonathanlewis.wordpress.com

Author: Cost Based Oracle: Fundamentals
http://www.jlcomp.demon.co.uk/cbo_book/ind_book.html

The Co-operative Oracle Users' FAQ
http://www.jlcomp.demon.co.uk/faq/ind_faq.html

joel garry

unread,

Feb 6, 2008, 6:09:52 PM2/6/08

to

On Feb 2, 3:01 am, "Jonathan Lewis" <jonat...@jlcomp.demon.co.uk>
wrote:
> <bobdu...@gmail.com> wrote in message

>
> news:805c5d03-8e41-4fa9...@v67g2000hse.googlegroups.com...
>
>
>
>
>
> > Anyways, Charles has helped me out bigtime by pointing me in the right
> > direction:

> >>>http://richardfoote.files.wordpress.com/2007/12/index-internals-rebui...

And now I see Richard has published some more details about coalesce
in his Feb 5 and 6 blogs: http://richardfoote.wordpress.com/

jg
--
@home.com is bogus.

"Bravery is being the only one who knows you're afraid." - David
Hackworth