Re: long running select min(timestamp) query

From: Charles Hooper <hooperc2000_at_yahoo.com>
Date: Tue, 29 Jan 2008 10:33:15 -0800 (PST)
Message-ID: <402fb373-752d-43f2-af4b-da34478d6c86@l1g2000hsa.googlegroups.com>


On Jan 29, 12:25 pm, "bobdu..._at_gmail.com" <bobdu..._at_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


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


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

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;


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

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; Charles Hooper
IT Manager/Oracle DBA
K&M Machine-Fabricating, Inc. Received on Tue Jan 29 2008 - 12:33:15 CST

Original text of this message