How to turn on the SQL trace, 10046 event in Oracle database and trcsess, tkprof utility



Last updated on August 16th, 2016 at 05:30 pm

Tracing is a important part for Oracle database tuning. This will help capture all the problem statement , wait event which are responsible for slow running of the session.
Oracle has provided has many quickest ways to trace the local session, other user session   and format the trace to make readable.
SQL trace, 10046 event

Let us take some look at how to turn on SQL trace, 10046 event in  Oracle database and trcsess, tkprof utlity

SQL Trace ,100046 event

If you want to trace in 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 statement above.They are tracing levels.Oracle Tracing has  tracing levels .Here are the valid values

 

0 No trace. Like switching sql_trace off.
2 The equivalent of regular sql_trace

It Provides execution path,row counts,smallest flat file

4 The same as 2, but with the addition of bind variable values
8 The same as 2, but with the addition of wait events

Regular Trace plus database operation timings that the SQL waited to have done in order to complete. For example: disk access timings.

12 The same as 2, but with both bind variable values and wait events

Regular trace with the both the wait and bind information. Contains the most complete information and will produce the largest trace file.
Provides execution path
Provides row counts
Can tell timings for all events associated with SQL.
Can tell what values the SQL was run with

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 functionality available in dbms_monitor. We can enable trace based on client identifier 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.
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 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 Miningand 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
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=ffffffff7d673bc0  bln=22  avl=01  flg=01
value=0
EXEC #5:c=0,e=377,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=1,plh=2802907561,tim=8866891139624
FETCH #5:c=0,e=26,p=0,cr=4,cu=0,mis=0,r=1,dep=1,og=1,plh=2802907561,tim=8866891139692
CLOSE #5:c=0,e=7,dep=1,type=3,tim=8866891139739=====================PARSING IN CURSOR #4 len=356 dep=1 uid=173 oct=3 lid=173 tim=8866891139952 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) >= SYSDATE
END OF STMT
BINDS #4:
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=ffffffff7d673b58  bln=128  avl=23  flg=05
value=”PER_SECURITY_PROFILE_ID”
EXEC #4:c=0,e=164,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=1,plh=1374985481,tim=8866891140097
FETCH #4:c=0,e=28,p=0,cr=3,cu=0,mis=0,r=1,dep=1,og=1,plh=1374985481,tim=8866891140171
CLOSE #4:c=0,e=2,dep=1,type=3,tim=8866891140218
=====================
PARSING IN CURSOR #5 len=230 dep=1 uid=173 oct=3 lid=173 tim=8866891140290 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 #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=2199
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=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=ffffffff7d673bc0  bln=22  avl=01  flg=01
value=0
EXEC #5:c=0,e=325,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=1,plh=2802907561,tim=8866891140599
FETCH #5:c=0,e=19,p=0,cr=3,cu=0,mis=0,r=0,dep=1,og=1,plh=2802907561,tim=8866891140659CLOSE #5:c=0,e=1,dep=1,type=3,tim=8866891140710
=====================
PARSING IN CURSOR #4 len=191 dep=1 uid=173 oct=3 lid=173 tim=8866891140843 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 #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=ffffffff7d673b78  bln=22  avl=03  flg=05
value=2199
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
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=ffffffff7d673bc0  bln=22  avl=01  flg=01
value=0
EXEC #4:c=0,e=324,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=1,plh=2802907561,tim=8866891141152FETCH #4:c=0,e=17,p=0,cr=4,cu=0,mis=0,r=1,dep=1,og=1,plh=2802907561,tim=8866891141208
CLOSE #4:c=0,e=7,dep=1,type=3,tim=8866891141256

 

tkprof utility

The trace files obtained from above method is in raw  form which can be converted into more readable format using tkprof utility  (Transient Kernel PROFile  utility)

tkprof
Usage: tkprof tracefile outputfile [explain= ] [table= ]
[print= ] [insert= ] [sys= ] [sort= ]
table=schema.tablename   Use ‘schema.tablename’ with ‘explain=’ option.
explain=user/password    Connect to ORACLE and issue EXPLAIN PLAN.
print=integer    List only the first ‘integer’ SQL statements.
aggregate=yes|no
insert=filename  List SQL statements and data inside INSERT statements.
sys=no           TKPROF does not list SQL statements run as user SYS.
record=filename  Record non-recursive statements found in the trace file.
waits=yes|no     Record summary for any wait events found in the trace file.
sort=option      Set of zero or more of the following sort options:
prscnt  number of times parse was called
prscpu  cpu time parsing
prsela  elapsed time parsing    prsdsk  number of disk reads during parseprsqry  number of buffers for consistent read during parseprscu   number of buffers for current read during parseprsmis  number of misses in library cache during parse

execnt  number of execute was called

execpu  cpu time spent executing

exeela  elapsed time executing

exedsk  number of disk reads during execute

exeqry  number of buffers for consistent read during execute

execu   number of buffers for current read during execute

exerow  number of rows processed during execute

exemis  number of library cache misses during execute

fchcnt  number of times fetch was called

fchcpu  cpu time spent fetching

fchela  elapsed time fetching

fchdsk  number of disk reads during fetch

fchqry  number of buffers for consistent read during fetch

fchcu   number of buffers for current read during fetch

fchrow  number of rows fetched

userid  userid of user that parsed the cursor

