One Can Succeed at Almost Anything For Which He Has Enthusiasm...

Wednesday, July 11, 2012

Control File Parallel Read & Write wait Event

A control file contains information about the associated database that is required for access by an instance, both at startup and during normal operation . It is the Oracle control file(s) that records information about the consistency of a database's physical structures and operational statuses . The database state changes through activities such as adding data files, altering the size or location of datafiles, redo being generated, archive logs being created, backups being taken, SCN numbers changing, or checkpoints being taken.

Why Control File Waits Occur ?
Control File Waits Occur due to the following reason .
1.) This wait occurs when a server process is updating all copies of the controlfile i.e, the session is writing physical blocks to all control files at same time .
2.) The session commits a transaction to a controlfile
3.) Changing a generic entry in the controlfile, the new value is being written to all controlfiles
4.) Controlfile resides on such a disk which is heavily used i.e, facing lots of i/o's .

We can check the wait experience by a session using v$session_wait views as
SQL>select event, wait_time, p1, p2, p3 frpm v$session_wait wher event like '%control%';
Here wait_time is the elapsed time for reads or writes.

Possible steps to reduce this wait :
1.) Reduce the number of controlfile copies to the minimum that ensures that not all copies can be lost at the same time.
2.) Move the controlfile copies to less saturated storage locations.
3.) Reduce the frequent log switches . To find the optimal time and size for log switch check this post .

As far my experience , Control file access is governed by activities such as redo logfile switching and checkpointing . Therefore it can only be influenced indirectly by tuning . It rarely occurs in my report and it get solved automatically when i check the other wait metric especially "log sync wait" and others waits .

Enjoy :-)

Friday, June 29, 2012

Configure OEM in Oracle 11gR2 on Window

The Oracle Enterprise Manager, (OEM) is the standard monitoring tool for Oracle databases . The OEM allows the DBA to easily manage every aspect of the database, even non-traditional tasks like applying patches and scheduling jobs . Sometimes OEM doesn't work due to some issue and i face such a issues while re-configuring it and follow this method . Let's have a look on this below issue . All the steps are same for window or linux/unix platform . (just change path and variable where required)

C:\>set ORACLE_SID=orcl

C:\>emca -deconfig dbcontrol db -repos drop

STARTED EMCA at Jun 28, 2012 10:52:27 AM

EM Configuration Assistant, Version 11.2.0.0.2 Production

Enter the following information:

Database SID: orcl

Listener port number: 1521

Password for SYS user:

Password for SYS user: xxxx

Do you wish to continue? [yes(Y)/no(N)]: y

Jun 28, 2012 10:52:53 AM oracle.sysman.emcp.EMConfig perform

INFO: This operation is being logged at C:\app\Neerajs\cfgtoollogs\emca\orcl\emca_2012_06_28_10_52_24.log.

Jun 28, 2012 10:52:55 AM oracle.sysman.emcp.EMDBPreConfig performDeconfiguration

WARNING: EM is not configured for this database. No EM-specific actions can be performed.

Jun 28, 2012 10:52:56 AM oracle.sysman.emcp.ParamsManager checkListenerStatusForDBControl

WARNING: Error initializing SQL connection. SQL operations cannot be performed

Jun 28, 2012 10:52:56 AM oracle.sysman.emcp.EMReposConfig invoke

INFO: Dropping the EM repository (this may take a while) ...

Jun 28, 2012 11:03:43 AM oracle.sysman.emcp.EMReposConfig invoke

INFO: Repository successfully dropped

Enterprise Manager configuration completed successfully

FINISHED EMCA at Jun 28, 2012 11:03:44 AM

Now, creating OEM

C:\>sqlplus sys/xxxx@orcl as sysdba

SQL*Plus: Release 11.2.0.1.0 Production on Thu Jun 28 11:07:03 2012

Connected to:

Oracle Database 11g Enterprise Edition Release 11.2.0.1.0 - Production

With the Partitioning, OLAP, Data Mining and Real Application Testing options

SQL> drop user SYSMAN cascade ;

drop user SYSMAN cascade

ERROR at line 1:

ORA-01918: user 'SYSMAN' does not exist

SQL> drop user MGMT_VIEW ;

