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 database has provided has many quickest ways to trace the local session, other user session and format the trace to make readable
Let us take some look at how to turn on SQL trace, 10046 event in Oracle database and trcsess, tkprof utility
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 Advantages Provides execution path Provides row counts Produces smallest flat file Disadvantages Cannot tell what values were supplied at run time to SQL If statistics for query are low but run time is long cannot tell what events caused the long wait |
| 4 | The same as 2, but with the addition of bind variable values Advantages Provides execution path Provides row counts Can tell what values the statement was run for Disadvantages Again if run time is long and statistics are low it will be hard to tell why in this type of trace. Produces a bigger flat file that the regular trace because bind variable information has to be stored. |
| 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. Advantages Provides execution path Provides row counts Can tell timings for all events associated with SQL. Disadvantages Trace file may easily max out due to all the information Oracle must write to the trace file and then only partial information is available in trace file. Bind variable information is not available |
| 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 Advantages Provides execution path Provides row counts Can tell timings for all events associated with SQL. Can tell what values the SQL was run with Disadvantages Trace file may easily max out due to all the information Oracle must write to the trace file and then only partial information is available in trace file. |
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 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: [email protected] 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:([email protected](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 DBMS_MONITOR package, we can check if trace is enabled using 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 enable through other methods, then the only way to check is 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
Oracle 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 parse prsqry number of buffers for consistent read during parseprscu number of buffers for current read during parseprsmis number of misses in library cache during parseexecnt 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 This print 10 sql only tkprof .trc elaps.prf sys=no explain=apps/ sort=(prsela,exeela,fchela) print=10 This print all the sql tkprof .trc elaps.prf sys=no explain=apps/apps 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: 6w82ggrtysx Plan Hash: 2325776775 SELECT 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: 276ut2ywqux 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)
Oracle trcsess utility
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.
More Information
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 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 therefore 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.
Also Reads
v$active_session_history
explain plan in Oracle
sql tuning Advisor
Thanks so much for the all the detailed and well organized information. Much appreciated!