SQL trace, 10046 event in Oracle

• Tracing is an important part of Oracle database tuning. This will help capture all the problem statements and waitevents that are responsible for the slow running of the session.
• Oracle database has provided has many quickest ways to trace the local session, and other user sessions and format the trace to make readable
• SQL tracing finds out below things for each sql statement executed
  • parse, execute, and fetch counts
  • CPU and elapsed times
  • physical reads and logical reads
  • number of rows processed
  • misses on the library cache
  • the username under which each parse occurred
  • each commit and rollback

Let us take a look at how to turn on SQL trace, 10046 events in the Oracle database

How to enable SQL Trace (10046 events)

If you want to enable trace in a local session, here are the steps to turn on SQL trace

Normal trace

alter session set sql_trace = true;  -- To put trace on

alter session set sql_trace = false;  -- To put trace off

Full level with wait event And bind trace

alter session set events = ‘10046 trace name context forever, level 12’;

To put tracing off

alter session set events = ‘10046 trace name context off’;

Same as Normal trace

exec DBMS_SESSION.set_sql_trace(sql_trace => TRUE);

exec DBMS_SESSION.set_sql_trace(sql_trace => FALSE);

If you want to trace in other running session,here are the steps

Normal trace

execute dbms_system.set_sql_trace_in_session (‘sid’,’serial’,true);  -- To put tracing on

execute dbms_system.set_sql_trace_in_session (‘sid’,’serial’,true);   -- To put tracing off

Full level with wait event And bind trace

execute dbms_system.set_ev(‘sid’,’serial’,10046,12,’’);

To put trace off

execute dbms_system.set_ev(‘sid’,’serial’,10046,0,’’);

You must have seen using 12,0 in various statements above. They are tracing levels. Oracle Tracing has tracing levels . Here are the valid values

There are other ways to do the tracing also. Here are some of these
(1) ORADEBUG
This requires login as sysdba

oradebug setospid   1111   -- Debug session with the specified Oracle  process id

oradebug setorapid  1111  --- Debug session with the specified OS process

oradebug event 10046 trace name context forever, level 4;

oradebug event 10046 trace name context off;   --- This disable the trace

oradebug close_trace  --- This closes  the trace file

Oradebug TRACEFILE_NAME;

(2) With Oracle 10g the SQL tracing options have been  extended using the DBMS_MONITOR package

EXECUTE dbms_monitor.session_trace_enable

Which is similar

ALTER SESSION SET EVENTS '10046 trace name context forever, level 2';

EXECUTE dbms_monitor.session_trace_enable (binds=>true);

Which is similar

ALTER SESSION SET EVENTS '10046 trace name context forever, level 4';

EXECUTE dbms_monitor.session_trace_enable (waits=>true);

Which is similar

ALTER SESSION SET EVENTS '10046 trace name context forever, level 8';

EXECUTE dbms_monitor.session_trace_enable('sid','serial#')

Which is similar

execute dbms_system.set_ev(‘sid’,’serial’,10046,2,’’);

EXECUTE dbms_monitor.session_trace_enable ('sid','serial#',binds=>true);

Which is similar

execute dbms_system.set_ev(‘sid’,’serial’,10046,4,’’);

EXECUTE dbms_monitor.session_trace_enable ('sid','serial#',waits=>true);

Which is similar

execute dbms_system.set_ev(‘sid’,’serial’,10046,8,’’);

There are many other functionalities available in dbms_monitor. We can enable trace based on client identifiers and multiple ways

How to identify the Trace files

We can identify the trace files using the spid of the session. Also, the trace file will contain “sid,serial#”  pair at the start of the trace file.
The below query can be used to find the local session trace file

select c.value || '/' || d.instance_name ||'_ora_' || a.spid || '.trc' trace
from v$process a, v$session b, v$parameter c, v$instance d
where a.addr = b.paddr
and b.audsid = userenv('sessionid')
and c.name = 'user_dump_dest'
/

There is another easy way to identify the trace file  which is called a trace identifier

alter session set tracefile_identifer=’ORAC’;  This is identifier

Example trace file

