September 8, 2010
There is a section in the Oracle Database 11.2 Performance Tuning Guide, which seems to have originated all the way back to the Oracle Database 10.1 Performance Tuning Guide that has bothered me a bit:
10.3.2.5 Finding the Object Requiring I/O
To determine the possible causes, first query V$SESSION to identify the value of ROW_WAIT_OBJ# when the session waits for db file scattered read. For example:SELECT row_wait_obj# FROM V$SESSION WHERE EVENT = 'db file scattered read';To identify the object and object type contended for, query DBA_OBJECTS using the value for ROW_WAIT_OBJ# that is returned from V$SESSION. For example:
SELECT owner, object_name, subobject_name, object_type FROM DBA_OBJECTS WHERE data_object_id = &row_wait_obj;
Notice that the documentation shows that the value from the ROW_WAIT_OBJ# column in V$SESSION is used to drive into DBA_OBJECTS using the DATA_OBJECT_ID column to determine the OBJECT_NAME and SUBOBJECT_NAME of the object involved in the wait event. At this point you might be thinking that it is also the DATA_OBJECT_ID that appears in the WAIT lines found in a 10046 trace file, and that would be a logical conclusion. Let’s see if we are able to find a little clarification from the documentation about the OBJECT_ID and DATA_OBJECT_ID columns:
“OBJECT_ID: Dictionary object number of the object
DATA_OBJECT_ID: Dictionary object number of the segment that contains the objectNote: OBJECT_ID and DATA_OBJECT_ID display data dictionary metadata. Do not confuse these numbers with the unique 16-byte object identifier (object ID) that Oracle Database assigns to row objects in object tables in the system.”
Well, that almost helps a little, DATA_OBJECT_ID relates to the segments that compose the object. More information may be found here.
A quick check of Metalink (MOS) finds the helpful Metalink Doc ID 39817.1 “Interpreting Raw SQL_TRACE and DBMS_SUPPORT.START_TRACE Output” that describes the contents of a 10046 trace file, but the document completely avoids describing the meaning of the obj# parameter in the WAIT lines of the trace file. Another Metalink document found by searching on the keyword DATA_OBJECT_ID also seemed to be a bit unclear about V$SESSION and DATA_OBJECT_ID/OBJECT_ID (to put it nicely).
So, do the waits events in V$SESSION and in 10046 trace files show the OBJECT_ID or the DATA_OBJECT_ID? What we need is a test case to see for ourselves. We will create a simple table with a primary key index, add a secondary index, insert 100,000 rows into the table, and then collect table and index statistics:
CREATE TABLE T10 (
C1 NUMBER,
C2 NUMBER,
C3 VARCHAR2(100),
PRIMARY KEY (C1));
CREATE INDEX IND_T10_C2 ON T10(C2);
INSERT INTO
T10
SELECT
ROWNUM,
ROWNUM,
LPAD('A',100,'A')
FROM
DUAL
CONNECT BY
LEVEL<=100000;
COMMIT;
EXEC DBMS_STATS.GATHER_TABLE_STATS(OWNNAME=>USER,TABNAME=>'T10',CASCADE=>TRUE)
Next, let’s check the OBJECT_ID and the DATA_OBJECT_ID for the indexes on the table that was just created:
COLUMN OBJECT_NAME FORMAT A12
SELECT
OBJECT_NAME,
OBJECT_ID,
DATA_OBJECT_ID
FROM
DBA_OBJECTS
WHERE
(OWNER,OBJECT_NAME) IN
(SELECT
OWNER,
INDEX_NAME
FROM
DBA_INDEXES
WHERE
TABLE_NAME='T10'
AND OWNER=USER);
OBJECT_NAME OBJECT_ID DATA_OBJECT_ID
------------ ---------- --------------
IND_T10_C2 99707 99707
SYS_C0016827 99706 99706
At this point the OBJECT_ID and DATA_OBJECT_ID columns contain identical values. So, let’s flush the buffer cache to force physical reads, enable a 10046 trace at level 12, and then select from the test table:
ALTER SYSTEM FLUSH BUFFER_CACHE; ALTER SYSTEM FLUSH BUFFER_CACHE; ALTER SESSION SET TRACEFILE_IDENTIFIER = 'TESTING_OBJECTID'; ALTER SESSION SET EVENTS '10046 TRACE NAME CONTEXT FOREVER, LEVEL 12'; SELECT * FROM T10 WHERE C1 BETWEEN 1 AND 100; ALTER SESSION SET EVENTS '10046 TRACE NAME CONTEXT OFF';
If we look inside the TESTING_OBJECTID trace file, we will probably see something that looks like this (the obj# for the primary key index is highlighted in blue):
... PARSING IN CURSOR #18 len=50 dep=0 uid=60 oct=3 lid=60 tim=1839119134694 hv=804032012 ad='1e3c5558' sqlid='56b2yxcryt3hc' SELECT * FROM T10 WHERE C1 BETWEEN 1 AND 100 END OF STMT PARSE #18:c=0,e=0,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=1,plh=2473627518,tim=1839119134694 EXEC #18:c=0,e=0,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=2473627518,tim=1839119134694 WAIT #18: nam='SQL*Net message to client' ela= 3 driver id=1413697536 #bytes=1 p3=0 obj#=376 tim=1839119156325 WAIT #18: nam='db file sequential read' ela= 16306 file#=5 block#=1322147 blocks=1 obj#=99706 tim=1839119172691 WAIT #18: nam='db file sequential read' ela= 161 file#=5 block#=1322148 blocks=1 obj#=99706 tim=1839119172929 WAIT #18: nam='db file sequential read' ela= 3604 file#=5 block#=1321964 blocks=1 obj#=99705 tim=1839119176568 FETCH #18:c=0,e=31267,p=3,cr=3,cu=0,mis=0,r=1,dep=0,og=1,plh=2473627518,tim=1839119165961 WAIT #18: nam='SQL*Net message from client' ela= 369 driver id=1413697536 #bytes=1 p3=0 obj#=99705 tim=1839119177012 WAIT #18: nam='SQL*Net message to client' ela= 1 driver id=1413697536 #bytes=1 p3=0 obj#=99705 tim=1839119177058 FETCH #18:c=0,e=0,p=0,cr=2,cu=0,mis=0,r=15,dep=0,og=1,plh=2473627518,tim=1839119165961 WAIT #18: nam='SQL*Net message from client' ela= 14786 driver id=1413697536 #bytes=1 p3=0 obj#=99705 tim=1839119191906 WAIT #18: nam='SQL*Net message to client' ela= 1 driver id=1413697536 #bytes=1 p3=0 obj#=99705 tim=1839119191942 FETCH #18:c=0,e=0,p=0,cr=2,cu=0,mis=0,r=15,dep=0,og=1,plh=2473627518,tim=1839119165961 WAIT #18: nam='SQL*Net message from client' ela= 9246 driver id=1413697536 #bytes=1 p3=0 obj#=99705 tim=1839119201244 WAIT #18: nam='SQL*Net message to client' ela= 2 driver id=1413697536 #bytes=1 p3=0 obj#=99705 tim=1839119201425 FETCH #18:c=0,e=0,p=0,cr=2,cu=0,mis=0,r=15,dep=0,og=1,plh=2473627518,tim=1839119197198 WAIT #18: nam='SQL*Net message from client' ela= 8680 driver id=1413697536 #bytes=1 p3=0 obj#=99705 tim=1839119210215 WAIT #18: nam='SQL*Net message to client' ela= 3 driver id=1413697536 #bytes=1 p3=0 obj#=99705 tim=1839119210364 FETCH #18:c=0,e=0,p=0,cr=2,cu=0,mis=0,r=15,dep=0,og=1,plh=2473627518,tim=1839119197198 WAIT #18: nam='SQL*Net message from client' ela= 15822 driver id=1413697536 #bytes=1 p3=0 obj#=99705 tim=1839119226311 WAIT #18: nam='SQL*Net message to client' ela= 1 driver id=1413697536 #bytes=1 p3=0 obj#=99705 tim=1839119226376 WAIT #18: nam='db file sequential read' ela= 174 file#=5 block#=1321965 blocks=1 obj#=99705 tim=1839119226589 FETCH #18:c=0,e=0,p=1,cr=3,cu=0,mis=0,r=15,dep=0,og=1,plh=2473627518,tim=1839119197198 WAIT #18: nam='SQL*Net message from client' ela= 10086 driver id=1413697536 #bytes=1 p3=0 obj#=99705 tim=1839119236751 WAIT #18: nam='SQL*Net message to client' ela= 1 driver id=1413697536 #bytes=1 p3=0 obj#=99705 tim=1839119236830 FETCH #18:c=0,e=0,p=0,cr=2,cu=0,mis=0,r=15,dep=0,og=1,plh=2473627518,tim=1839119228446 WAIT #18: nam='SQL*Net message from client' ela= 8652 driver id=1413697536 #bytes=1 p3=0 obj#=99705 tim=1839119245603 WAIT #18: nam='SQL*Net message to client' ela= 1 driver id=1413697536 #bytes=1 p3=0 obj#=99705 tim=1839119245641 FETCH #18:c=0,e=0,p=0,cr=2,cu=0,mis=0,r=9,dep=0,og=1,plh=2473627518,tim=1839119228446 STAT #18 id=1 cnt=100 pid=0 pos=1 obj=99705 op='TABLE ACCESS BY INDEX ROWID T10 (cr=18 pr=4 pw=0 time=0 us cost=4 size=11000 card=100)' STAT #18 id=2 cnt=100 pid=1 pos=1 obj=99706 op='INDEX RANGE SCAN SYS_C0016827 (cr=9 pr=2 pw=0 time=0 us cost=2 size=0 card=100)' WAIT #18: nam='SQL*Net message from client' ela= 11094 driver id=1413697536 #bytes=1 p3=0 obj#=99705 tim=1839119256866 CLOSE #18:c=0,e=0,dep=0,type=0,tim=1839119228446 ...
One of Jonthan Lewis’ blog articles shows that rebuilding an index will cause its OBJECT_ID and DATA_OBJECT_ID columns to deviate from each other. So, let’s rebuild the table’s indexes and see what happens to the OBJECT_ID and DATA_OBJECT_ID columns:
ALTER INDEX IND_T10_C2 REBUILD; ALTER INDEX SYS_C0016827 REBUILD; SELECT OBJECT_NAME, OBJECT_ID, DATA_OBJECT_ID FROM DBA_OBJECTS WHERE (OWNER,OBJECT_NAME) IN (SELECT OWNER, INDEX_NAME FROM DBA_INDEXES WHERE TABLE_NAME='T10' AND OWNER=USER); OBJECT_NAME OBJECT_ID DATA_OBJECT_ID ------------ ---------- -------------- IND_T10_C2 99707 99708 SYS_C0016827 99706 99709
For both indexes the OBJECT_ID column stayed the same, while the DATA_OBJECT_ID changed. Let’s repeat the earlier test:
ALTER SYSTEM FLUSH BUFFER_CACHE; ALTER SYSTEM FLUSH BUFFER_CACHE; ALTER SESSION SET TRACEFILE_IDENTIFIER = 'TESTING_OBJECTID2'; ALTER SESSION SET EVENTS '10046 TRACE NAME CONTEXT FOREVER, LEVEL 12'; SELECT * FROM T10 WHERE C1 BETWEEN 1 AND 100; ALTER SESSION SET EVENTS '10046 TRACE NAME CONTEXT OFF';
If we look inside the TESTING_OBJECTID2 trace file, we will probably see something that looks like this (the obj# for the primary key index is highlighted in blue):
... PARSING IN CURSOR #7 len=50 dep=0 uid=60 oct=3 lid=60 tim=1839468475585 hv=804032012 ad='1e3c5558' sqlid='56b2yxcryt3hc' SELECT * FROM T10 WHERE C1 BETWEEN 1 AND 100 END OF STMT PARSE #7:c=0,e=58941,p=6,cr=7,cu=0,mis=1,r=0,dep=0,og=1,plh=2473627518,tim=1839468475585 EXEC #7:c=0,e=0,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=2473627518,tim=1839468475585 WAIT #7: nam='SQL*Net message to client' ela= 3 driver id=1413697536 #bytes=1 p3=0 obj#=376 tim=1839468487835 WAIT #7: nam='db file sequential read' ela= 187 file#=5 block#=1322155 blocks=1 obj#=99706 tim=1839468488080 WAIT #7: nam='db file sequential read' ela= 14827 file#=5 block#=1322156 blocks=1 obj#=99706 tim=1839468502945 WAIT #7: nam='db file sequential read' ela= 2599 file#=5 block#=1321964 blocks=1 obj#=99705 tim=1839468505581 FETCH #7:c=0,e=0,p=3,cr=3,cu=0,mis=0,r=1,dep=0,og=1,plh=2473627518,tim=1839468475585 WAIT #7: nam='SQL*Net message from client' ela= 371 driver id=1413697536 #bytes=1 p3=0 obj#=99705 tim=1839468506021 WAIT #7: nam='SQL*Net message to client' ela= 1 driver id=1413697536 #bytes=1 p3=0 obj#=99705 tim=1839468506066 FETCH #7:c=0,e=0,p=0,cr=2,cu=0,mis=0,r=15,dep=0,og=1,plh=2473627518,tim=1839468475585 WAIT #7: nam='SQL*Net message from client' ela= 11270 driver id=1413697536 #bytes=1 p3=0 obj#=99705 tim=1839468517397 WAIT #7: nam='SQL*Net message to client' ela= 1 driver id=1413697536 #bytes=1 p3=0 obj#=99705 tim=1839468517471 FETCH #7:c=0,e=0,p=0,cr=2,cu=0,mis=0,r=15,dep=0,og=1,plh=2473627518,tim=1839468506832 WAIT #7: nam='SQL*Net message from client' ela= 9067 driver id=1413697536 #bytes=1 p3=0 obj#=99705 tim=1839468526595 WAIT #7: nam='SQL*Net message to client' ela= 1 driver id=1413697536 #bytes=1 p3=0 obj#=99705 tim=1839468526635 FETCH #7:c=0,e=0,p=0,cr=2,cu=0,mis=0,r=15,dep=0,og=1,plh=2473627518,tim=1839468506832 WAIT #7: nam='SQL*Net message from client' ela= 11581 driver id=1413697536 #bytes=1 p3=0 obj#=99705 tim=1839468538273 WAIT #7: nam='SQL*Net message to client' ela= 1 driver id=1413697536 #bytes=1 p3=0 obj#=99705 tim=1839468538345 FETCH #7:c=0,e=0,p=0,cr=2,cu=0,mis=0,r=15,dep=0,og=1,plh=2473627518,tim=1839468538078 WAIT #7: nam='SQL*Net message from client' ela= 14327 driver id=1413697536 #bytes=1 p3=0 obj#=99705 tim=1839468552729 WAIT #7: nam='SQL*Net message to client' ela= 1 driver id=1413697536 #bytes=1 p3=0 obj#=99705 tim=1839468552763 WAIT #7: nam='db file sequential read' ela= 160 file#=5 block#=1321965 blocks=1 obj#=99705 tim=1839468552953 FETCH #7:c=0,e=0,p=1,cr=3,cu=0,mis=0,r=15,dep=0,og=1,plh=2473627518,tim=1839468538078 WAIT #7: nam='SQL*Net message from client' ela= 13353 driver id=1413697536 #bytes=1 p3=0 obj#=99705 tim=1839468566369 WAIT #7: nam='SQL*Net message to client' ela= 1 driver id=1413697536 #bytes=1 p3=0 obj#=99705 tim=1839468566406 FETCH #7:c=0,e=0,p=0,cr=2,cu=0,mis=0,r=15,dep=0,og=1,plh=2473627518,tim=1839468538078 WAIT #7: nam='SQL*Net message from client' ela= 13395 driver id=1413697536 #bytes=1 p3=0 obj#=99705 tim=1839468579857 WAIT #7: nam='SQL*Net message to client' ela= 1 driver id=1413697536 #bytes=1 p3=0 obj#=99705 tim=1839468579922 FETCH #7:c=0,e=0,p=0,cr=2,cu=0,mis=0,r=9,dep=0,og=1,plh=2473627518,tim=1839468569331 STAT #7 id=1 cnt=100 pid=0 pos=1 obj=99705 op='TABLE ACCESS BY INDEX ROWID T10 (cr=18 pr=4 pw=0 time=0 us cost=4 size=11000 card=100)' STAT #7 id=2 cnt=100 pid=1 pos=1 obj=99706 op='INDEX RANGE SCAN SYS_C0016827 (cr=9 pr=2 pw=0 time=0 us cost=2 size=0 card=100)' WAIT #7: nam='SQL*Net message from client' ela= 6563 driver id=1413697536 #bytes=1 p3=0 obj#=99705 tim=1839468586612 CLOSE #7:c=0,e=0,dep=0,type=0,tim=1839468569331 ...
In the above, we still see the OBJECT_ID value, not the DATA_OBJECT_ID value. So, the quote from the Oracle Performance Tuning Guide does not agree with the trace file tests when we use the primary key index. Let’s try again using the secondary index:
ALTER SYSTEM FLUSH BUFFER_CACHE; ALTER SYSTEM FLUSH BUFFER_CACHE; ALTER SESSION SET TRACEFILE_IDENTIFIER = 'TESTING_OBJECTID3'; ALTER SESSION SET EVENTS '10046 TRACE NAME CONTEXT FOREVER, LEVEL 12'; SELECT * FROM T10 WHERE C2 BETWEEN 1 AND 100; ALTER SESSION SET EVENTS '10046 TRACE NAME CONTEXT OFF';
If we look inside the TESTING_OBJECTID3 trace file, we will probably see something that looks like this (the obj# for the secondary index is highlighted in green):
... PARSING IN CURSOR #12 len=50 dep=0 uid=60 oct=3 lid=60 tim=1839710379843 hv=2985431092 ad='1e344a10' sqlid='7xpx31ksz441n' SELECT * FROM T10 WHERE C2 BETWEEN 1 AND 100 END OF STMT PARSE #12:c=0,e=0,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=1,plh=1233283356,tim=1839710379843 EXEC #12:c=0,e=0,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=1233283356,tim=1839710379843 WAIT #12: nam='SQL*Net message to client' ela= 3 driver id=1413697536 #bytes=1 p3=0 obj#=376 tim=1839710383650 WAIT #12: nam='db file sequential read' ela= 29848 file#=5 block#=3103739 blocks=1 obj#=99707 tim=1839710413557 WAIT #12: nam='db file sequential read' ela= 164 file#=5 block#=3103740 blocks=1 obj#=99707 tim=1839710413798 WAIT #12: nam='db file sequential read' ela= 14273 file#=5 block#=1321964 blocks=1 obj#=99705 tim=1839710428108 FETCH #12:c=0,e=31253,p=3,cr=3,cu=0,mis=0,r=1,dep=0,og=1,plh=1233283356,tim=1839710411096 WAIT #12: nam='SQL*Net message from client' ela= 379 driver id=1413697536 #bytes=1 p3=0 obj#=99705 tim=1839710428561 WAIT #12: nam='SQL*Net message to client' ela= 1 driver id=1413697536 #bytes=1 p3=0 obj#=99705 tim=1839710428607 FETCH #12:c=0,e=0,p=0,cr=2,cu=0,mis=0,r=15,dep=0,og=1,plh=1233283356,tim=1839710411096 WAIT #12: nam='SQL*Net message from client' ela= 11997 driver id=1413697536 #bytes=1 p3=0 obj#=99705 tim=1839710440668 WAIT #12: nam='SQL*Net message to client' ela= 0 driver id=1413697536 #bytes=1 p3=0 obj#=99705 tim=1839710440704 FETCH #12:c=0,e=0,p=0,cr=2,cu=0,mis=0,r=15,dep=0,og=1,plh=1233283356,tim=1839710411096 WAIT #12: nam='SQL*Net message from client' ela= 12518 driver id=1413697536 #bytes=1 p3=0 obj#=99705 tim=1839710453280 WAIT #12: nam='SQL*Net message to client' ela= 1 driver id=1413697536 #bytes=1 p3=0 obj#=99705 tim=1839710453359 FETCH #12:c=0,e=0,p=0,cr=2,cu=0,mis=0,r=15,dep=0,og=1,plh=1233283356,tim=1839710442343 WAIT #12: nam='SQL*Net message from client' ela= 6330 driver id=1413697536 #bytes=1 p3=0 obj#=99705 tim=1839710459749 WAIT #12: nam='SQL*Net message to client' ela= 1 driver id=1413697536 #bytes=1 p3=0 obj#=99705 tim=1839710459786 FETCH #12:c=0,e=0,p=0,cr=2,cu=0,mis=0,r=15,dep=0,og=1,plh=1233283356,tim=1839710442343 WAIT #12: nam='SQL*Net message from client' ela= 9842 driver id=1413697536 #bytes=1 p3=0 obj#=99705 tim=1839710469685 WAIT #12: nam='SQL*Net message to client' ela= 1 driver id=1413697536 #bytes=1 p3=0 obj#=99705 tim=1839710469720 WAIT #12: nam='db file sequential read' ela= 163 file#=5 block#=1321965 blocks=1 obj#=99705 tim=1839710469913 FETCH #12:c=0,e=0,p=1,cr=3,cu=0,mis=0,r=15,dep=0,og=1,plh=1233283356,tim=1839710442343 WAIT #12: nam='SQL*Net message from client' ela= 6686 driver id=1413697536 #bytes=1 p3=0 obj#=99705 tim=1839710476663 WAIT #12: nam='SQL*Net message to client' ela= 1 driver id=1413697536 #bytes=1 p3=0 obj#=99705 tim=1839710476744 FETCH #12:c=0,e=0,p=0,cr=2,cu=0,mis=0,r=15,dep=0,og=1,plh=1233283356,tim=1839710473594 WAIT #12: nam='SQL*Net message from client' ela= 7580 driver id=1413697536 #bytes=1 p3=0 obj#=99705 tim=1839710484439 WAIT #12: nam='SQL*Net message to client' ela= 1 driver id=1413697536 #bytes=1 p3=0 obj#=99705 tim=1839710484478 FETCH #12:c=0,e=0,p=0,cr=2,cu=0,mis=0,r=9,dep=0,og=1,plh=1233283356,tim=1839710473594 STAT #12 id=1 cnt=100 pid=0 pos=1 obj=99705 op='TABLE ACCESS BY INDEX ROWID T10 (cr=18 pr=4 pw=0 time=0 us cost=4 size=11000 card=100)' STAT #12 id=2 cnt=100 pid=1 pos=1 obj=99707 op='INDEX RANGE SCAN IND_T10_C2 (cr=9 pr=2 pw=0 time=0 us cost=2 size=0 card=100)' WAIT #12: nam='SQL*Net message from client' ela= 4803 driver id=1413697536 #bytes=1 p3=0 obj#=99705 tim=1839710489408 CLOSE #12:c=0,e=0,dep=0,type=0,tim=1839710473594 ...
The above trace file section again shows the OBJECT_ID value, not the DATA_OBJECT_ID value. Maybe the single block reads just do not follow the pattern shown in the documentation – the documentation example showed a “db file scattered read wait” event. Let’s change the DATA_OBJECT_ID value for the table by truncating the table and re-insert the 100,000 rows so that we will be able to test a multi-block read wait event:
SELECT OBJECT_NAME, OBJECT_ID, DATA_OBJECT_ID FROM DBA_OBJECTS WHERE OBJECT_NAME='T10' AND OWNER=USER; OBJECT_NAME OBJECT_ID DATA_OBJECT_ID ------------ ---------- -------------- T10 99705 99705 TRUNCATE TABLE T10; SELECT OBJECT_NAME, OBJECT_ID, DATA_OBJECT_ID FROM DBA_OBJECTS WHERE OBJECT_NAME='T10' AND OWNER=USER; OBJECT_NAME OBJECT_ID DATA_OBJECT_ID ------------ ---------- -------------- T10 99705 99712 INSERT INTO T10 SELECT ROWNUM, ROWNUM, LPAD('A',100,'A') FROM DUAL CONNECT BY LEVEL<=100000; COMMIT; EXEC DBMS_STATS.GATHER_TABLE_STATS(OWNNAME=>USER,TABNAME=>'T10',CASCADE=>TRUE) ALTER SYSTEM FLUSH BUFFER_CACHE; ALTER SYSTEM FLUSH BUFFER_CACHE;
Now, let’s repeat the test script, forcing a full table scan (ROWNUM is used to terminate the full table scan as soon as 100 rows are retrieved):
ALTER SESSION SET TRACEFILE_IDENTIFIER = 'TESTING_OBJECTID4'; ALTER SESSION SET EVENTS '10046 TRACE NAME CONTEXT FOREVER, LEVEL 12'; SELECT /*+ FULL(T10) */ * FROM T10 WHERE C1 BETWEEN 1 AND 100 AND ROWNUM<=100; ALTER SESSION SET EVENTS '10046 TRACE NAME CONTEXT OFF';
If we look inside the TESTING_OBJECTID4 trace file, we will probably see something that looks like this (the obj# for the table is highlighted in orange):
... PARSING IN CURSOR #7 len=85 dep=0 uid=60 oct=3 lid=60 tim=1843785745036 hv=934747497 ad='1e3459a0' sqlid='4mv0qgcvvf7b9' SELECT /*+ FULL(T10) */ * FROM T10 WHERE C1 BETWEEN 1 AND 100 AND ROWNUM<=100 END OF STMT PARSE #7:c=0,e=0,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=1,plh=548010678,tim=1843785745036 EXEC #7:c=0,e=0,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=548010678,tim=1843785745036 WAIT #7: nam='SQL*Net message to client' ela= 3 driver id=1413697536 #bytes=1 p3=0 obj#=376 tim=1843785748938 WAIT #7: nam='db file sequential read' ela= 12046 file#=5 block#=1321962 blocks=1 obj#=99705 tim=1843785761044 WAIT #7: nam='db file scattered read' ela= 584 file#=5 block#=1321963 blocks=5 obj#=99705 tim=1843785761743 FETCH #7:c=0,e=7583,p=6,cr=5,cu=0,mis=0,r=1,dep=0,og=1,plh=548010678,tim=1843785752619 WAIT #7: nam='SQL*Net message from client' ela= 312 driver id=1413697536 #bytes=1 p3=0 obj#=99705 tim=1843785762170 WAIT #7: nam='SQL*Net message to client' ela= 1 driver id=1413697536 #bytes=1 p3=0 obj#=99705 tim=1843785762216 FETCH #7:c=0,e=0,p=0,cr=1,cu=0,mis=0,r=15,dep=0,og=1,plh=548010678,tim=1843785752619 WAIT #7: nam='SQL*Net message from client' ela= 6205 driver id=1413697536 #bytes=1 p3=0 obj#=99705 tim=1843785768477 WAIT #7: nam='SQL*Net message to client' ela= 3 driver id=1413697536 #bytes=1 p3=0 obj#=99705 tim=1843785768573 FETCH #7:c=0,e=0,p=0,cr=1,cu=0,mis=0,r=15,dep=0,og=1,plh=548010678,tim=1843785752619 WAIT #7: nam='SQL*Net message from client' ela= 5615 driver id=1413697536 #bytes=1 p3=0 obj#=99705 tim=1843785774285 WAIT #7: nam='SQL*Net message to client' ela= 2 driver id=1413697536 #bytes=1 p3=0 obj#=99705 tim=1843785774368 FETCH #7:c=0,e=0,p=0,cr=1,cu=0,mis=0,r=15,dep=0,og=1,plh=548010678,tim=1843785752619 WAIT #7: nam='SQL*Net message from client' ela= 5314 driver id=1413697536 #bytes=1 p3=0 obj#=99705 tim=1843785779776 WAIT #7: nam='SQL*Net message to client' ela= 3 driver id=1413697536 #bytes=1 p3=0 obj#=99705 tim=1843785779888 FETCH #7:c=0,e=0,p=0,cr=1,cu=0,mis=0,r=15,dep=0,og=1,plh=548010678,tim=1843785752619 WAIT #7: nam='SQL*Net message from client' ela= 5731 driver id=1413697536 #bytes=1 p3=0 obj#=99705 tim=1843785785718 WAIT #7: nam='SQL*Net message to client' ela= 2 driver id=1413697536 #bytes=1 p3=0 obj#=99705 tim=1843785785826 FETCH #7:c=0,e=0,p=0,cr=2,cu=0,mis=0,r=15,dep=0,og=1,plh=548010678,tim=1843785783865 WAIT #7: nam='SQL*Net message from client' ela= 5572 driver id=1413697536 #bytes=1 p3=0 obj#=99705 tim=1843785791470 WAIT #7: nam='SQL*Net message to client' ela= 1 driver id=1413697536 #bytes=1 p3=0 obj#=99705 tim=1843785791505 FETCH #7:c=0,e=0,p=0,cr=1,cu=0,mis=0,r=15,dep=0,og=1,plh=548010678,tim=1843785783865 WAIT #7: nam='SQL*Net message from client' ela= 6224 driver id=1413697536 #bytes=1 p3=0 obj#=99705 tim=1843785797784 WAIT #7: nam='SQL*Net message to client' ela= 1 driver id=1413697536 #bytes=1 p3=0 obj#=99705 tim=1843785797874 FETCH #7:c=0,e=0,p=0,cr=1,cu=0,mis=0,r=9,dep=0,og=1,plh=548010678,tim=1843785783865 STAT #7 id=1 cnt=100 pid=0 pos=1 obj=0 op='COUNT STOPKEY (cr=13 pr=6 pw=0 time=0 us)' STAT #7 id=2 cnt=100 pid=1 pos=1 obj=99705 op='TABLE ACCESS FULL T10 (cr=13 pr=6 pw=0 time=0 us cost=199 size=11000 card=100)' WAIT #7: nam='SQL*Net message from client' ela= 4043 driver id=1413697536 #bytes=1 p3=0 obj#=99705 tim=1843785802044 CLOSE #7:c=0,e=0,dep=0,type=0,tim=1843785783865 WAIT #0: nam='SQL*Net message to client' ela= 1 driver id=1413697536 #bytes=1 p3=0 obj#=99705 tim=1843785802117 WAIT #0: nam='SQL*Net message from client' ela= 877475 driver id=1413697536 #bytes=1 p3=0 obj#=99705 tim=1843786679612 ...
The above trace file section again shows the OBJECT_ID value, not the DATA_OBJECT_ID value – even for the “db file scattered read” wait event. The documentation reference must not apply to 10046 trace files.
Now let’s test V$SESSION – the view mentioned in the Oracle Performance Tuning Guide. We will need 2 sessions for this test. First, let’s insert 1,000,000 rows into the test table so that it takes a little longer to select the rows from the table (allowing us to check on the session’s wait events using a second session), and then determine the SID for the first session:
Session 1:
INSERT INTO
T10
SELECT
ROWNUM+100000,
ROWNUM+100000,
LPAD('A',100,'A')
FROM
DUAL
CONNECT BY
LEVEL<=1000000;
COMMIT;
SELECT DISTINCT SID FROM V$MYSTAT;
SID
---
302
ALTER SYSTEM FLUSH BUFFER_CACHE;
ALTER SYSTEM FLUSH BUFFER_CACHE;
SET AUTOTRACE TRACEONLY STATISTICS
SET ARRAYSIZE 5000
The SID for session 1 is 302, so in Session 2 we will prepare to repeatedly execute the following SQL statement:
Session 2:
SELECT EVENT, ROW_WAIT_OBJ# FROM V$SESSION WHERE SID=302;
In Session 1, let’s start executing our SQL statement, and immediately jump into Session 2 to start querying V$SESSION:
Session 1:
SELECT * FROM T10;
Session 2:
SELECT EVENT, ROW_WAIT_OBJ# FROM V$SESSION WHERE SID=302; EVENT ROW_WAIT_OBJ# ------------------------------ ------------- SQL*Net message from client 99705 SQL> / EVENT ROW_WAIT_OBJ# ------------------------------ ------------- SQL*Net message from client 99705 SQL> / EVENT ROW_WAIT_OBJ# ------------------------------ ------------- db file sequential read 99705 SQL> / EVENT ROW_WAIT_OBJ# ------------------------------ ------------- SQL*Net message from client 99705 ... SQL> / EVENT ROW_WAIT_OBJ# ------------------------------ ------------- direct path read 99705 SQL> / EVENT ROW_WAIT_OBJ# ------------------------------ ------------- direct path read 99705 SQL> / EVENT ROW_WAIT_OBJ# ------------------------------ ------------- SQL*Net message from client 99705
Notice in the above that V$SESSION shows the OBJECT_ID for table T10, not the DATA_OBJECT_ID as described in the 11.2.0.1 Performance Tuning Guide. Maybe it is just the “db file sequential read” and “direct path read” wait events (obviously, this test was performed in 11g or above due to the “direct path read” wait events, specifically 11.1.0.7) that show the OBJECT_ID – the example from the Performance Tuning Guide showed a lookup that involved a “db file scattered read” wait event. Let’s see if that wait event is handled differently in V$SESSION than the “db file sequential read” and “direct path read” wait events. We will need to set event 10949 in the session to disable the direct path reads for the full table scan:
Session 1:
ALTER SESSION SET DB_FILE_MULTIBLOCK_READ_COUNT=16; ALTER SESSION SET EVENTS '10949 TRACE NAME CONTEXT FOREVER, LEVEL 1'; ALTER SYSTEM FLUSH BUFFER_CACHE; ALTER SYSTEM FLUSH BUFFER_CACHE; SELECT * FROM T10;
Session 2:
SQL> / EVENT ROW_WAIT_OBJ# ------------------------------ ------------- SQL*Net message from client 99705 SQL> / EVENT ROW_WAIT_OBJ# ------------------------------ ------------- SQL*Net message from client 99705 SQL> / EVENT ROW_WAIT_OBJ# ------------------------------ ------------- db file scattered read 99705 SQL> / EVENT ROW_WAIT_OBJ# ------------------------------ ------------- db file scattered read 99705 SQL> / EVENT ROW_WAIT_OBJ# ------------------------------ ------------- db file scattered read 99705 SQL> / EVENT ROW_WAIT_OBJ# ------------------------------ ------------- SQL*Net more data to client 99705
We are still seeing the OBJECT_ID of table T10, and not the DATA_OBJECT_ID in the query of V$SESSION. Just to make certain that nothing strange happened where the DATA_OBJECT_ID reverted back to the OBJECT_ID value:
SELECT
OBJECT_NAME,
OBJECT_ID,
DATA_OBJECT_ID
FROM
DBA_OBJECTS
WHERE
OBJECT_NAME='T10'
AND OWNER=USER;
OBJECT_NAME OBJECT_ID DATA_OBJECT_ID
------------ ---------- --------------
T10 99705 99712
Is this the third documentation bug that was mentioned in articles of this blog (bug number 2 was identified by Chris Antognini just a couple of days ago)? Maybe things change with partitioned objects? What better way to determine what happens than to set up a test case?
CREATE TABLE T11
PARTITION BY RANGE(C1)
(PARTITION P1 VALUES LESS THAN (5),
PARTITION P2 VALUES LESS THAN (10),
PARTITION P3 VALUES LESS THAN (20),
PARTITION P4 VALUES LESS THAN (40),
PARTITION P5 VALUES LESS THAN (80),
PARTITION P6 VALUES LESS THAN (160),
PARTITION P7 VALUES LESS THAN (320),
PARTITION P8 VALUES LESS THAN (640),
PARTITION P9 VALUES LESS THAN (1280),
PARTITION P10 VALUES LESS THAN (2560),
PARTITION P11 VALUES LESS THAN (5120),
PARTITION P12 VALUES LESS THAN (10240),
PARTITION P20 VALUES LESS THAN (MAXVALUE))
AS
SELECT
ROWNUM C1,
ROWNUM C2,
LPAD('A',100,'A') C3
FROM
DUAL
CONNECT BY
LEVEL<=1000000;
COMMIT;
EXEC DBMS_STATS.GATHER_TABLE_STATS(OWNNAME=>USER,TABNAME=>'T11',CASCADE=>TRUE)
Let’s take a look at the OBJECT_IDs and DATA_OBJECT_IDs for this table (note that I have switched from Oracle Database 11.1.0.7 to 11.2.0.1 running on a different server):
SELECT OBJECT_NAME, SUBOBJECT_NAME, OBJECT_ID, DATA_OBJECT_ID FROM DBA_OBJECTS WHERE OBJECT_NAME='T11' AND OWNER=USER ORDER BY OBJECT_ID; OBJECT_NAME SUBOBJECT_NAME OBJECT_ID DATA_OBJECT_ID ------------ -------------------- ---------- -------------- T11 77269 T11 P1 77270 77270 T11 P2 77271 77271 T11 P3 77272 77272 T11 P4 77273 77273 T11 P5 77274 77274 T11 P6 77275 77275 T11 P7 77276 77276 T11 P8 77277 77277 T11 P9 77278 77278 T11 P10 77279 77279 T11 P11 77280 77280 T11 P12 77281 77281 T11 P20 77282 77282
We start out with the OBJECT_ID and DATA_OBJECT_IDs having the same values, and then we truncate the table and check again:
TRUNCATE TABLE T11;
INSERT INTO
T11
SELECT
ROWNUM C1,
ROWNUM C2,
LPAD('A',100,'A') C3
FROM
DUAL
CONNECT BY
LEVEL<=1000000;
COMMIT;
SELECT
OBJECT_NAME,
SUBOBJECT_NAME,
OBJECT_ID,
DATA_OBJECT_ID
FROM
DBA_OBJECTS
WHERE
OBJECT_NAME='T11'
AND OWNER=USER
ORDER BY
OBJECT_ID;
OBJECT_NAME SUBOBJECT_NAME OBJECT_ID DATA_OBJECT_ID
------------ -------------------- ---------- --------------
T11 77269
T11 P1 77270 77283
T11 P2 77271 77284
T11 P3 77272 77285
T11 P4 77273 77286
T11 P5 77274 77287
T11 P6 77275 77288
T11 P7 77276 77289
T11 P8 77277 77290
T11 P9 77278 77291
T11 P10 77279 77292
T11 P11 77280 77293
T11 P12 77281 77294
T11 P20 77282 77295
The values are different now, as expected. So, we test:
ALTER SYSTEM FLUSH BUFFER_CACHE; ALTER SYSTEM FLUSH BUFFER_CACHE; SET AUTOTRACE TRACEONLY STATISTICS SET ARRAYSIZE 5000 ALTER SESSION SET TRACEFILE_IDENTIFIER = 'TESTING_OBJECTID5'; ALTER SESSION SET EVENTS '10046 TRACE NAME CONTEXT FOREVER, LEVEL 12'; SELECT /*+ FULL(T11) */ * FROM T11 WHERE C1 BETWEEN 1 AND 1000 AND ROWNUM<=1000; ALTER SESSION SET EVENTS '10046 TRACE NAME CONTEXT OFF';
From the resulting trace file:
... PARSING IN CURSOR #14 len=87 dep=0 uid=185 oct=3 lid=185 tim=182313780472 hv=2324608198 ad='467af4a28' sqlid='bqfj36a58xd66' SELECT /*+ FULL(T11) */ * FROM T11 WHERE C1 BETWEEN 1 AND 1000 AND ROWNUM<=1000 END OF STMT PARSE #14:c=0,e=609,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=1,plh=3101738663,tim=182313780472 EXEC #14:c=0,e=14,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=3101738663,tim=182313780539 WAIT #14: nam='SQL*Net message to client' ela= 1 driver id=1413697536 #bytes=1 p3=0 obj#=0 tim=182313780566 WAIT #14: nam='db file sequential read' ela= 386 file#=8 block#=13442 blocks=1 obj#=77270 tim=182313780979 WAIT #14: nam='db file scattered read' ela= 537 file#=8 block#=13443 blocks=5 obj#=77270 tim=182313781641 FETCH #14:c=0,e=1146,p=6,cr=4,cu=0,mis=0,r=1,dep=0,og=1,plh=3101738663,tim=182313781727 WAIT #14: nam='SQL*Net message from client' ela= 792 driver id=1413697536 #bytes=1 p3=0 obj#=77270 tim=182313782565 WAIT #14: nam='SQL*Net message to client' ela= 0 driver id=1413697536 #bytes=1 p3=0 obj#=77270 tim=182313782595 WAIT #14: nam='db file sequential read' ela= 395 file#=8 block#=13506 blocks=1 obj#=77271 tim=182313783021 WAIT #14: nam='db file scattered read' ela= 504 file#=8 block#=13507 blocks=5 obj#=77271 tim=182313783615 WAIT #14: nam='db file sequential read' ela= 414 file#=8 block#=13826 blocks=1 obj#=77272 tim=182313784129 WAIT #14: nam='db file scattered read' ela= 506 file#=8 block#=13827 blocks=5 obj#=77272 tim=182313784724 WAIT #14: nam='db file sequential read' ela= 396 file#=8 block#=13842 blocks=1 obj#=77273 tim=182313785226 WAIT #14: nam='db file scattered read' ela= 496 file#=8 block#=13843 blocks=5 obj#=77273 tim=182313785812 WAIT #14: nam='db file sequential read' ela= 318 file#=8 block#=13858 blocks=1 obj#=77274 tim=182313786245 WAIT #14: nam='db file scattered read' ela= 457 file#=8 block#=13859 blocks=5 obj#=77274 tim=182313786809 WAIT #14: nam='db file sequential read' ela= 369 file#=8 block#=13874 blocks=1 obj#=77275 tim=182313787319 WAIT #14: nam='db file scattered read' ela= 503 file#=8 block#=13875 blocks=5 obj#=77275 tim=182313787877 WAIT #14: nam='db file sequential read' ela= 395 file#=8 block#=13890 blocks=1 obj#=77276 tim=182313788447 WAIT #14: nam='db file scattered read' ela= 515 file#=8 block#=13891 blocks=5 obj#=77276 tim=182313789053 WAIT #14: nam='db file sequential read' ela= 329 file#=8 block#=13906 blocks=1 obj#=77277 tim=182313789587 WAIT #14: nam='db file scattered read' ela= 508 file#=8 block#=13907 blocks=5 obj#=77277 tim=182313790188 WAIT #14: nam='SQL*Net more data to client' ela= 34 driver id=1413697536 #bytes=8145 p3=0 obj#=77277 tim=182313790482 WAIT #14: nam='db file scattered read' ela= 558 file#=7 block#=2556696 blocks=8 obj#=77277 tim=182313791079 WAIT #14: nam='db file sequential read' ela= 371 file#=8 block#=13922 blocks=1 obj#=77278 tim=182313791521 WAIT #14: nam='db file scattered read' ela= 459 file#=8 block#=13923 blocks=5 obj#=77278 tim=182313792039 WAIT #14: nam='db file scattered read' ela= 457 file#=7 block#=2556720 blocks=8 obj#=77278 tim=182313792800 FETCH #14:c=0,e=10366,p=64,cr=76,cu=0,mis=0,r=999,dep=0,og=1,plh=3101738663,tim=182313792954 STAT #14 id=1 cnt=1000 pid=0 pos=1 obj=0 op='COUNT STOPKEY (cr=80 pr=70 pw=0 time=570 us)' STAT #14 id=2 cnt=1000 pid=1 pos=1 obj=0 op='PARTITION RANGE ITERATOR PARTITION: 1 9 (cr=80 pr=70 pw=0 time=570 us cost=16 size=111000 card=1000)' STAT #14 id=3 cnt=1000 pid=2 pos=1 obj=77269 op='TABLE ACCESS FULL T11 PARTITION: 1 9 (cr=80 pr=70 pw=0 time=353 us cost=16 size=111000 card=1000)' WAIT #14: nam='SQL*Net message from client' ela= 4472 driver id=1413697536 #bytes=1 p3=0 obj#=77278 tim=182313797501 CLOSE #14:c=0,e=9,dep=0,type=0,tim=182313818474 ...
———————–
The 10046 trace files shows the OBJECT_ID column of DBA_OBJECTS, not the DATA_OBJECT_ID column as seen in the tests that used both unpartitioned and partitioned tables. This documentation bug has been bugging me for at least four and a half years, but probably longer than that – I just thought it was worth briefly mentioning the problem.
Charles Hooper's Oracle Notes 
Recent Comments