drop user MGMT_VIEW

ERROR at line 1:

ORA-01918: user 'MGMT_VIEW' does not exist

SQL> drop role MGMT_USER ;

drop role MGMT_USER

ERROR at line 1:

ORA-01919: role 'MGMT_USER' does not exist

Drop all the dependent synonyms of "sysman"

SQL> spool drop_synonym.sql

SQL> SELECT 'drop public synonym ' || synonym_name || ';' FROM dba_synonyms WHERE table_owner = 'SYSMAN';

no rows selected

If we have got any output here , then run the below script .

SQL> @drop_synonym.sql

Let's Configure EM

C:\>set ORACLE_SID=orcl

C:\>set ORACLE_HOME=C:\app\Neerajs\product\11.2.0\dbhome_1

C:\>emca -config dbcontrol db -repos create

STARTED EMCA at Jun 28, 2012 11:08:59 AM

EM Configuration Assistant, Version 11.2.0.0.2 Production

Enter the following information:

Database SID: orcl

Exception in thread "main" oracle.sysman.emcp.exception.DatabaseUnavailableException: Database instance unavailable.

at oracle.sysman.emcp.DatabaseChecks.throwDBUnavailableException(DatabaseChecks.java:151)

at oracle.sysman.emcp.DatabaseChecks.checkDbAvailabilityImpl(DatabaseChecks.java:144)

at oracle.sysman.emcp.DatabaseChecks.checkDbAvailability(DatabaseChecks.java:163)

at oracle.sysman.emcp.DatabaseChecks.getDbServiceName(DatabaseChecks.java:582)

at oracle.sysman.emcp.EMConfigAssistant.performConfiguration(EMConfigAssistant.java:1272)

at oracle.sysman.emcp.EMConfigAssistant.statusMain(EMConfigAssistant.java:574)

at oracle.sysman.emcp.EMConfigAssistant.main(EMConfigAssistant.java:522)

and the emca log contains the below details :

oracle.sysman.emcp.util.GeneralUtil initSQLEngineLoacly

CONFIG: ORA-01031: insufficient privileges

oracle.sysman.assistants.util.sqlEngine.SQLFatalErrorException: ORA-01031: insufficient privileges

at oracle.sysman.assistants.util.sqlEngine.SQLEngine.executeImpl(SQLEngine.java:1655)

at oracle.sysman.assistants.util.sqlEngine.SQLEngine.connect(SQLEngine.java:978)

at oracle.sysman.emcp.util.GeneralUtil.initSQLEngineLoacly(GeneralUtil.java:445)

at oracle.sysman.emcp.util.GeneralUtil.initSQLEngine(GeneralUtil.java:637)

at oracle.sysman.emcp.DatabaseChecks.checkDbAvailabilityImpl(DatabaseChecks.java:118)

From the above logs, we find two hints i.e, database instance is down and ORA-01031 . We search on meta-link and find some useful information . So, some possible reasons may be :

1.) Database may not be up.

2.) Database is started setting environment variable ORACLE_HOME with trailing '/'. Reset ORACLE_HOME and bounce the database.

3.) Confirm that the database is up. Connect to the database via sql*plus and do:-

C:\>sqlplus sys/xxxx@orcl as sysdba

SQL*Plus: Release 11.2.0.1.0 Production on Thu Jun 28 17:25:00 2012

Connected to:

Oracle Database 11g Enterprise Edition Release 11.2.0.1.0 - Production

With the Partitioning, OLAP, Data Mining and Real Application Testing options

SQL> select instance_name,status,version from v$instance;

INSTANCE_NAME STATUS VERSION

---------------- ------------ -----------------

orcl OPEN 11.2.0.1.0

4.) Confirm whether the $ORACLE_HOME environmental variable is correct. This involves comparing the current ORACLE_HOME environmental setting, with the one that was set the last time the database was started.

a.) To check the current ORACLE_HOME :-

set ORACLE_HOME (windows)

b.) To check the $ORACLE_HOME which was set at the time when the database was last started .Connect to sqlplus as SYS as SYSDBA and issue the following:-

SQL> var OHM varchar2(100);