Trace file /app/oracle/TEST/diag/rdbms/test/TEST/trace/TEST_ora_13025_IDEN.trc
Oracle Database 11g Enterprise Edition Release 11.2.0.4.0 - 64bit Production
With the Partitioning, Real Application Clusters, OLAP, Data Mining and Real Application Testing options
ORACLE_HOME = /app/oracle/TEST/11.2.0/db
System name:    SunOS12
Node name: sun12Release:   5.10Version:   Generic_144488-11
Machine:   sun4u
Instance name: TEST
Redo thread mounted by this instance: 1
Oracle process number: 202
Unix process pid: 13025, image: oracle@ SunOS12
*** 2013-10-21 12:28:56.461
*** SESSION ID:(3875.17341) 2013-10-21 12:28:56.461*** CLIENT ID:() 2013-10-21 12:28:56.461
*** SERVICE NAME:(TEST) 2013-10-21 12:28:56.461
*** MODULE NAME:(STANDARD@sunOS12(TNS V1-V3)) 2013-10-21 12:28:56.461
*** ACTION NAME:() 2013-10-21 12:28:56.461
CLOSE #4:c=0,e=11,dep=1,type=1,tim=8866891135825
=====================
PARSING IN CURSOR #5 len=356 dep=1 uid=173 oct=3 lid=173 tim=8866891136821 hv=2468783182 ad='4c70e4398' sqlid='0wmwsjy9kd92f'SELECT PROFILE_OPTION_ID, APPLICATION_ID, SITE_ENABLED_FLAG , APP_ENABLED_FLAG , RESP_ENABLED_FLAG , USER_ENABLED_FLAG, ORG_ENABLED_FLAG , SERVER_ENABLED_FLAG, SERVERRESP_ENABLED_FLAG, HIERARCHY_TYPE, USER_CHANGEABLE_FLAG FROM FND_PROFILE_OPTIONS WHERE PROFILE_OPTION_NAME = :B1 AND START_DATE_ACTIVE <= SYSDATE AND NVL(END_DATE_ACTIVE, SYSDATE) >= SYSDATEEND OF STMT
BINDS #5:
Bind#0
oacdty=01 mxl=128(80) mxlc=00 mal=00 scl=00 pre=00
oacflg=03 fl2=1206001 frm=01 csi=871 siz=128 off=0
kxsbbbfp=ffffffff7d677b48  bln=128  avl=21  flg=0
value="PER_BUSINESS_GROUP_ID"
EXEC #5:c=0,e=1474,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=1,plh=1374985481,tim=8866891138224
FETCH #5:c=0,e=61,p=0,cr=3,cu=0,mis=0,r=1,dep=1,og=1,plh=1374985481,tim=8866891138429
CLOSE #5:c=0,e=5,dep=1,type=3,tim=8866891138503
=====================
PARSING IN CURSOR #4
 len=230 dep=1 uid=173 oct=3 lid=173 tim=8866891138634 hv=3575592451 ad='3aeea3da0' sqlid='55dc767ajydh3'
SELECT PROFILE_OPTION_VALUE FROM FND_PROFILE_OPTION_VALUES WHERE PROFILE_OPTION_ID = :B4 AND APPLICATION_ID = :B3 AND LEVEL_ID = 10003 AND LEVEL_VALUE = :B2 AND LEVEL_VALUE_APPLICATION_ID = :B1 AND PROFILE_OPTION_VALUE IS NOT NULL
END OF STMT
BINDS #4:
Bind#0
oacdty=02 mxl=22(21) mxlc=00 mal=00 scl=00 pre=00
oacflg=03 fl2=1206001 frm=00 csi=00 siz=96 off=0
kxsbbbfp=ffffffff7d677b68  bln=22  avl=03  flg=05
value=1204
Bind#1
oacdty=02 mxl=22(21) mxlc=00 mal=00 scl=00 pre=00
oacflg=03 fl2=1206001 frm=00 csi=00 siz=0 off=24
kxsbbbfp=ffffffff7d677b80  bln=22  avl=02  flg=01
value=800
Bind#2
oacdty=02 mxl=22(21) mxlc=00 mal=00 scl=00 pre=00
oacflg=03 fl2=1206001 frm=00 csi=00 siz=0 off=48
kxsbbbfp=ffffffff7d677b98  bln=22  avl=04  flg=01
value=50334
Bind#3
oacdty=02 mxl=22(21) mxlc=00 mal=00 scl=00 pre=00
oacflg=03 fl2=1206001 frm=00 csi=00 siz=0 off=72
kxsbbbfp=ffffffff7d677bb0  bln=22  avl=01  flg=01
value=0
EXEC #4:c=0,e=377,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=1,plh=2802907561,tim=8866891138978
FETCH #4:c=0,e=26,p=0,cr=3,cu=0,mis=0,r=0,dep=1,og=1,plh=2802907561,tim=8866891139050
CLOSE #4:c=0,e=2,dep=1,type=3,tim=8866891139116
=====================
PARSING IN CURSOR #5 
len=191 dep=1 uid=173 oct=3 lid=173 tim=8866891139308 hv=303338305 ad='3bedf0e48' sqlid='7qs7fx89194u1'
SELECT PROFILE_OPTION_VALUE FROM FND_PROFILE_OPTION_VALUES WHERE PROFILE_OPTION_ID = :B4 AND APPLICATION_ID = :B3 AND LEVEL_ID = :B2 AND LEVEL_VALUE = :B1 AND PROFILE_OPTION_VALUE IS NOT NULL
END OF STMT
BINDS #5:
Bind#0
oacdty=02 mxl=22(21) mxlc=00 mal=00 scl=00 pre=00
oacflg=03 fl2=1206001 frm=00 csi=00 siz=96 off=0
kxsbbbfp=ffffffff7d673b78  bln=22  avl=03  flg=05
value=1204
Bind#1
oacdty=02 mxl=22(21) mxlc=00 mal=00 scl=00 pre=00
oacflg=03 fl2=1206001 frm=00 csi=00 siz=0 off=24
kxsbbbfp=ffffffff7d673b90  bln=22  avl=02  flg=01
value=800
Bind#2
oacdty=02 mxl=22(21) mxlc=00 mal=00 scl=00 pre=00
oacflg=03 fl2=1206001 frm=00 csi=00 siz=0 off=48
kxsbbbfp=ffffffff7d673ba8  bln=22  avl=04  flg=01
value=10001

how to check if trace is enabled in oracle

If you have enabled tracing using the DBMS_MONITOR package, we can check if the trace is enabled using the below query

set lines 180
col module for a45
col sql_trace_waits for a20
col sql_trace_binds for a20
col sql_trace for a20
select username,module,sid,sql_trace,sql_trace_waits,sql_trace_binds from v$session where sql_trace='ENABLED'
/

If it is enabled through other methods, then the only way to check is to look at the trace location and find out the trace files which are recent and then find the sid and serial# in it and then you can query v$session to find the session and you can disable the trace if you want

Sql trace in 11g and above

In 11g and higher, sql_trace is also an event and can be set with event syntax:

SQL> oradebug doc event name sql_trace

sql_trace: event for sql trace

Usage
-------
sql_trace
wait < false | true >,
bind < false | true >,
plan_stat < never | first_execution | all_executions | adaptive >,
level <ub4>

So you could use it as follows to enable SQL_TRACE requesting bind information:

alter session set events 'sql_trace bind=true';

or bind and wait for information (notice comma separated):

alter session set events 'sql_trace bind=true, wait=true';

Further trace can be limited to a set of SQL_IDs if you include a filter for it. E.g.

alter session set events 'sql_trace [sql: sql_id=g3yc1js3g2689 | sql_id=7ujay4u33g337]bind=true, wait=true';

10046 EVENT levels: (the new sql_trace values are included in [..])
These are bit values so can be put together to get different mixes
1 – Enable standard SQL_TRACE functionality (Default)
4 – As Level 1 PLUS trace bind values [ bind=true ]
8 – As Level 1 PLUS trace waits [ wait=true ]
This is especially useful for spotting latch wait etc.
but can also be used to spot full table scans and index scans.

As of 11g these additional bit levels are available:
16 – Generate STAT line dumps for each execution [ plan_stat=all_executions ]
32 – Never dump execution statistics [ plan_stat=never ]

As of 11.2.0.2 this additional bit level is available:
64 – Adaptive dump of STAT lines. [ plan_stat=adaptive ]
This dumps the STAT information if a SQL took more than about 1 minute thereby
giving information for the more expensive SQLs and for different executions of such
SQLs.

eg: A common event level is 12 which includes standard SQL_TRACE output, binds, waits, and
default STAT line tracing.

Notes:
STAT dumping has been amended in 11g so that they are not aggregated across all executions but are dumped after execution. This has been done to address cases where the cursor is not closed and the STAT information is not dumped.
Now we guarantee to capture the STAT information following the execution. See the above bit levels to have finer control over STAT lines.

Size of trace files

• The trace file size is limited by the parameter MAX_DUMP_FILE_SIZE. The unit of this parameter, if you don’t specify the K or M option, is in OS block size.
• Be sure this parameter is set to a value higher enough to generate all the content.
• Generally we ask them to set it to unlimited but we need to monitor the trace location for filesystem full issues

Also Reads
v$active_session_history
explain plan in Oracle
sql tuning Advisor