Saturday, May 26, 2012

Interpreting Raw Sql Trace File



SQL_TRACE is the main method for collecting SQL Execution information in Oracle. It records a wide range of information and statistics that can be used to tune SQL operations. The sql trace file contains a great deal of information . Each cursor that is opened after tracing has been enabled will be recorded in the trace file. 
The raw trace file mostly contains the cursor number . Eg, PARSING IN CURSOR #3 . EXECutes, FETCHes and WAITs are recorded against a cursor. The information applies to the most recently parsed statement within that cursor . Firstly,  let's have a look on "Wait Events"  . 

WAIT #6: nam='db file sequential read' ela= 8458 file#=110 block#=63682 blocks=1 obj#=221 tim=506028963546

WAIT        = An event that we waited for.
nam           = What was being waited for . The wait events here are the same as are seen in view V$SESSION_WAIT .
ela             = Elapsed time for the operation.(microseconds)
p1 = P1 for the given wait event.
p2 = P2 for the given wait event.
p3     = P3 for the given wait event.

Example No. 1 : WAIT #6: nam='db file sequential read' ela= 8458 file#=110 block#=63682 blocks=1 obj#=221 tim=506028963546 
The above line can be translated as  : Completed waiting under CURSOR no 6  for "db file sequential read" . We waited 8458 microseconds i.e. approx. 8.5 milliseconds .For a read of:  File 110, start block 63682, for 1 Oracle block of Object number 221. Timestamp was 506028963546 . 

Example no.2 : WAIT #1: nam='library cache: mutex X' ela= 814 idn=3606132107 value=3302829850624 where=4 obj#=-1 tim=995364327604
The above line can be translated as : Completed WAITing under CURSOR no 1 for "library cache: mutex X" .We waited 814 microseconds i.e. approx. 0.8 milliseconds .To get an eXclusive library cache latch with  Identifier 3606132107 value 3302829850624 location 4 . It was not associated with any particular object (obj#=-1) Timestamp 995364327604.

The trace file also show the processing of the sql statements Oracle processes SQL statements as follow :
Stage 1: Create a Cursor
Stage 2: Parse the Statement
Stage 3: Describe Results
Stage 4: Defining Output
Stage 5: Bind Any Variables
Stage 6: Execute the Statement
Stage 7: Parallelize the Statement
Stage 8: Fetch Rows of a Query Result
Stage 9: Close the Cursor
Now let's  move to another important term PARSING IN CURSOR #n . EXECutes, FETCHes and WAITs are recorded against a cursor. The information applies to the most recently parsed statement within that cursor.

PARSING IN CURSOR# : 
Cursor :  In order for Oracle to process an SQL statement, it needs to create an area of memory known as the context area; this will have the information needed to process the statement. This information includes the number of rows processed by the statement, a pointer to the parsed representa-tion of the statement (parsing an SQL statement is the process whereby information is transferred to the server, at which point the SQL statement is evaluated as being valid).

A cursor is a handle, or pointer, to the context area. Through the cursor, a PL/SQL program can control the context area and what happens to it as the statement is processed. Two important features about the cursor are
1.)  Cursors allow you to fetch and process rows returned by a SE-LECT statement, one row at a time.
2.)  A cursor is named so that it can be referenced.

Parsing : Oracle Parsing is the first step in processing of any database statement . PARSE record is accompanied by the cursor number. Let's have a look on "Parsing in Cursor" of a particular trace file .


