Re: long running select min(timestamp) query
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