SQL> EXEC dbms_system.get_env('ORACLE_HOME', :OHM) ;

PL/SQL procedure successfully completed.

SQL> PRINT OHM

OHM

<Oracle_Home which was set at the time that the database was last started will be returned here>

c.) If the ORACLE_HOME was set wrongly at the time that the database was started (as determined by above steps), then the database will need to be shut down and re-started. To shut the database down, it will be necessary to set the 'wrong' ORACLE_HOME (the one which is returned in the OHM output). After the database has been successfully shut down, then the correct ORACLE_HOME should be set, and the database can be re-started.

5.) Confirm whether it's possible to connect to the database as the SYSDBA user remotely, using sqlplus. As part of the repository creation/drop process, the SYS user needs to be able to connect as SYSDBA . The ORA-01031: insufficient privileges error is returned when the SYS user is unable to connect as SYSDBA. To test this outside of dbconsole, test a sqlplus remote connection (one which connects via a tnsnames.ora alias) as sysdba. eg:-

$ORACLE_HOME/bin>sqlplus sys/<password>@<alias> as sysdba

If the above returns the ora-1031 error, check the following :-

a.) Check whether the REMOTE_LOGIN_PASSWORDFILE initialization parameter is set correctly in the database. For the purposes of configuring dbconsole, it must be set to 'EXCLUSIVE'. This value can be checked by logging into the database via sql*plus and typing "show parameter remote".

SQL> show parameter remote

NAME TYPE VALUE

---------------------------- --------- --------------

remote_login_passwordfile string EXCLUSIVE

If this parameter is not set to 'EXCLUSIVE', the following command can be run .

SQL>alter system set remote_login_passwordfile=EXCLUSIVE scope=spfile;

b.) For dbconsole 11.2.0.1 and 11.2.0.2 check whether the %ORACLE_HOME%/network/admin/sqlnet.ora (or %TNS_ADMIN%/sqlnet.ora) contains the entry .

SQLNET.AUTHENTICATION_SERVICES = (NTS)

In my case the value of SQLNET.AUTHENTICATION_SERVICES is NONE . So, i changed to NTS and finally able to configure the OEM . The rest are as

C:\>set ORACLE_SID=orcl

C:\>set ORACLE_HOME=C:\app\Neerajs\product\11.2.0\dbhome_1

C:\>emca -config dbcontrol db -repos create -SID ORCL -PORT 1521 -ORACLE_HOME C:\app\Neerajs\product\11.2.0\dbhome_1

STARTED EMCA at Jun 28, 2012 11:51:08 AM

EM Configuration Assistant, Version 11.2.0.0.2 Production

Enter the following information:

Listener ORACLE_HOME [ C:\app\Neerajs\product\11.2.0\dbhome_1 ]: C:\app\Neerajs\product\11.2.0\dbhome_1

Password for SYS user:

Password for DBSNMP user:

Password for SYSMAN user:

Email address for notifications (optional):

Outgoing Mail (SMTP) server for notifications (optional):

-----------------------------------------------------------------

You have specified the following settings

Database ORACLE_HOME ................ C:\app\Neerajs\product\11.2.0\dbhome_1

Local hostname ................ ramtech-199

Listener ORACLE_HOME ................ C:\app\Neerajs\product\11.2.0\dbhome_1

Listener port number ................ 1521

Database SID ................ ORCL

Email address for notifications ...............

Outgoing Mail (SMTP) server for notifications ...............

-----------------------------------------------------------------

Do you wish to continue? [yes(Y)/no(N)]: y

Jun 28, 2012 11:51:48 AM oracle.sysman.emcp.EMConfig perform

INFO: This operation is being logged at C:\app\Neerajs\cfgtoollogs\emca\orcl\emca_2012_06_28_11_51_07.log.

Jun 28, 2012 11:51:51 AM oracle.sysman.emcp.EMReposConfig createRepository

INFO: Creating the EM repository (this may take a while) ...

Jun 28, 2012 12:55:16 PM oracle.sysman.emcp.EMReposConfig invoke

INFO: Repository successfully created

Jun 28, 2012 12:55:53 PM oracle.sysman.emcp.EMReposConfig uploadConfigDataToRepository

INFO: Uploading configuration data to EM repository (this may take a while) ...

Jun 28, 2012 1:07:37 PM oracle.sysman.emcp.EMReposConfig invoke

INFO: Uploaded configuration data successfully

Jun 28, 2012 1:07:58 PM oracle.sysman.emcp.util.DBControlUtil configureSoftwareLib

INFO: Software library configured successfully.

Jun 28, 2012 1:07:58 PM oracle.sysman.emcp.EMDBPostConfig configureSoftwareLibrary

INFO: Deploying Provisioning archives ...

Jun 28, 2012 1:10:46 PM oracle.sysman.emcp.EMDBPostConfig configureSoftwareLibrary

INFO: Provisioning archives deployed successfully.

Jun 28, 2012 1:10:47 PM oracle.sysman.emcp.util.DBControlUtil secureDBConsole

INFO: Securing Database Control (this may take a while) ...

Jun 28, 2012 1:11:26 PM oracle.sysman.emcp.util.DBControlUtil secureDBConsole

INFO: Database Control secured successfully.

Jun 28, 2012 1:11:27 PM oracle.sysman.emcp.util.DBControlUtil startOMS

INFO: Starting Database Control (this may take a while) ...

Jun 28, 2012 1:14:55 PM oracle.sysman.emcp.EMDBPostConfig performConfiguration

INFO: Database Control started successfully

Jun 28, 2012 1:15:05 PM oracle.sysman.emcp.EMDBPostConfig performConfiguration

INFO: >>>>>>>>>>> The Database Control URL is https://ramtech-199:5500/em <<<<<<<<<<<

Jun 28, 2012 1:15:48 PM oracle.sysman.emcp.EMDBPostConfig invoke

WARNING:

************************ WARNING ************************

Management Repository has been placed in secure mode wherein Enterprise Manager data will be encrypted. The encryption key has been placed in the file: C:/app/neerajs/product/11.2.0/dbhome_1/ramtech-199_orcl/sysman/config

/emkey.ora. Please ensure this file is backed up as the encrypted data will become unusable if this file is lost.

***********************************************************

Enterprise Manager configuration completed successfully

FINISHED EMCA at Jun 28, 2012 1:15:48 PM

Enjoy :-)

Tuesday, May 29, 2012

Interested Transaction List ( ITL ) in Oracle

Few days back, I received an e-mail from a reader , who is having doubt on locking mechanism i.e, related to ITL . This post will give some good concept about the ITL . Let's start from the beginning i.e, from the transaction .

Transaction : A transaction starts when an update to data such as insert, update or delete occurs (or the intention to do so, e.g. SELECT FOR UPDATE) and ends when the session issues a commit or rollback. Like everything else, a specific transaction should have a name or an identifier to differentiate it from another one of the same type. Each transaction is given a transaction ID.

Locks : In multi-user systems, many users may update the same information at the same time. Locking allows only one user to update a particular data at a time , another person cannot modify the same data. When any user start the transaction then oracle automatically locks the data . Oracle uses a different locking method then most other databases, Oracle locking policy consists of the following :

Oracle locks data at the row level on modification only. There is no lock escalation to a block or table level, ever.
Oracle never locks data just to read it. There are no locks placed on rows of data by simple reads.
A writer of data does not block a reader of data .
A writer of data is blocked only when another writer of data has already locked the row it was going after.

What is Interested Transaction List (ITL) ?

It is a simple data structure called "Interested Transaction List" (ITL), a list that maintains information on transaction. The transaction identifier will be stored as an entry in the ITL in the header of the data block. The ITL contains several placeholders (or slots) for transactions. When a row in the block is locked for the first time, the transaction places a lock in one of the slots. In other words, the transaction makes it known that it is interested in some rows (hence the term "Interested Transaction List").

When a different transaction locks another set of rows in the same block, that information is stored in another slot and so on. When a transaction ends after a commit or a rollback, the locks are released and the slot which was used to mark the row locks in the block is now considered free .

ITL slots are required for every transaction, it contains the transaction ID (XID) which is a pointer to an entry in the transaction table of a rollback segment. We can still read the data but other processes wanting to change the data must wait until the lock is released (commit or rollback). The ITL entry contains a XID, undo byes address (UBA) information, flags indicating the transaction status (Flag) and lock count (Lck) showing the number of rows locked by this transaction within the block and SCN at which the transaction is updated.

How many slots are typically available in ITL ?

During the table creation, the INITRANS parameter defines how many slots are initially created in the ITL. INITRANS is a block level storage parameter which can be specified while creating an object (table). INITRANS and MAXTRANS parameters are used to control the concurrent access to the same block . When the transactions exhaust all the available slots and a new transaction comes in to lock a row, the ITL grows to create another slot. The ITL can grow up to the number defined by the MAXTRANS parameter of the table, provided there is space in the block. Nevertheless, if there is no more room in the block, even if the MAXTRANS is high enough, the ITL cannot grow. the maximum value for MAXTRANS parameter is 255.

Each ITL entry in the block transaction variable header takes 24 bytes. Though a block can have a maximum of 255 different ITL entries, the ITL allocation is limited by block size. The database block size plays an important role when allocating the number of inital ITL entries for the block. The rule is "the total size allocated for initial ITLs SHOULD be LESS THAN 50% of the database block size" .

i.e, sizeof(INITIAL ITLs) < ( 50% of the DATABASE BLOCK SIZE )

BLOCK SIZE(B) NO OF ITL entries allocated in block header

============ =============================

2048 41

4096 83

8192 169

What happens when a transaction does not find a free slot to place its lock information?

This can occur because either

1.) the block is so packed that the ITL cannot grow to create a free slot, or

2.) the MAXTRANS has already been reached. In this case, the transaction that needs to lock a row has to wait until a slot becomes available. This wait is termed as ITL waits and can be seen from the view v$session_wait, in which the session is waiting on an event named "enqueue" Since the INITRANS is one, there is only one slot for the ITL. The rest of the block is empty.

How to Diagnose the ITL Wait How do we know that a segment is experiencing ITL waits?

To check for ITL waits, set up the STATISTICS_LEVEL to TYPICAL in init.ora or via ALTER SYSTEM, then examine the segment statistics for the waits.

SQL>select owner ,object_name from v$segment_statistics where statistic_name='ITL waits' and value> 0 ;

When we suspect that a database is suffering from these waits, query the view v$session_wait. If the event on which the system is waiting is "enqueue," then the session might be experiencing ITL waits. However, enqueue is a very broad event that encompasses any type of locks, so it does not accurately specify the ITL waits. When the wait event is experienced, issue the following complex query a table tab1 (say)

SQL> Select s.sid SID, s.serial# Serial#, l.type type, ' ' object_name, lmode held, request request

from v$lock l, v$session s, v$process p

where s.sid = l.sid and s.username <> ' ' and s.paddr = p.addr and l.type <> 'TM' and

(l.type <> 'TX' or l.type = 'TX' and l.lmode <> 6)

union

select s.sid SID, s.serial# Serial#, l.type type, object_name object_name, lmode held, request request

from v$lock l, v$session s, v$process p, sys.dba_objects o

where s.sid = l.sid and o.object_id = l.id1 and l.type = 'TM' and s.username <> ' ' and s.paddr = p.addr

union

select s.sid SID, s.serial# Serial#,l.type type, '(Rollback='||rtrim(r.name)||')' object_name, lmode held,

request request

from v$lock l, v$session s, v$process p, v$rollname r

where s.sid = l.sid and l.type = 'TX' and l.lmode = 6 and trunc(l.id1/65536) = r.usn and s.username <> ' ' and s.paddr = p.addr order by 5, 6 ;

The output of the query will look something like this:

SID SERIAL# TY OBJECT_NAME HELD REQUEST

----- ---------- ------- ------------------- ------- -------------

36 8428 TX 0 4

36 8428 TM TAB1 3 0

52 29592 TM TAB1 3 0

52 29592 TX (Rollback=RBS1_6) 6 0

Note how the sessions 36 and 52 both have a TM (DML) lock on the table TAB1 of type 3 (Row Exclusive), but session 52 also holds a TX (Transaction) lock on the rollback segment of mode 6 (Exclusive) and Session 36 is waiting for a mode 4 (Share) lock. If this combination of locking occurs, we can be sure that session 36 is waiting for ITL on the table TAB1. Beware of a similar but different diagnosis when two sessions try to insert the same key value (a real locking – primary key violation). In that case, we would also see an additional TX lock on a rollback segment from the session that is waiting; for ITL waits, this TX lock on the rollback segment would not be seen. To know more about working of ITL click here

Examining ITL allocation :

1.) Create a table with INITRANS 4.

SQL> create table test1 (I number) INITRANS 4 ;

2.) Insert few record for testing purpose. A blockdump can be taken later.

SQL> insert into test1 values (10) ;

SQL> commit ;

now updated the table from sessions too these transaction are in hang state .

3.) Find out the block number and the file id for dumping the block :

SQL> select dbms_rowid.rowid_relative_fno(rowid), dbms_rowid.rowid_block_number(rowid) from test;

or use the below command

SQL> select header_file,header_block from dba_segments where owner='HR' and segment_name='TEST' ;

4.) Dump the data block:

SQL> alter system dump datafile 4 block min 636 block max 636 ;

5.) Open the dump trace file located in USER_DUMP_DEST directory and check the following:

Block dump from disk:

buffer tsn: 4 rdba: 0x0100027c (4/636)

scn: 0x0000.002a1814 seq: 0x02 flg: 0x04 tail: 0x18140602

frmt: 0x02 chkval: 0x1561 type: 0x06=trans data

Hex dump of block: st=0, typ_found=1

Block header dump: 0x0100027c

Object id on Block? Y

seg/obj: 0x1277b csc: 0x00.2a1372 itc: 10 flg: E typ: 1 - DATA

brn: 0 bdba: 0x1000278 ver: 0x01 opc: 0

inc: 0 exflg: 0

Itl Xid Uba Flag Lck Scn/Fsc

0x01 0x0001.001.00000380 0x00c01117.0204.07 --U- 2 fsc 0x0000.002a1376

0x02 0x0000.000.00000000 0x00000000.0000.00 ---- 0 fsc 0x0000.00000000

0x03 0x0000.000.00000000 0x00000000.0000.00 ---- 0 fsc 0x0000.00000000

0x04 0x0000.000.00000000 0x00000000.0000.00 ---- 0 fsc 0x0000.00000000

bdba: 0x0100027c

data_block_dump,data header at 0xe511924

itl = interested transaction list (list of transactions on a block that have changes on that block)

xid = transaction id (it is a set of three numbers – undo segment#, undo slot# and undo record# - separated by periods.)

uba = undo block address (pointer to a transactions list of undo blocks)

scn/fsc = system change/commit number of the current transaction

tsn = Tablespace Number

rdba = Relative data block address.Its value is "0100027c" in hexa decimal & 16777852 in decimal

seg/obj = is the object_id. 0x 1277b = 75643 in 75643 in decimal.

itc: 10 = Number of interested transaction list(ITL) entry in the block.

typ: 1 = data –> Indicates this is an data block

Flag = State for current transaction (C – Commited) U- indicates that the particular ITL was used.

Lck = Number of Lock held by the transacion

csc: 0x00.2a1372 = This is the comit SCN number of the block

If we use locally managed tablespaces with automatic segment space management , we can more or less forget about these parameters as Oracle takes care of it for us . In Oracle 10g and above, this is now more to concern . In the past they were much more important that they are now .

Note :

Lck” column shows a value. It shows “2”, meaning two rows in the blocks is locked by a transaction. But, which transaction? To get that answer, note the value under the “Xid” column. It shows the transaction ID - 0x0001.001.00000380 . These numbers are in hexadecimal (as indicated by the 0x at the beginning of the number).
A transaction is identified by a transaction ID (XID) which is a set of three numbers – undo segment#, undo slot# and undo record# - separated by periods.
We can also check all the active transactions in the view v$transaction, where the columns XIDUSN, XIDSLOT and XIDSQN denote the undo segment#, undo slot# and undo rec# - the values that make up the transaction ID.
The v$transaction view also contains the session address under SES_ADDR column, which can be used to join with the SADDR column of v$session view to get the session details

References:- http://www.rampant-books.com/

Enjoy :-)

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 :-)