Some examples
tkprof file.trc file.txt sys=no explain=userid/password sort=prsela,exeela,fchela
tkprof file.trc file.txt  sys=no explain=userid/password  sort=prsela,exeela,fchela
tkprof file.trc file.txt sys=no
tkprof file.trc file.txt sys=no explain=userid/password sort=prsela,exeela,fchela

Example content of tkprof file

TKPROF: Release 11.2.0.4.0 – Production on Tue Jan 17 14:12:41 2013
Copyright (c) 1982, 2007, Oracle.  All rights reserved.
Trace file: TEST_ora_15941.trc
Sort options: execpu  fchcpu
********************************************************************************
count    = number of times OCI procedure was executed
cpu      = cpu time in seconds executing
elapsed  = elapsed time in seconds executing
disk     = number of physical reads of buffers from disk
query    = number of buffers gotten for consistent read
current  = number of buffers gotten in current mode (usually for update)
rows     = number of rows processed by the fetch or execute call
********************************************************************************
SQL ID: 6w821sggrtysx
Plan Hash: 2325776775SELECT FUNCTION_NAME    FROM FND_USER_DESKTOP_OBJECTS  WHERE USER_ID = :b1  AND APPLICATION_ID = :b2  AND  RESPONSIBILITY_ID = :b3  AND TYPE = ‘FUNCTION’  AND ROWNUM <= 10 ORDER BY SEQUENCE
call     count       cpu    elapsed       disk      query    current        rows
——- ——  ——– ———- ———- ———- ———-  ———-
Parse        1      0.00       0.00          0          0          0           0
Execute      1      0.00       0.00          0          0          0           0
Fetch        2      0.00       0.00          0          4          0           1
——- ——  ——– ———- ———- ———- ———-  ———-
total        4      0.00       0.00          0          4          0           1
Misses in library cache during parse: 0
Optimizer mode: ALL_ROWS
Parsing user id: 173  (APPS)
Number of plan statistics captured: 1
Rows (1st) Rows (avg) Rows (max)  Row Source Operation
———- ———- ———-  —————————————————
1          1          1  SORT ORDER BY (cr=4 pr=0 pw=0 time=0 us cost=6 size=41 card=1)
1          1          1   COUNT STOPKEY (cr=4 pr=0 pw=0 time=0 us)
1          1          1    TABLE ACCESS BY INDEX ROWID FND_USER_DESKTOP_OBJECTS (cr=4 pr=0 pw=0 time=0 us cost=5 size=41 card=1)
1          1          1     INDEX RANGE SCAN FND_USER_DESKTOP_OBJECTS_N1 (cr=3 pr=0 pw=0 time=0 us cost=3 size=0 card=3)(object id 33596)
Rows     Execution Plan
——-  —————————————————
0  SELECT STATEMENT   MODE: ALL_ROWS
1   SORT (ORDER BY)
1    COUNT (STOPKEY)
1     TABLE ACCESS   MODE: ANALYZED (BY INDEX ROWID) OF
‘FND_USER_DESKTOP_OBJECTS’ (TABLE)
1      INDEX   MODE: ANALYZED (RANGE SCAN) OF
‘FND_USER_DESKTOP_OBJECTS_N1’ (INDEX)
Elapsed times include waiting on following events:
Event waited on                             Times   Max. Wait  Total Waited
—————————————-   Waited  ———-  ————
SQL*Net message to client                       5        0.00          0.00
SQL*Net message from client                     5        0.00          0.00********************************************************************************
SQL ID: 276ut2y7ywqux
Plan Hash: 3856112528
select object_name, icon_name
from
fnd_desktop_objects
call     count       cpu    elapsed       disk      query    current        rows
——- ——  ——– ———- ———- ———- ———-  ———-
Parse        1      0.00       0.00          0          0          0           0
Execute      1      0.00       0.00          0          0          0           0
Fetch        3      0.00       0.00          0          6          0          47
——- ——  ——– ———- ———- ———- ———-  ———-
total        5      0.00       0.00          0          6          0          47
Misses in library cache during parse: 0
Optimizer mode: ALL_ROWS
Parsing user id: 173  (APPS)
Number of plan statistics captured: 1
Rows (1st) Rows (avg) Rows (max)  Row Source Operation
———- ———- ———-  —————————————————
47         47         47  TABLE ACCESS FULL FND_DESKTOP_OBJECTS (cr=6 pr=0 pw=0 time=0 us cost=2 size=1175 card=47)
Rows     Execution Plan
——-  —————————————————
0  SELECT STATEMENT   MODE: ALL_ROWS
47   TABLE ACCESS   MODE: ANALYZED (FULL) OF ‘FND_DESKTOP_OBJECTS’
(TABLE)
Elapsed times include waiting on following events:Event waited on                             Times   Max. Wait  Total Waited—————————————-   Waited  ———-  ————

SQL*Net message to client                       4        0.00          0.00

SQL*Net message from client                     4        0.00          0.00

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

trcsess utlity

When using shared server sessions, many processes are involved. The trace pertaining to the user session is scattered across different trace files belonging to different processes. This makes it difficult to get a complete picture of the life cycle of a session.
The trcsess utility consolidates trace output from selected trace files based on several criteria

trcsess  [output=output_file_name]
[session=session_id]
[clientid=client_id]
[service=service_name]
[action=action_name]
[module=module_name]
[trace_files]
trcsess output=main.trc service=TEST  *trc

After the consolidate trace file had been generated you can execute tkprof on it.


Leave a Reply