Something is Bugging Me: V$SESSION and 10046 Trace Files Show OBJECT_ID or DATA_OBJECT_ID?

8 09 2010

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 object

Note: 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.


Actions

Information

6 responses

8 09 2010
Taral Desai

Very nice article. Really an eye opener

9 09 2010
Damir Vadas

Heavens and hell!

9 09 2010
maclean

10046 shows object_id, most time we have to identify the object from p1,p2,p3 ….

10 09 2010
Charles Hooper

maclean,

Your comment pretty well matches what I found when I started working with 10.2 in late 2005/early 2006. However, it seems that I have forgotten this fact once or twice, so I thought it best to document it in my Oracle Notes.

It is typically a lot faster (and less resource intensive) to use the OBJ# directly from the trace file to determine the object name, than it is to use the (named in 10g) P1, P2, and P3 parameters to find the object name. The 10g R2 Performance Tuning Guide, however, caused me a bit of confusion initially when I was trying to work with the OBJ# parameters found in 10046 trace files. I kept wondering what caused some lookups using the DATA_OBJECT_ID rather than the OBJECT_ID to work, while others failed – when I read Jonathan Lewis’ blog article (mentioned above) the cause was suddenly quite obvious.

10 09 2010
Franck Pachot

Hi,

What I’ve observed until now is that within dictionary tables, dictionary views, traces, dbms_xxx packages,…:
– OBJECT_ID, OBJ# or OBJN always refer to the logical object OBJECT_ID
– DATA_OBJECT_ID, DATAOBJ#, OBJD, OBJ, OBJECT_NUMBER always refer to physical segment DATA_OBJECT_ID

But rather than relying on that is is a good idea to test all queries with a moved table, in order to have different ID, (and move it into a transported tablespace in order to avoid another confusion between relative and absolute file numbers…)

Regards,
Franck.

10 09 2010
Charles Hooper

Franck,

That is a very helpful summary of which names imply OBJECT_ID and which names imply DATA_OBJECT_ID.

I would be interested in seeing any exceptions to Franck’s summary.

Leave a Reply

Fill in your details below or click an icon to log in:

WordPress.com Logo

You are commenting using your WordPress.com account. Log Out / Change )

Twitter picture

You are commenting using your Twitter account. Log Out / Change )

Facebook photo

You are commenting using your Facebook account. Log Out / Change )

Google+ photo

You are commenting using your Google+ account. Log Out / Change )

Connecting to %s




Follow

Get every new post delivered to your Inbox.

Join 141 other followers

%d bloggers like this: