10046 Extended SQL Trace Interpretation

1 12 2009

December 1, 2009

(Forward to the Next Post in the Series)

10046 extended SQL trace files provide a significant level of detail specific to a single session.  Extended SQL traces are enabled by setting event 10046 to level 4 (bind variables), level 8 (wait events), or level 12 (bind variables and wait events).  There are several methods that may be used to set event 10046, partially dependent on the Oracle release version, and whether or not the event may be set interactively within the session:

  ALTER SESSION SET EVENTS '10046 TRACE NAME CONTEXT FOREVER, LEVEL 12';
-or-
  EXEC SYS.DBMS_SYSTEM.SET_EV(SID,SERIAL#,10046,12,'');
-or-
  EXEC SYS.DBMS_SUPPORT.START_TRACE_IN_SESSION(SID,SERIAL#,WAITS=>TRUE,BINDS=>FALSE);
-or-
  EXEC DBMS_MONITOR.SESSION_TRACE_ENABLE(SESSION_ID=>SID,SERIAL_NUM=>SERIAL#,WAITS=>TRUE,BINDS=>TRUE)
-or-
  EXEC SYS.DBMS_SYSTEM.SET_SQL_TRACE_IN_SESSION(SID,SERIAL#,TRUE);

The SID and SERIAL# may be retrieved from V$SESSION for the session of interest.  The SYS.DBMS_SYSTEM.SET_EV method is unsupported, but it works fine on older versions of Oracle where the other methods do not exist.  Not all of the above methods work in older Oracle releases.  Oracle will create the trace files in the server’s udump directory (or the trace directory with release 11.1.0.6 and later).  A logon trigger may be used to enable a 10046 extended SQL trace, possibly enabling a trace for all sessions that start the same program, or for a specific user.  10046 traces may also be enabled with the SQL*Plus ORADEBUG functionality.

Before executing any of the above commands (especially if enabled using an ALTER SYSTEM method), determine how to disable a 10046 trace, depending on how it was started:

  ALTER SESSION SET EVENTS '10046 TRACE NAME CONTEXT OFF';
-or-
  EXEC SYS.DBMS_SYSTEM.SET_EV(SID,SERIAL#,10046,0,'');
-or-
  EXEC SYS.DBMS_SUPPORT.STOP_TRACE_IN_SESSION(SID,SERIAL#);
-or-
  EXEC SYS.DBMS_SYSTEM.SET_SQL_TRACE_IN_SESSION(SID,SERIAL#,FALSE);

A short summary of several keywords found in a 10046 extended SQL trace file:
len= the number of characters in the SQL statement
dep= tells the application/trigger depth at which the SQL statement was executed. dep=0 indicates that it was executed by the client application. dep=1 indicates that the SQL statement was executed by a trigger, the Oracle optimizer, or a space management call. dep=2 indicates that the SQL statement was called from a trigger, dep=3 indicates that the SQL statement was called from a trigger that was called from a trigger.
tim= is a time stamp measured in 1/1,000,000 of a second that may be used for tracking the progress in the 10046 trace file – take the delta value of the most recent tim=, subtract the first tim=, divide the result by 1,000,000 – equals the number of seconds into the trace file.
c= CPU seconds – amount of CPU resources required at that point in the execution. On 8.1.7.4 and earlier, divide by 100 to obtain the number of seconds. After 8.1.7.4, divide by 1,000,000 to obtain the number of seconds.
e= Elapsed seconds – number of seconds as measured by a high precision clock at that point in the execution. This may be significantly different from CPU seconds. On 8.1.7.4 and earlier, divide by 100 to obtain the number of seconds. After 8.1.7.4, divide by 1,000,000 to obtain the number of seconds.
p= Physical blocks read from disk.
cr= Consistent reads
cu= Consistent reads in current mode
mis= Number of shared pool misses at that stage of execution.
r= Number of rows returned by the call
og= Optimizer goal – 1=ALL_ROWS, 2=FIRST_ROWS (and FIRST_ROWS_n), 3=RULE, 4=CHOOSE
XCTEND rlbk=0 indicates that the client issued a COMMIT, rd_only=1 indicates that no information changed in the database as a result of the COMMIT
ela= is the elapsed time in 1/100 of a second on 8.1.7.4 and earlier, and in 1/1,000,000 of a second on versions after 8.1.7.4.
p1= meaning depends on the wait event
p2= meaning depends on the wait event
p3= meaning depends on the wait event

STAT lines – the row source execution plan:
id= line identifier
cnt= number of rows returned or processed
pid= parent operation identifier – used to determine indentation of the plan
obj= object id of the object referenced at that stage of the plan

Putting the pieces together, it is possible to do the following analysis of a raw 10046 extended SQL trace file:

PARSING IN CURSOR #12 len=170 dep=0 uid=31 oct=3 lid=31 tim=768609360 hv=205969412 ad='a64cba88'
SELECT C1 , SUBSTR(C2,1,20) C2  FROM T7 WHERE   
  EXISTS ( 
    SELECT 
      1 
    FROM 
      T8 
    WHERE 
      T8.C1=T7.C1)
  AND T7.C1 BETWEEN :1 AND :2
END OF STMT
PARSE #12:c=0,e=29,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,tim=768609356
BINDS #12:
kkscoacd
 Bind#0
  oacdty=02 mxl=22(21) mxlc=00 mal=00 scl=00 pre=00
  oacflg=00 fl2=1000010 frm=00 csi=178 siz=48 off=0
  kxsbbbfp=151423d0  bln=22  avl=02  flg=05
  value=1
 Bind#1
  oacdty=02 mxl=22(21) mxlc=00 mal=00 scl=00 pre=00
  oacflg=00 fl2=1000010 frm=00 csi=178 siz=0 off=24
  kxsbbbfp=151423e8  bln=22  avl=03  flg=01
  value=81000
EXEC #12:c=0,e=807,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,tim=768611110
WAIT #12: nam='SQL*Net message to client' ela= 4 driver id=1413697536 #bytes=1 p3=0 obj#=114176 tim=768611226
WAIT #12: nam='db file sequential read' ela= 184 file#=4 block#=1779171 blocks=1 obj#=114178 tim=768611561
WAIT #12: nam='db file scattered read' ela= 213 file#=4 block#=1779172 blocks=5 obj#=114178 tim=768612046
WAIT #12: nam='db file sequential read' ela= 103 file#=4 block#=1138380 blocks=1 obj#=114177 tim=768612399
WAIT #12: nam='db file sequential read' ela= 87 file#=4 block#=1754469 blocks=1 obj#=114177 tim=768612648
WAIT #12: nam='db file sequential read' ela= 88 file#=4 block#=1138382 blocks=1 obj#=114177 tim=768612865
WAIT #12: nam='db file sequential read' ela= 81 file#=4 block#=1138374 blocks=1 obj#=114176 tim=768613103
FETCH #12:c=0,e=2195,p=10,cr=51,cu=0,mis=0,r=14,dep=0,og=1,tim=768613513
WAIT #12: nam='SQL*Net message from client' ela= 3432 driver id=1413697536 #bytes=1 p3=0 obj#=114176 tim=768617150
STAT #12 id=1 cnt=14 pid=0 pos=1 obj=0 op='FILTER  (cr=51 pr=10 pw=0 time=2170 us)'
STAT #12 id=2 cnt=14 pid=1 pos=1 obj=0 op='NESTED LOOPS  (cr=51 pr=10 pw=0 time=2137 us)'
STAT #12 id=3 cnt=14 pid=2 pos=1 obj=0 op='SORT UNIQUE (cr=7 pr=6 pw=0 time=984 us)'
STAT #12 id=4 cnt=14 pid=3 pos=1 obj=114178 op='TABLE ACCESS FULL T8 (cr=7 pr=6 pw=0 time=900 us)'
STAT #12 id=5 cnt=14 pid=2 pos=2 obj=114176 op='TABLE ACCESS BY INDEX ROWID T7 (cr=44 pr=4 pw=0 time=1131 us)'
STAT #12 id=6 cnt=14 pid=5 pos=1 obj=114177 op='INDEX UNIQUE SCAN SYS_C0020535 (cr=30 pr=3 pw=0 time=820 us)'

A simple walk through of the trace file, mapping the trace file to a timeline (this is output from my Toy Project for Performance Tuning):

Cursor 12   Ver 1   Parse at 0.000000
SELECT C1 , SUBSTR(C2,1,20) C2  FROM T7 WHERE   
  EXISTS ( 
    SELECT 
      1 
    FROM 
      T8 
    WHERE 
      T8.C1=T7.C1)
  AND T7.C1 BETWEEN :1 AND :2

Cursor 12   Ver 1   Parse at -0.000004 (Parse to Parse -0.000004),CPU Time 0.000000,
            Elapsed Time 0.000029,Rows Affected 0,Blks from Buff 0,Blks from Disk 0,Goal=ALL_ROWS
Bind Variables:BINDS #12:  -0.000004
   Bind#0
    oacdty=02 mxl=22(21) mxlc=00 mal=00 scl=00 pre=00
    oacflg=00 fl2=1000010 frm=00 csi=178 siz=48 off=0
    kxsbbbfp=151423d0  bln=22  avl=02  flg=05
    value=1
   Bind#1
    oacdty=02 mxl=22(21) mxlc=00 mal=00 scl=00 pre=00
    oacflg=00 fl2=1000010 frm=00 csi=178 siz=0 off=24
    kxsbbbfp=151423e8  bln=22  avl=03  flg=01
    value=81000

Cursor 12   Ver 1 Execute at 0.001750 (Parse to Exec  0.001750),CPU Time 0.000000,
            Elapsed Time 0.000807,Rows Affected 0,Blks from Buff 0,Blks from Disk 0,
Cursor 12   Ver 1            0.001866  0.000004   SQL*Net message to client
Cursor 12   Ver 1            0.002201  0.000184   db file sequential read
Cursor 12   Ver 1            0.002686  0.000213   db file scattered read
Cursor 12   Ver 1            0.003039  0.000103   db file sequential read
Cursor 12   Ver 1            0.003288  0.000087   db file sequential read
Cursor 12   Ver 1            0.003505  0.000088   db file sequential read
Cursor 12   Ver 1            0.003743  0.000081   db file sequential read
Cursor 12   Ver 1   Fetch at 0.004153 (Parse to Fetch 0.004153),CPU Time 0.000000,
            Elapsed Time 0.002195,Rows Retrievd 14,Blks from Buff 51,Blks from Disk 10
Cursor 12   Ver 1            0.007790  0.003432   SQL*Net message from client

Sometimes mapping the trace file to a timeline is not the best approach, but understanding the role of a specific SQL statement is more critical to understanding the cause of a performance problem (this is output from my Toy Project for Performance Tuning):

Similar SQL Statements in Group: 1
|PARSEs 1|CPU S 0.000000|CLOCK S 0.000029|ROWs  0|PHY RD BLKs  0|CON RD BLKs (Mem)  0|CUR RD BLKs (Mem) 0|SHARED POOL MISs 0|
|EXECs  1|CPU S 0.000000|CLOCK S 0.000807|ROWs  0|PHY RD BLKs  0|CON RD BLKs (Mem)  0|CUR RD BLKs (Mem) 0|SHARED POOL MISs 0|
|FETCHs 1|CPU S 0.000000|CLOCK S 0.002195|ROWs 14|PHY RD BLKs 10|CON RD BLKs (Mem) 51|CUR RD BLKs (Mem) 0|SHARED POOL MISs 0|

Cursor 12   Ver 1   Parse at 0.000000  Similar Cnt 1
|PARSEs 1|CPU S 0.000000|CLOCK S 0.000029|ROWs  0|PHY RD BLKs  0|CON RD BLKs (Mem)  0|CUR RD BLKs (Mem) 0|SHARED POOL MISs 0|
|EXECs  1|CPU S 0.000000|CLOCK S 0.000807|ROWs  0|PHY RD BLKs  0|CON RD BLKs (Mem)  0|CUR RD BLKs (Mem) 0|SHARED POOL MISs 0|
|FETCHs 1|CPU S 0.000000|CLOCK S 0.002195|ROWs 14|PHY RD BLKs 10|CON RD BLKs (Mem) 51|CUR RD BLKs (Mem) 0|SHARED POOL MISs 0|
  CLOCK S 98.67%
|++++++++++++++++++++|

SELECT C1 , SUBSTR(C2,1,20) C2  FROM T7 WHERE   
  EXISTS ( 
    SELECT 
      1 
    FROM 
      T8 
    WHERE 
      T8.C1=T7.C1)
  AND T7.C1 BETWEEN :1 AND :2

      (Rows 14)   FILTER  (cr=51 pr=10 pw=0 time=2170 us)
      (Rows 14)    NESTED LOOPS  (cr=51 pr=10 pw=0 time=2137 us)
      (Rows 14)     SORT UNIQUE (cr=7 pr=6 pw=0 time=984 us)
      (Rows 14)      TABLE ACCESS FULL T8 (cr=7 pr=6 pw=0 time=900 us)
      (Rows 14)     TABLE ACCESS BY INDEX ROWID T7 (cr=44 pr=4 pw=0 time=1131 us)
      (Rows 14)      INDEX UNIQUE SCAN SYS_C0020535 (cr=30 pr=3 pw=0 time=820 us)

Bind Variables:BINDS #12:  -0.000004
   Bind#0
    oacdty=02 mxl=22(21) mxlc=00 mal=00 scl=00 pre=00
    oacflg=00 fl2=1000010 frm=00 csi=178 siz=48 off=0
    kxsbbbfp=151423d0  bln=22  avl=02  flg=05
    value=1
   Bind#1
    oacdty=02 mxl=22(21) mxlc=00 mal=00 scl=00 pre=00
    oacflg=00 fl2=1000010 frm=00 csi=178 siz=0 off=24
    kxsbbbfp=151423e8  bln=22  avl=03  flg=01
    value=81000

Of course, if the STATISTICS_LEVEL parameter is set to ALL, or a GATHER_PLAN_STATISTICS hint is provided, the following will retrieve the actual execution plan for the test query, if executed immediately after the test query:

SELECT
  *
FROM
  TABLE(DBMS_XPLAN.DISPLAY_CURSOR(NULL,NULL,'ALLSTATS LAST'))

The output of the above for this SQL statement follows:

SQL_ID  bkhdgq864dq04, child number 0
-------------------------------------
SELECT C1 , SUBSTR(C2,1,20) C2  FROM T7 WHERE       EXISTS (       SELECT         1       FROM         T8       WHERE        
T8.C1=T7.C1)    AND T7.C1 BETWEEN :1 AND :2

Plan hash value: 1996673128

--------------------------------------------------------------------------------------------------------------------------------------------
| Id  | Operation                     | Name         | Starts | E-Rows | A-Rows |   A-Time   | Buffers | Reads  |  OMem |  1Mem | Used-Mem |
--------------------------------------------------------------------------------------------------------------------------------------------
|*  1 |  FILTER                       |              |      1 |        |     14 |00:00:00.01 |      51 |     10 |       |       |          |
|   2 |   NESTED LOOPS                |              |      1 |      1 |     14 |00:00:00.01 |      51 |     10 |       |       |          |
|   3 |    SORT UNIQUE                |              |      1 |      1 |     14 |00:00:00.01 |       7 |      6 |  9216 |  9216 | 8192  (0)|
|*  4 |     TABLE ACCESS FULL         | T8           |      1 |      1 |     14 |00:00:00.01 |       7 |      6 |       |       |          |
|   5 |    TABLE ACCESS BY INDEX ROWID| T7           |     14 |      1 |     14 |00:00:00.01 |      44 |      4 |       |       |          |
|*  6 |     INDEX UNIQUE SCAN         | SYS_C0020535 |     14 |      1 |     14 |00:00:00.01 |      30 |      3 |       |       |          |
--------------------------------------------------------------------------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------
   1 - filter(:1<=:2)
   4 - filter(("T8"."C1">=:1 AND "T8"."C1"<=:2))
   6 - access("T8"."C1"="T7"."C1")
       filter(("T7"."C1"<=:2 AND "T7"."C1">=:1))

The raw 10046 Extended SQL trace offers several advantages over the DBMS_XPLAN output if the P1, P2, and P3 values from the wait events are examined closely:

nam='db file scattered read' ela= 213 file#=4 block#=1779172 blocks=5 obj#=114178 tim=768612046

In the above, a multi-block read from disk requiring 0.000213 seconds of absolute file number 4, starting at block 1779172, and extending for 5 blocks was performed.  The blocks belong to object ID 114178 and happened at the trace file’s sequential time of 768612046, which may be referenced to the sequential time of other lines in the trace file.

Much more information about 10046 extended SQL traces is provided in the the chapters I co-wrote for the “Expert Oracle Practices: Oracle Database Administration from the Oak Table” book.


Actions

Information

10 responses

27 01 2011
walid

Hi,
I have generated 10046 trace.
But when I checked the wait event for a query, I find abj#=0.
*** 2011-01-25 00:39:47.711
WAIT #30: nam=’db file sequential read’ ela= 9292 file#=2 block#=329387 blocks=1 obj#=0 tim=23252790781437
WAIT #30: nam=’db file sequential read’ ela= 8916 file#=2 block#=329388 blocks=1 obj#=0 tim=23252790790688
WAIT #30: nam=’db file sequential read’ ela= 8318 file#=2 block#=329389 blocks=1 obj#=0 tim=23252790810226
WAIT #30: nam=’db file sequential read’ ela= 6725 file#=2 block#=329390 blocks=1 obj#=0 tim=23252790818804
WAIT #30: nam=’db file sequential read’ ela= 6541 file#=2 block#=329391 blocks=1 obj#=0 tim=23252790827108

Have you an idea about obj”#=0?
Thanks,

27 01 2011
Charles Hooper

Notice that the file# is a very low number. File# 1 would be the datafile associated with the SYSTEM tablespace, so that probably provides an indication about whether or not this non-object is in a user-managed area of the database or a system managed area of the database (not the best choice of words, but close enough). File# 2 is *probably* the datafile for the undo tablespace. Riyaj Shamsudeen provides a trace file section in a comment on the following page, which also shows “file#=2″ and “obj#=0″, and he explains that obj#=0 indicates reading from undo:

http://orainternals.wordpress.com/about/

Doug Burns also hinted that same answer in a comment in this article:

http://oracledoug.com/serendipity/index.php?/archives/1321-11g-and-direct-path-reads.html

1 02 2011
Ahmed AANGOUR

Hi Charles,

I created a temporary table (named HISNEG_TT) which contains 3 indexes and ran the following statement:

insert into hisneg_tt select * from hisneg where rownum<=200000;

Here is an excerpt of the 10046 trace for this statement:

PARSING IN CURSOR #6 len=64 dep=0 uid=89 oct=2 lid=89 tim=1296558900981805 hv=3351120423 ad='1d78cb390' sqlid='0uygn4z3vw2j7'
 insert into hisneg_tt select * from hisneg where rownum<=200000
 select file_name,TABLESPACE_NAME from dba_data_files where file_id=3;
FILE_NAME
----------------------------------------------------------------------------------------------------
TABLESPACE_NAME
------------------------------
/UBIXT3/data/undotbs01.dbf
UNDOTBS1

I’m just inserting some rows into a global temporary table. I do not see the link between the temporary table and the rollback segment?
Could you please help me to understand this ?

Regards,
Ahmed

1 02 2011
Charles Hooper

Ahmed,

A small portion of your 10046 trace file was lost (that happens sometimes when less than signs are used in comments). Enough of your comment remained for me to understand your question. Page 103 of the book “Expert Oracle Database Architecture: Oracle Database Programming 9i, 10g, and 11g Techniques and Solutions, Second Edition” explains very briefly why undo is still written for temp tables:

http://books.google.com/books?id=HPJDlGmecwcC&pg=PA103

More information is found in the same book around page 331.

1 02 2011
Ahmed AANGOUR
PARSE #6:c=3000,e=3175,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=1,plh=2102008689,tim=1296558900981804
WAIT #6: nam='db file sequential read' ela= 129 file#=3 block#=320 blocks=1 obj#=0 tim=1296558900982272
WAIT #6: nam='db file sequential read' ela= 82 file#=3 block#=10028 blocks=1 obj#=0 tim=1296558900982440
WAIT #6: nam='asynch descriptor resize' ela= 1 outstanding #aio=0 current aio limit=134 new aio limit=166 obj#=0 tim=1296558900982490
WAIT #6: nam='asynch descriptor resize' ela= 1 outstanding #aio=0 current aio limit=166 new aio limit=150 obj#=0 tim=1296558900982568
WAIT #6: nam='asynch descriptor resize' ela= 1 outstanding #aio=0 current aio limit=150 new aio limit=182 obj#=0 tim=1296558900982700
WAIT #6: nam='asynch descriptor resize' ela= 0 outstanding #aio=0 current aio limit=182 new aio limit=166 obj#=0 tim=1296558900982747
WAIT #6: nam='asynch descriptor resize' ela= 1 outstanding #aio=0 current aio limit=166 new aio limit=198 obj#=0 tim=1296558900982869
WAIT #6: nam='asynch descriptor resize' ela= 1 outstanding #aio=0 current aio limit=198 new aio limit=182 obj#=0 tim=1296558900982916
WAIT #6: nam='Disk file operations I/O' ela= 30 FileOperation=2 fileno=52 filetype=2 obj#=118919 tim=1296558900983023
WAIT #6: nam='db file sequential read' ela= 33861 file#=52 block#=12490 blocks=1 obj#=118919 tim=1296558901016907
WAIT #6: nam='Disk file operations I/O' ela= 27 FileOperation=2 fileno=55 filetype=2 obj#=118919 tim=1296558901017007
WAIT #6: nam='db file scattered read' ela= 640 file#=52 block#=12491 blocks=5 obj#=118919 tim=1296558901017765
WAIT #6: nam='db file sequential read' ela= 139 file#=3 block#=240 blocks=1 obj#=0 tim=1296558901018839
WAIT #6: nam='db file scattered read' ela= 5712 file#=52 block#=12496 blocks=8 obj#=118919 tim=1296558901025316
WAIT #6: nam='Disk file operations I/O' ela= 24 FileOperation=2 fileno=44 filetype=2 obj#=118919 tim=1296558901028150
WAIT #6: nam='db file scattered read' ela= 17726 file#=44 block#=1638601 blocks=7 obj#=118919 tim=1296558901045902
WAIT #6: nam='db file scattered read' ela= 6292 file#=44 block#=1638608 blocks=8 obj#=118919 tim=1296558901054605
WAIT #6: nam='db file scattered read' ela= 3264 file#=44 block#=1638617 blocks=7 obj#=118919 tim=1296558901060646
WAIT #6: nam='db file scattered read' ela= 7771 file#=44 block#=1638624 blocks=8 obj#=118919 tim=1296558901070624
WAIT #6: nam='db file scattered read' ela= 6359 file#=44 block#=1638633 blocks=7 obj#=118919 tim=1296558901079753
WAIT #6: nam='db file scattered read' ela= 3538 file#=44 block#=1638640 blocks=8 obj#=118919 tim=1296558901085661
WAIT #6: nam='db file scattered read' ela= 463 file#=44 block#=1638649 blocks=7 obj#=118919 tim=1296558901088796
WAIT #6: nam='Disk file operations I/O' ela= 24 FileOperation=2 fileno=45 filetype=2 obj#=118919 tim=1296558901091702
WAIT #6: nam='db file scattered read' ela= 3352 file#=45 block#=1778304 blocks=8 obj#=118919 tim=1296558901095097
WAIT #6: nam='db file scattered read' ela= 5323 file#=45 block#=1778313 blocks=7 obj#=118919 tim=1296558901103578
WAIT #6: nam='db file scattered read' ela= 3613 file#=45 block#=1778320 blocks=8 obj#=118919 tim=1296558901109981
WAIT #6: nam='db file scattered read' ela= 3583 file#=45 block#=1778329 blocks=7 obj#=118919 tim=1296558901116539
WAIT #6: nam='db file scattered read' ela= 5434 file#=45 block#=1778336 blocks=8 obj#=118919 tim=1296558901124916
WAIT #6: nam='db file scattered read' ela= 3128 file#=45 block#=1778345 blocks=7 obj#=118919 tim=1296558901131010
WAIT #6: nam='db file scattered read' ela= 1561 file#=45 block#=1778352 blocks=8 obj#=118919 tim=1296558901135106
WAIT #6: nam='Disk file operations I/O' ela= 26 FileOperation=2 fileno=46 filetype=2 obj#=118919 tim=1296558901138859
WAIT #6: nam='db file scattered read' ela= 10658 file#=46 block#=1778306 blocks=126 obj#=118919 tim=1296558901149544
WAIT #6: nam='Disk file operations I/O' ela= 40 FileOperation=2 fileno=47 filetype=2 obj#=118919 tim=1296558901200480
WAIT #6: nam='db file scattered read' ela= 8864 file#=47 block#=1778306 blocks=126 obj#=118919 tim=1296558901209384
WAIT #6: nam='Disk file operations I/O' ela= 42 FileOperation=2 fileno=48 filetype=2 obj#=118919 tim=1296558901255836
WAIT #6: nam='db file scattered read' ela= 11523 file#=48 block#=1770114 blocks=126 obj#=118919 tim=1296558901267396
WAIT #6: nam='Disk file operations I/O' ela= 41 FileOperation=2 fileno=50 filetype=2 obj#=118919 tim=1296558901319167
WAIT #6: nam='db file scattered read' ela= 15872 file#=50 block#=1778306 blocks=126 obj#=118919 tim=1296558901335080
1 02 2011
Ahmed AANGOUR

Thanks Charles for your answer.
I made an other test which consists in updating a table from one session and querying this table from another session and it seems that blocks access on undo segments are always done in a mono-block way (db file sequential read).
Do you confirm that? Do you have an idea why multiblock access cannot be done on undo segments?

1 02 2011
Charles Hooper

Ahmed,

Interesting questions. Unfortunately, I do not think that I can answer the questions quite as well as a couple of other people. What you might need to keep in mind is that there is a chance that multiple undo blocks (scattered in the undo segments) will need to be applied to a block in the buffer cache so that the block will become consistent as of the start of the query (or the start of the session’s transaction). Jonathan Lewis explained the process well in his 10+ year old “Practical Oracle 8i” book. Search the book for consistent get. Amazon’s website allows you to view partial contents of the book, see pages 14-16.
http://www.amazon.com/Practical-Oracle8i-TM-Efficient-Databases/dp/0201715848/ref=cm_cr-mr-title#reader_0201715848

Jonathan also explained the process here:

http://jonathanlewis.wordpress.com/2009/06/12/consistent-gets-2/

http://jonathanlewis.wordpress.com/2009/06/09/quiz-night/

2 02 2011
Ahmed AANGOUR

I have Jonathan’s book at home. I will have a look into it.
Thanks Charles for the knowledge you share with us via this blog and the OTN forum.
I’m reading the latest oakTable book and I really appreciate the 2 chapters you co-wrote with Randolf Geist.
These 2 chapters have become my survival guide for troubleshooting performance issues.
The rest of the book is also very helpful.
With one chapter written by Richard Foote about indexes, this book would have been PERFECT.

Regards,
Ahmed

2 02 2011
Charles Hooper

Ahmed,

Thank you for the kind words. Randolf and I spent a great deal of time working on those two chapters, so I am very happy to hear that you have found the information to be useful. I agree that a chapter on indexes written by Richard Foote would have been a great addition to the book – I believe that I suggest it (or that Richard should write an entire book) to the lead editor. I was also hoping that Tanel Poder would write a chapter for the book.

6 03 2013
Understanding Oracle traces and plan | oraclebits

[...] (3 part series)http://hoopercharles.wordpress.com/2009/12/01/10046-extended-sql-trace-interpretation/ (2 part [...]

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 143 other followers

%d bloggers like this: