Determining Why a Query Using MIN(column) in the WHERE Clause on an Indexed Column takes a Long Time

December 6, 2009

Some time ago the following question appeared in the comp.database.oracle.server Usenet group:
http://groups.google.com/group/comp.databases.oracle.server/browse_thread/thread/79d0a3d85381dc64

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?

I provided the following test case to demonstrate one possible reason for a MIN(column) query to require a longer time to execute than it should:

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:

 
---------------------------------------------------------------------------­--------------------
| 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 |
---------------------------------------------------------------------------­--------------------

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:

---------------------------------------------------------------------------­--------------------
| Id  | Operation                  | Name    | Starts | E-Rows | A-Rows |   A-Time   | Buffers |
---------------------------------------------------------------------------­--------------------
|   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;

The DBMS Xplan:

---------------------------------------------------------------------------­--------------------
| Id  | Operation                  | Name    | Starts | E-Rows | A-Rows |   A-Time   | Buffers |
---------------------------------------------------------------------------­--------------------
|   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 #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;

The DBMS Xplan:

---------------------------------------------------------------------------­--------------------
| Id  | Operation                  | Name    | Starts | E-Rows | A-Rows |   A-Time   | Buffers |
---------------------------------------------------------------------------­--------------------
|   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 |
---------------------------------------------------------------------------­--------------------

From the 10046 trace file:

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;

—

The original poster provided the following and sent to me a trace file for the query execution:

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
---------------------------------------------------------------------------­---------------------
| Id  | Operation                  | Name               | Rows  | Bytes | Cost (%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
---------------------------------------------------------------------------­----------
| 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 |
---------------------------------------------------------------------------­----------
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

 In the above, notice the 118,525 consistent gets and the 118,248 for the original table compared to the 132 consistent gets and 6 physical reads for the test table that the OP created, which indicates that Oracle was having trouble immediately jumping to the index block containing the minimum value when performing the INDEX FULL SCAN (MIN/MAX) operation.

The OP provided the following follow up:

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)?

Jonathan Lewis provided an excellent response to the OP.