PARSING IN CURSOR #2 len=92 dep=0 uid=0 oct=3 lid=0 tim=277930332201 hv=1039576264 ad='15d51e60' sqlid='dsz47ssyzdb68'
select p.PID,p.SPID,s.SID from v$process p,v$session s where s.paddr = p.addr and s.sid = 12
END OF STMT
PARSE#2:c=31250,e=19173,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=1,plh=836746634,tim=27930332198
EXEC #2:c=0,e=86,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=836746634,tim=77930335666
WAIT #2: nam='SQL*Net message to client' ela= 10 driver id=1413697536 #bytes=1 p3=0 obj#=116 tim=77930335778
FETCH #2:c=0,e=805,p=0,cr=0,cu=0,mis=0,r=1,dep=0,og=1,plh=836746634,tim=77930336684
WAIT #2: nam='SQL*Net message from client' ela= 363 driver id=1413697536 #bytes=1 p3=0 obj#=116 tim=77930337227
FETCH #2:c=0,e=31,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=836746634,tim=77930337421
STAT #2 id=1 cnt=1 pid=0 pos=1 obj=0 op='NESTED LOOPS  (cr=0 pr=0 pw=0 time=0 us cost=0 size=152 card=1)'
STAT #2 id=2 cnt=27 pid=1 pos=1 obj=0 op='MERGE JOIN CARTESIAN (cr=0 pr=0 pw=0 time=156 us cost=0 size=96 card=1)'
STAT #2 id=3 cnt=1 pid=2 pos=1 obj=0 op='NESTED LOOPS  (cr=0 pr=0 pw=0 time=0 us cost=0 size=39 card=1)'
STAT #2 id=4 cnt=1 pid=3 pos=1 obj=0 op='FIXED TABLE FIXED INDEX X$KSLWT (ind:1) (cr=0 pr=0 pw=0 time=0 us cost=0 size=26 card=1)'
STAT #2 id=5 cnt=1 pid=3 pos=2 obj=0 op='FIXED TABLE FIXED INDEX X$KSLED (ind:2) (cr=0 pr=0 pw=0 time=0 us cost=0 size=13 card=1)'
STAT #2 id=6 cnt=27 pid=2 pos=2 obj=0 op='BUFFER SORT (cr=0 pr=0 pw=0 time=78 us cost=0 size=57 card=1)'
STAT #2 id=7 cnt=27 pid=6 pos=1 obj=0 op='FIXED TABLE FULL X$KSUPR (cr=0 pr=0 pw=0 time=130 us cost=0 size=57 card=1)'
STAT #2 id=8 cnt=1 pid=1 pos=2 obj=0 op='FIXED TABLE FIXED INDEX X$KSUSE (ind:1) (cr=0 pr=0 pw=0 time=0 us cost=0 size=56 card=1)'
WAIT #2: nam='SQL*Net message to client' ela= 7 driver id=1413697536 #bytes=1 p3=0 obj#=116 tim=77930338248
*** 2012-05-19 15:07:22.843
WAIT #2: nam='SQL*Net message from client' ela= 38291082 driver id=1413697536 #bytes=1 p3=0 obj#=116 tim=77968629417
CLOSE #2:c=0,e=30,dep=0,type=0,tim=77968629737


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.
uid     = Schema id under which SQL was parsed.
oct = Oracle command type.
lid = Privilege user id
tim    = Timestamp.
hv = Hash id.
ad = SQLTEXT address


PARSE #3:  c=15625,  e=177782,  p=2,  cr=3,  cu=0,  mis=1,  r=0,  dep=0,  og=1,  plh=272002086,
tim=276565143470


c      = CPU time (microseconds rounded to centiseconds granularity on 9i & above)
e  = Elapsed time (centiseconds prior to 9i, microseconds thereafter)
p  = Number of physical reads.
cr  = Number of buffers retrieved for CR reads.(Consistent reads)
cu    =Number of buffers retrieved in current mode.
mis  = Cursor missed in the cache.
r  = Number of rows processed.
dep = Recursive call depth (0 = user SQL, >0 = recursive).
og = Optimizer goal: 1=All_Rows, 2=First_Rows, 3=Rule, 4=Choose


From the above Parse line it is very clear that the total time taken in parsing the statement is  0.177 sec and the no. of physical reads done are 2 .


Bind Variables :  If the SQL statement does reference bind variables, then the following  SQL statement shown in the cursor can locate a section of text associated with each bind variable. For each bind variable there are a number of attributes listed.  The following are the ones we are interested in here:


