In this post I will give an overview of Oracle trace files. The following are a collection of information from several books (especially [1]). Check out the References section at the end of this post.
Oracle trace files are text files that contain session information for the process that created
them. Trace files can be generated by the Oracle background processes, through the use of
trace events, or by user server processes. These trace files can contain useful information
for performance tuning and system troubleshooting.
In order to process a SQL statement, the database engine (specifically, the
SQL engine) carries out database calls (parse, execute, and fetch). For each database call, the SQL engine either
• does some processing itself, by using CPU;
• makes use of other resources (for example, a disk); or
• has to go through a synchronization point needed to guarantee the multiuser capabilities of the database engine (for example, a latch).
The aim of SQL trace is twofold: first, to provide information in order to break up the response time between service time and wait time, and second, to give detailed information about the used resources and synchronization points. All this information regarding each interaction between the SQL engine and the other components is written in a trace file.
Notice how the event number and the level are specified.
this is not achieved by specifying level 0.
Note that in this way we can enable/disable tracing only from within the session. If one wants to enable tracing for some other session specifying a session ID and a serial number, then one must call the procedure set_ev in the package dbms_system.
The following PL/SQL call enables SQL trace at level 12 for the session identified by ID 127
and serial number 29. No parameter has a default value. The last parameter then, even if it is
not relevant in this case, must be specified.
dbms_system.set_ev(si => 127, -- session id
se => 29, -- serial number
ev => 10046, -- event number
le => 12, -- level
nm => NULL)
The following PL/SQL call disables SQL trace for the session identified by ID 127 and serial
number 29. Notice that compared to the previous case, only the value of the parameter speci-
fying the level has changed.
dbms_system.set_ev(si => 127, -- session id
se => 29, -- serial number
ev => 10046, -- event number
le => 0, -- level
nm => NULL)
dbms_monitor.session_trace_enable(session_id => 127,
serial_num => 29,
waits => TRUE,
binds => FALSE)
The parameter waits defaults to TRUE, and the parameter binds defaults to FALSE.
Note: If Real Application Clusters is used, the procedures session_trace_enable and
session_trace_disable have to be executed on the instance where the session resides.
The dbms_monitor package also includes procedures in order to enable/disable tracing apart from the session level, at the Client Id level, the Component level, or the Database level (for more details check [1] or DBMS_MONITOR package in the Oracle manual [2])
The above query was ran on a 4-node RAC (a half rack Oracle Exadata). The session (sid = 2651) for which we want to know the tracefile name, runs on instance number 2 with instance name "dwhprd2". Of course the query constructs the possible tracefile name for each instance but for this case only the result for instance 2 is meaningful since this is where the specific session lives.
V$PROCESS and V$SESSION. Assuming you have access to read the user_dump_dest directory, you can use the session parameter tracefile_identifier. With this, you can add a uniquely identifiable string to the
trace file name, for example:
Oracle trace files are text files that contain session information for the process that created
them. Trace files can be generated by the Oracle background processes, through the use of
trace events, or by user server processes. These trace files can contain useful information
for performance tuning and system troubleshooting.
In order to process a SQL statement, the database engine (specifically, the
SQL engine) carries out database calls (parse, execute, and fetch). For each database call, the SQL engine either
• does some processing itself, by using CPU;
• makes use of other resources (for example, a disk); or
• has to go through a synchronization point needed to guarantee the multiuser capabilities of the database engine (for example, a latch).
The aim of SQL trace is twofold: first, to provide information in order to break up the response time between service time and wait time, and second, to give detailed information about the used resources and synchronization points. All this information regarding each interaction between the SQL engine and the other components is written in a trace file.
How to Enable/Disable Tracing
Prior to 10g
The following SQL statement enables SQL trace at level 12 (most complete level including info about wait events and bind variables) for the session executing it.Notice how the event number and the level are specified.
nikos@NIKOSDB> ALTER SESSION SET events '10046 trace name context forever, level 12'
2 /
Session altered.
this is not achieved by specifying level 0.
nikos@NIKOSDB> ALTER SESSION SET events '10046 trace name context off'
2 /
Session altered.
Note that in this way we can enable/disable tracing only from within the session. If one wants to enable tracing for some other session specifying a session ID and a serial number, then one must call the procedure set_ev in the package dbms_system.
The following PL/SQL call enables SQL trace at level 12 for the session identified by ID 127
and serial number 29. No parameter has a default value. The last parameter then, even if it is
not relevant in this case, must be specified.
dbms_system.set_ev(si => 127, -- session id
se => 29, -- serial number
ev => 10046, -- event number
le => 12, -- level
nm => NULL)
The following PL/SQL call disables SQL trace for the session identified by ID 127 and serial
number 29. Notice that compared to the previous case, only the value of the parameter speci-
fying the level has changed.
dbms_system.set_ev(si => 127, -- session id
se => 29, -- serial number
ev => 10046, -- event number
le => 0, -- level
nm => NULL)
By default, the package dbms_system can be executed only by the user sys. If the privilege
to execute it should be provided to other users, be careful because the package contains other
procedures and the procedure set_ev itself can be used to set other events as well
to execute it should be provided to other users, be careful because the package contains other
procedures and the procedure set_ev itself can be used to set other events as well
The contemporary way (10g onwards)
As of Oracle Database 10g, for enabling and disabling SQL trace, the package dbms_monitor is
provided. With this package, not only do you have an official way at last of taking full advantage
of SQL trace, but more important, you can enable and disable SQL trace based on the session
attributes: client identifier, service name, module name, and
action name. This means that if the application is correctly instrumented, you can enable and
disable SQL trace independently of the session used to execute the database calls. Nowadays, this is particularly useful because in many situations connection pooling is used, so users are
not tied to a specific session.
To enable and disable SQL trace for a session, the package dbms_monitor provides the proce-
dures session_trace_enable and session_trace_disable, respectively.
In order to enable tracing from the current session, simply enter:
nkarag@DWHPRD> exec dbms_monitor.session_trace_enable
PL/SQL procedure successfully completed.
In order to disable tracing for the current session, simply enter:
nkarag@DWHPRD> exec dbms_monitor.session_trace_disable
PL/SQL procedure successfully completed.
If you want to monitor the status of tracing for the current status issue the following:
nkarag@DWHPRD> host cat tf_status.sql
col sql_trace format a10
col sql_trace_waits format a16
col sql_trace_binds format a16
select sql_trace, sql_trace_waits, sql_trace_binds
from gv$session
where username = USER and (sid) = (select sid from v$mystat where rownum = 1)
/
nkarag@DWHPRD> @tf_status
SQL_TRACE SQL_TRACE_WAITS SQL_TRACE_BINDS
---------- ---------------- ----------------
ENABLED TRUE FALSE
You can enable tracing for a session other than the current by giving values to the corresponding parameters. For example:
serial_num => 29,
waits => TRUE,
binds => FALSE)
The parameter waits defaults to TRUE, and the parameter binds defaults to FALSE.
Note: If Real Application Clusters is used, the procedures session_trace_enable and
session_trace_disable have to be executed on the instance where the session resides.
The dbms_monitor package also includes procedures in order to enable/disable tracing apart from the session level, at the Client Id level, the Component level, or the Database level (for more details check [1] or DBMS_MONITOR package in the Oracle manual [2])
How to find where is the trace file
Prior to 11g
Trace files are produced by database engine server processes running on the database server.
This means they are written to a disk accessible from the database server. Depending on the
type of the process producing the trace files, they are written in two distinct directories:
- Dedicated server processes create trace files in the directory configured through the initialization parameter user_dump_dest.
- Background processes create trace files in the directory configured through the initialization parameter background_dump_dest.
- If you use a shared server connection to Oracle, you are using a background process so the location of your trace files is defined by background_dump_dest.
The 11g way
As of Oracle Database 11g, with the introduction of the Automatic Diagnostic Repository (ADR),
the initialization parameters user_dump_dest and background_dump_dest are deprecated in
favor of the initialization parameter diagnostic_dest. Since the new initialization parameter
sets the base directory only, you can use the view v$diag_info to get the exact location of the
trace files.
The following shows the trace file directory on each database node on a 4-node RAC:
nkarag@DWHPRD> select * from gv$diag_info where name = 'Diag Trace' order by 1
2 /
INST_ID NAME VALUE
---------- ---------------------------------------------------------------- ------------------------------------------------
1 Diag Trace /u01/app/oracle/diag/rdbms/dwhprd/DWHPRD1/trace
2 Diag Trace /u01/app/oracle/diag/rdbms/dwhprd/DWHPRD2/trace
3 Diag Trace /u01/app/oracle/diag/rdbms/dwhprd/DWHPRD3/trace
4 Diag Trace /u01/app/oracle/diag/rdbms/dwhprd/DWHPRD4/trace
How to find the name of the trace file
The name of the trace file itself used to be version and platform dependent. As of Oracle9i
and for the most-common platforms, however, it has the following structure:
{instance name}_{process name}_{process id}.trc
Where :
- instance name: This is the lowercase value of the initialization parameter instance_name. Notice that in a Real Application Clusters environment, this is different from the initialization parameter db_name. It is available in the column instance_name of the view v$instance.
- process name: This is the lowercase value of the name of the process that is producing the trace file. For dedicated server processes, the name ora is used. For shared server processes, it is found in the column name of either the view v$dispatcher or v$shared_server. For parallel slave processes, it is found in the column server_name of the view v$px_process. For most other background processes, it is found in the column name of the view v$bgprocess.
- process id: This is the process identifier at the operating system level. Its value is found in the column spid of the view v$process.
Prior to 11g
The following query constructs the name of the trace file for the current session:
nkarag@DWHPRD> host cat ftf_10g.sql
set linesize 999
column trace_file_name format a100
SELECT s.sid,
s.server,
lower(
CASE
WHEN s.server IN ('DEDICATED','SHARED') THEN (SELECT value FROM v$parameter WHERE name = 'user_dump_dest')||'/'||
i.instance_name || '_' ||
nvl(pp.server_name, nvl(ss.name, 'ora')) || '_' ||
p.spid
ELSE
NULL
END
) ||
CASE
WHEN p.traceid IS NOT NULL THEN
'_' || p.traceid
ELSE
''
END ||
'.trc' AS trace_file_name
FROM v$instance i,
v$session s,
v$process p,
v$px_process pp,
v$shared_server ss
WHERE s.paddr = p.addr
AND s.sid = pp.sid (+)
AND s.paddr = ss.paddr(+)
AND s.type = 'USER'
and s.sid = (select sys_context('USERENV', 'SID') from dual)
ORDER BY s.sid;
nkarag@DWHPRD> @ftf_10g
SID SERVER TRACE_FILE_NAME
---------- --------- ----------------------------------------------------------------------------------------------------
1142 DEDICATED /u01/app/oracle/diag/rdbms/dwhprd/dwhprd4/trace/dwhprd4_ora_112807.trcThe 11g way
In 11g with the Automatic Diagnostic Repository things are much more simple:
nkarag@DWHPRD> SELECT value FROM v$diag_info WHERE name = 'Default Trace File'
2 /
VALUE
-------------------------------------------------------------------------------
/u01/app/oracle/diag/rdbms/dwhprd/DWHPRD4/trace/DWHPRD4_ora_112807.trc
Find the trace file name for another session
If you want to find the trace file name for the trace file produced by another session, then you can use the following query to achieve the mapping between a session and the trace file. This query is RAC-enabled meaning that it uses the global GV$ views and so it returns the tracefile name for each possible instance.
(Note: that if you dont provide a sid the query returns the tracefile name for the current session)
nkarag@DWHPRD> -- first find the target session nkarag@DWHPRD> @fsess Session altered. Enter value for username: nkarag old 7: username = nvl(upper('&username'), username) new 7: username = nvl(upper('nkarag'), username) Enter value for sid: old 8: and sid = nvl('&sid', sid) new 8: and sid = nvl('', sid) USERNAME SID SERIAL# INST_ID STATUS LOGON_TIME PROG MACHINE ------------- ----- ---------- ---------- -------- ------------------- ------------------------------ -------------------------- NKARAG 900 15189 1 ACTIVE 19-06-2013 16:48:06 oracle@ex1db01.ote.gr (PZ99) CENTRAL-DOMAIN\OTE-NKARAG NKARAG 2916 31543 4 ACTIVE 19-06-2013 16:48:06 oracle@ex1db04.ote.gr (PZ99) CENTRAL-DOMAIN\OTE-NKARAG NKARAG 2916 41941 2 ACTIVE 19-06-2013 16:48:06 oracle@ex1db02.ote.gr (PZ99) CENTRAL-DOMAIN\OTE-NKARAG NKARAG 1142 26047 4 ACTIVE 19-06-2013 16:20:31 sqlplus.exe CENTRAL-DOMAIN\OTE-NKARAG NKARAG 2916 1207 3 ACTIVE 19-06-2013 16:48:06 oracle@ex1db03.ote.gr (PZ99) CENTRAL-DOMAIN\OTE-NKARAG ----- 5 NKARAG 2651 31399 2 INACTIVE 19-06-2013 15:37:09 Toad.exe CENTRAL-DOMAIN\OTE-NKARAG NKARAG 1659 33241 3 INACTIVE 19-06-2013 09:46:19 Toad.exe CENTRAL-DOMAIN\OTE-NKARAG NKARAG 390 52109 2 INACTIVE 19-06-2013 09:48:48 Toad.exe CENTRAL-DOMAIN\OTE-NKARAG NKARAG 1663 49113 4 INACTIVE 19-06-2013 09:46:15 Toad.exe CENTRAL-DOMAIN\OTE-NKARAG NKARAG 2663 11971 3 INACTIVE 19-06-2013 12:56:03 OMS exagridsrv.ote.gr ----- 5 10 rows selected. nkarag@DWHPRD> -- now lets get the tracefile name nkarag@DWHPRD> host cat ftf_map2sess.sql set linesize 999 column trace_file_name format a100 SELECT s.inst_id, s.sid, s.serial#, s.server, lower( CASE WHEN s.server IN ('DEDICATED','SHARED') THEN (SELECT value FROM v$parameter WHERE name = 'user_dump_dest')||'/'|| i.instance_name || '_' || nvl(pp.server_name, nvl(ss.name, 'ora')) || '_' || p.spid ELSE NULL END ) || CASE WHEN p.traceid IS NOT NULL THEN '_' || p.traceid ELSE '' END || '.trc' AS trace_file_name FROM gv$instance i, gv$session s, gv$process p, gv$px_process pp, gv$shared_server ss WHERE s.sid = nvl('&sid',(select sys_context('USERENV', 'SID') from dual)) AND s.paddr = p.addr and s.inst_id = p.inst_id AND s.sid = pp.sid (+) and s.inst_id = pp.inst_id (+) AND s.paddr = ss.paddr(+) and s.inst_id = ss.inst_id (+) AND s.type = 'USER' ORDER BY trace_file_name / nkarag@DWHPRD> @ftf_map2sess Enter value for sid: 2651 old 26: s.sid = nvl('&sid',(select sys_context('USERENV', 'SID') from dual)) new 26: s.sid = nvl('2651',(select sys_context('USERENV', 'SID') from dual)) INST_ID SID SERIAL# SERVER TRACE_FILE_NAME ---------- ----- ---------- --------- ------------------------------------------------------------------------------------------ 2 2651 31399 DEDICATED /u01/app/oracle/diag/rdbms/dwhprd/dwhprd4/trace/dwhprd1_ora_117181.trc2 2651 31399 DEDICATED /u01/app/oracle/diag/rdbms/dwhprd/dwhprd4/trace/dwhprd2_ora_117181.trc2 2651 31399 DEDICATED /u01/app/oracle/diag/rdbms/dwhprd/dwhprd4/trace/dwhprd3_ora_117181.trc 2 2651 31399 DEDICATED /u01/app/oracle/diag/rdbms/dwhprd/dwhprd4/trace/dwhprd4_ora_117181.trc
The above query was ran on a 4-node RAC (a half rack Oracle Exadata). The session (sid = 2651) for which we want to know the tracefile name, runs on instance number 2 with instance name "dwhprd2". Of course the query constructs the possible tracefile name for each instance but for this case only the result for instance 2 is meaningful since this is where the specific session lives.
Tagging Trace Files
There is a way to “tag” your trace file so that you can find it even if you are not permitted access toV$PROCESS and V$SESSION. Assuming you have access to read the user_dump_dest directory, you can use the session parameter tracefile_identifier. With this, you can add a uniquely identifiable string to the
trace file name, for example:
nkarag@DWHPRD> host cat tf_set_id.sql
alter session set tracefile_identifier = '&tf_id';
nkarag@DWHPRD> @tf_set_id
Enter value for tf_id: nikos
old 1: alter session set tracefile_identifier = '&tf_id'
new 1: alter session set tracefile_identifier = 'nikos'
nkarag@DWHPRD> SELECT value FROM v$diag_info WHERE name = 'Default Trace File'
2 /
VALUE
-------------------------------------------------------------------------------
/u01/app/oracle/diag/rdbms/dwhprd/DWHPRD4/trace/DWHPRD4_ora_112807_nikos.trc
How to format a trace file
TKPROF is a command-line tool. Its main purpose is to take a raw trace file as input and
generate a formatted text file as output. For example:
tkprof DBM11106_ora_6334.trc DBM11106_ora_6334.txt
If you run TKPROF without arguments, you get a complete list of its arguments with a short
description for each of them.
generate a formatted text file as output. For example:
tkprof DBM11106_ora_6334.trc DBM11106_ora_6334.txt
If you run TKPROF without arguments, you get a complete list of its arguments with a short
description for each of them.
How to interpret the contents of a trace file
This is a major topic and deserves a separate post (or many posts) on its own. So we will discuss it in some future post. Note that an excellent book for explaining how to read and interpret the contents of trace files is Cary Millsap's "Optimizing Oracle Performance".
Enjoy
Oracle Learner
Enjoy
Oracle Learner
References
- "Troubleshooting Oracle Performance", Christian Antognini, Apress 2008
- Oracle® Database PL/SQL Packages and Types Reference 11g Release 2 (11.2)
- Metalink Note (21154.1), EVENT: 10046 "enable SQL statement tracing (including binds/waits)"
- Metalink Note (171647.1), Tracing Oracle Applications using Event 10046 in 10.7, 11.0, and 11i
- Expert Oracle Database Architecture 2nd Ed. Tom Kyte, Apress 2012
No comments:
Post a Comment