In the previous SQL_TRACE blog, we discussed how to trace Oracle sessions and how to gather information using “trace” files.

This blog will help you to understand and interpret 10046 raw trace data.

Start session tracing

First of all, let’s start 10046 trace at the session level:

SQL> ALTER SESSION SET tracefile_identifier = '10046';

Session altered.

SQL> ALTER SESSION SET timed_statistics = true;

Session altered.

SQL> ALTER SESSION SET statistics_level = all;

Session altered.

SQL> ALTER SESSION SET max_dump_file_size = unlimited;

Session altered.

SQL> ALTER SESSION SET events '10046 trace name context forever,level 12';

Session altered.

Execute the following statements to be traced:

SQL> SELECT COUNT(*) FROM 
  2  (
  3     SELECT a.synonym_name, b.table_name, a.owner
  4       FROM dba_synonyms a, dba_tables b
  5      WHERE a.synonym_name = b.table_name
  6  ) ; 

COUNT(*)
--------
84

Note: row count(*) may be different in your database.

Disable the session trace and exit:

SQL> ALTER SESSION SET events '10046 trace name context off';

Session altered.

SQL> exit

Change to your user_dump_dest directory to find the raw trace output file.

You can query where is your user_dump_dest directory located by executing the following statement:

SQL> SELECT name, value FROM v$parameter WHERE name = 'user_dump_dest' ;

NAME                 VALUE
-------------------- ----------
user_dump_dest       /u01/trace

List directory contents to find the raw trace file named with “_10046.trc” suffix.

In this example “db01″ is the database name and “3732” is the ID of the operating system process executing our database session:

db01_ora_3732_10046.trc

Now open the file. There are a lot of lines but we will focus just on those related to our SQL statement:

You will find an output similar to this:

PARSING IN CURSOR #140584383934648 len=138 dep=0 uid=0 oct=3 lid=0 
tim=1699354797 hv=4163043499 ad='a334bf78' sqlid='00gy33bw2605b'

select count(*) from
(
select a.synonym_name,b.table_name,a.owner
from dba_synonyms a, dba_tables b
where a.synonym_name = b.table_name
)
END OF STMT

And the interpretation is the following:

CURSOR number is #140584383934648

"len" is the length of the current SQL statement. 
(in this case 138 characters)

"dep" is the recursive depth of the cursor. 
(level "0" corresponds to the root operation).

"uid" is the schema ID under which SQL was parsed. 
(in this case "0" is "sys" user ID). 

"oct" is Oracle command type. 
(in this case "3" corresponds to a "select" statement).

"lid" is the Oracle privilege user id. 
(in this case "0" is "sys" user ID).

"tim" is the value in V$TIMER when the line was executed.

"hv" is the corresponding hash id for this statement.

"ad" is the library cache address of the cursor as is shown in V$SQL.

"sqlid" is the SQL identifier of a cached cursor as is shown in V$SQLTEXT.

Now we will take a closer look to operations being performed during this execution.
Let’s take a couple of line as example:

EXEC #140584383934648:c=0,e=276,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,
plh=4001053730,tim=1699355348

Let’s do some interpretation about the example shown above:

EXEC means that a pre-parsed statement was executed.

"c" is CPU time measured in microseconds.

"e" elapsed time measured in microseconds.

"p" is the number of physical reads.

"cr" is the number of buffers retrieved for CR reads.

"cu" is the number of buffers retrieved in current mode.

"mis" cursor missed in the cache.

"r" is the number of rows processed.

"dep" is the recursive call depth (0 = user SQL, >0 = recursive).

"og" Optimizer goal: 1=All_Rows, 2=First_Rows, 3=Rule, 4=Choose.
(in this example "All_Rows" option was performed).

"plh" This value provides the execution plan hash value.

"tim" is the timestamp when the statement was executed.

The following trace line details a wait event (one of many registered in trace file):

WAIT #140584383934648: nam='db file sequential read' 
ela= 28671 file#=1 block#=1184 blocks=1 obj#=103 tim=1699388527

Let’s try to understand this record:

WAIT is an event that we waited for.

"nam" is *what* was being waited for. 
The wait events here are the same shown in V$SESSION_WAIT view.

"ela" is the elapsed time for the current operation in microseconds.
(1 second = 1,000,000 micro-seconds)

"file#" is file ID as shown in V$DATAFILE view.

"block#" is the starting block ID.

"blocks" represents how many blocks were involved.

"obj#" is the object ID of row source. 
(-1 if it was not associated with any particular object).

"tim" is the timestamp of the statement execution.

And this is the explanation:

Completed WAITing under CURSOR 140584383934648 for "db file sequential read". 

We wait 28671 microseconds (aprox. 29 milliseconds) for a read of file #1. 

Start block was #1184 for 1 Oracle block of object number #103. 

Operation was done at timestamp 1699388527.

The 10046 trace file contains a great deal of information and requires some level of expertise to understand it but you can use this blog post as an initial reference guide.

 

 

 

 

 

 

 

 

 

 

 

 

Comment