mxl      =  the maximum length - ie. the maximum number of bytes occupied by the variable. Eg. dty=2 and mxl=22 denotes a NUMBER(22) column.
scl       = the scale (for NUMBER columns)
pre      = the precision (for NUMBER columns)
value  = the value of the bind variable
dty      = the datatype.  Typical values are:
1       VARCHAR2 or NVARCHAR2
2       NUMBER
8       LONG
11     ROWID
12     DATE
23     RAW
24     LONG RAW
96     CHAR
112   CLOB or NCLOB
113   BLOB
114   BFILE


EXEC :  Execute a pre-parsed statement. At this point, Oracle has all necessary information and resources, so the statement is executed. For example
EXEC #2:c=0,e=225,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,plh=3684871272,tim=282618239403


Fetch : Fetch rows from a cursor . For example
FETCH #4:c=0,e=8864,p=1,cr=26,cu=0,mis=0,r=1,dep=0,og=1,plh=3564694750,tim=282618267037


STAT :  Lines report explain plan statistics for the numbered [CURSOR]. These let us know the 'run time' explain plan. For example
STAT #1 id=1 cnt=7 pid=0 pos=1 obj=0 op='SORT ORDER BY (cr=0 pr=0 pw=0 time=0 us cost=2 size=2128 card=1)'

id       = Line of the explain plan which the row count applies to (starts at line 1).  This is effectively the row source row count for all row sources in the execution tree
cnt =  Number of rows for this row source.
pid  =  Parent id of this row source.
pos   =  Position in explain plan.
obj     =  Object id of row source (if this is a base object).
op='...'   The row source access operation


XCTEND  A transaction end marker. For example  XCTEND rlbk=0, rd_only=1, tim=282636050491
rlbk           =1   if a rollback was performed, 0 if no rollback (commit).
rd_only      =1   if transaction was read only, 0 if changes occurred.


CLOSE  cursor is closed .for example CLOSE #4:c=0,e=32,dep=0,type=0,tim=282636050688
c            = CPU time (microseconds rounded to centiseconds granularity on 9i and above)
e           = Elapsed time (centiseconds prior to 9i, microseconds thereafter)
dep       = Recursive depth of the cursor
type     = Type of close operation

Note : Timestamp are used to determine the time between any 2 operations.
Reference : Metalink [ID 39817.1]



Enjoy    :-) 



Saturday, May 19, 2012

Tracing using Event 10046


Event 10046 is an well known feature within the Oracle database that generates detailed information on how a statement is parsed, what the values of bind variables are, and what wait events occurred during a particular session . The 10046 event allows us to track, at a very fine level, the execution of a given set of SQL statements. The 10046 event can be set at both the session level (for tracing of a specific session) or at a database level. It can be set either via a parameter file setting, or it can be set dynamically for the database, for our session or even for another session. 

Event 10046 is quite helpful for DBA to determine exactly, why the database is performing in a certain way, by documenting how a statement is parsed and noting what wait events occured during the statement execution. 

Most of us are well known familiar with Oracle's sql_trace facility, which emits performance information about Oracle parse, execute, fetch, commit, and rollback database calls. Using sql_trace is actually the equivalent of using event 10046 set at level 1. 

The event 10046 is internally described as:

SQL> set serveroutput on 
SQL> begin  
   dbms_output.put_line (SQLERRM (-10046)) ; 
end ; 
/

Event 10046 level 
There are five different levels . The Levels are  as
1.) Level 1  is the default. This level traces all activities until the trace session is stopped. This event enable the standard SQL_TRACE facility (same as SQL_TRACE=TRUE).

2.)  Level 4  provides level 1 tracing and displays the entered value for all bind variables. Bind variables are the values that the user enters. The code displays these bind variables as: b1, etc. When level 4 is activated, the substituted value for the bind variable is displayed in the trace file.

3.) Level 8  provides level 1 tracing and displays a list of all database wait events. Database wait events list the reasons if the elapsed time is greater than the CPU time in the tkprof report.

4.) Level 12  provides level 1 tracing in addition to both bind variable substitution and database wait events.

5.) Level 16  added in 11g to generate STAT line dumps for each execution. STAT dumping has been amended in 11g so that they are not aggregated across all executions but are dumped after execution.

How to enable the event 10046 
The following  steps are required to enable event 10046

1.) Set timed statistics to TRUE
 SQL> alter session set timed_statistics=true ; 
Session altered.

2.) set statistics level
SQL> alter session set statistics_level=all ; 
Session altered.

3.) Set max_dump_file_size to UNLIMITED 
SQL> alter session set max_dump_file_size=unlimited ; 
Session altered.

4.) Enable the event 
SQL> alter session set events '10046 trace name context forever, level 12' ; 

We can check the generated trace file in the directory specified in the parameter user_dump_dest
SQL> show parameter user_dump_dest  

Stop Tracing   
If the session is not exited then the trace can be disabled using :
SQL> alter session set events '10046 trace name context off' ; 

Enabling  tracing in other sessions
We can enable tracing in other session using the oradebug utility .Here the steps to enable the tracing in another session.

1.) Find the SPID of the session which we want to trace 
SQL> select p.PID,p.SPID,s.SID   from v$process p,v$session s
where s.paddr = p.addr  and s.sid = &SESSION_ID ;   
or 
SQL> select spid from v$process 
where addr=(select paddr from v$session where sid=<enter the SID>); 
We can identify the session_id by using the v$session view using the following attribute  sid, serial#, username, osuser, machine ,server ,terminal , program .

2.) Once the OS process id for the process has been determined then login to SQL*Plus as a dba and execute the following 
c:\> sqlplus / as sysdba
SQL> oradebug setospid <SPID> ;    or
SQL> oradebug setorapid <PID> ; 
SQL> oradebug unlimit ; 
SQL> oradebug event 10046 trace name context forever, level 8 ; 


Turn off tracing 
SQL> oradebug event 10046 trace name context off ; 

There are various way of enable, disable and vary the contents of this trace . Here are the some way to enable and disable the tracing .
SQL> EXEC DBMS_SYSTEM.set_ev(si=>123, se=>1234, ev=>10046, le=>12, nm=>' ');   <--enable
SQL> EXEC DBMS_SYSTEM.set_ev(si=>123, se=>1234, ev=>10046, le=>0, nm=>' ');   <--disable

In next post , i will try to cover the topic " Interpreting Trace File" .


Enjoy         :-) 


Thursday, May 10, 2012

Difference between LGWR SYNC and ASYNC in Oracle DataGuard


Oracle Data Guard redo log transport offers synchronous log transport mode (LogXptMode = 'SYNC') or asynchronous log transport mode (LogXptMode = 'ASYNC').  The difference is all about when the COMMIT happens . 

LogXptMode = ('SYNC'):  As the name implies, SYNC mode synchronizes the primary with the standby database and all DML on the primary server will NOT be committed until the logs have been successfully transported to the standby servers.  The synchronous log transport mode is required for the Maximum Protection and Maximum Availability data protection modes.
LogXptMode = ('ASYNC'): Conversely, asynchronous mode (ASYNC) allows updates (DML) to be committed on the primary server before the log file arrives on the standby servers.  The asynchronous log transport mode is required for the Maximum Performance data protection mode.

There is a very good post witten by "Shawn Kelley" related to Sync and Async in dataguard .

LGWR is an attribute of the LOG_ARCHIVE_DEST_n parameter which is used to specify the network transmission mode. Specifying the SYNC attribute (which is the default), tells the LGWR process to synchronously archive to the local online redo log files at the same time it transmits redo data to archival destinations. Specifically, the SYNC atrribute performs all network I/O synchornously in conjunction with each write operation to the online redo log file. Transactions are not committed on the primary database until the redo data necessary to recover the transactions is received by the destination.

The ASYNC attribute perfoms all network I/O asynchronously and control is returned to the executing application or user immediately. When this attribute is specified, the LGWR process archives to the local online redo log file and submits the network I/O request to the network server (LNSn process for that destination, and the LGWR process continues processing the next request without waiting for the network I/O to complete.

What happens if the network between the Primary and Standby [database] is lost with LGWR SYNC and ASYNC ? or What happens if the standby database is shutdown with LGWR SYNC and ASYNC?
This is dependent upon the database mode we have set. If we have set Maximum Protection, we have chosen a configuration that guarantees that no data loss will occur. We have set this up by specifying the LWGR, SYNC, and AFFIRM attributes of the LOG_ARCHIVE_DEST_n parameter for at least one standby database. This mode provides the highest level of data protection possible and to achieve this the redo data needed to recover each transaction must be written to both the local online redo log and the standby redo log on at least one standby database before the transaction commits. To ensure data loss cannot occur, the primary database shuts down if a fault (such as the network going down) prevents it from writing its redo stream to at least one remote standby redo log.

If  we have set the Maximum Availability mode, we have chosen a configuration that provides the highest level of data protection that is possible without compromising the availablity of the primary database. Like the maximum database does not shut down if a fault prevents it from writing its redo stream to a remote standby redo log. Instead, the primary database operates in maximum performance mode until the fault is corrected and all gaps in redo log files are resolved. When all gaps are resolved, the primary database automatically resumes operating in maximum availabitly mode. This guarantees that no data loss will occur if the primary database fails, but only if a second fault does not complete set of redo data being sent from the primary database to at least one standby database.

If we have set the Maximum Performance mode (the default), we have chosen a mode that provides the highest level of data protection that is possible without affecting the performance of the primary database. This is accomplished by allowing a transaction to commit as soon as the redo data needed to recover the transaction is written to the local online redo log. The primary database's redo data stream is also written to at least one standby database, bu that the redo stream is written asynchronously with respect to the commitment of the transactions that create the redo data.

The maximum performance mode enables us to either set the LGWR and AYSNC attributes, or set the ARCH attribute on the LOG_ARCHIVE_DEST_n parameter for the standby database destination. If the primary database fails, we can reduce the amount of data that is not received on the standby destination by setting the LGWR and ASYNC attributes.

If LGWR SYNC or ASYNC is deployed, what process(es) bring(s) the standby database back into sync with the primary [database] if the network is lost and is then restored? How does it do it?

Again, this is dependent upon the mode we have chosen for our database. The LGWR process (and possibly the LNSn process if we have multiple standby databases) is responsible for closing the gap.

My biggest question is, when the network to the standby is lost with SYNC or ASYNC, where is the information queued and how is it retransmitted once the network has been re-established?
This implies that our database has been set to either maximum availability or maximum performance mode. We cannot use the ASYNC attribute with maximum protection mode. The information is queued in the local online redo log and the LGWR (and the LNSn) process will transmit the data to the standby database's online redo log file to close the gap once the network connectivity has been re-established

Gap recovery is handled through the polling mechanism. For physical and logical standby databases, Oracle Change Data Capture, and Oracle Streams, Data Guard performs gap detection and resolution by automatically retrieving missing archived redo log files from the primary database. No extra configuration settings are required to poll the standby database(s) to detect any gaps or to resolve the gaps.

The important consideration here is that automatic gap recovery is contigent upon the availablity of the primary database. If the primary database is not available and we have a configuration with mulitple physical standby databases, we can set up additional initialization parameters so that the Redo Apply can resolve archive gaps from another standby database.

It is possible to manually determine if a gap exists and to resolve those archive gaps. To manually determine if a gap exists, query the V$ARCHIVE_GAP view on our physical standby database. If a gap is found, we will then need to locate the archived log files on our primary database, copy them to our standby database, and register them.


Enjoy       :)