Generating SQL Trace Files Oracle Tips by Burleson Consulting

The following Tip is from the outstanding book "Oracle PL/SQL Tuning: Expert Secrets for High Performance Programming" by Dr. Tim Hall, Oracle ACE of the year, 2006:

There are numerous ways to enable, disable and vary the contents of this trace.  The following methods have been available for several versions of the database.

-- All versions.

SQL> ALTER SESSION SET sql_trace=TRUE;
SQL> ALTER SESSION SET sql_trace=FALSE;

SQL> EXEC DBMS_SESSION.set_sql_trace(sql_trace => TRUE);
SQL> EXEC DBMS_SESSION.set_sql_trace(sql_trace => FALSE);

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

SQL> EXEC DBMS_SYSTEM.set_sql_trace_in_session(sid=>123, serial#=>1234, sql_trace=>TRUE);
SQL> EXEC DBMS_SYSTEM.set_sql_trace_in_session(sid=>123, serial#=>1234, sql_trace=>FALSE);

SQL> EXEC DBMS_SYSTEM.set_ev(si=>123, se=>1234, ev=>10046, le=>8, nm=>' ');
SQL> EXEC DBMS_SYSTEM.set_ev(si=>123, se=>1234, ev=>10046, le=>0, nm=>' ');

-- All versions, requires DBMS_SUPPORT package to be loaded.

SQL> EXEC DBMS_SUPPORT.start_trace(waits=>TRUE, binds=>FALSE);
SQL> EXEC DBMS_SUPPORT.stop_trace;

SQL> EXEC DBMS_SUPPORT.start_trace(sid=>123, serial=>1234, waits=>TRUE, binds=>FALSE);
SQL> EXEC DBMS_SUPPORT.stop_trace(sid=>123, serial=>1234);

The dbms_support package is not present by default, but can be loaded as the SYS user by executing the @$ORACLE_HOME/rdbms/admin/dbmssupp.sql script.

For methods that require tracing levels, the following are valid values:

• 0 - No trace. Like switching sql_trace off.

• 2 - The equivalent of regular sql_trace.

• 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.

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

The same combinations are possible for those methods with boolean parameters for waits and binds.

With the advent of Oracle 10g, the SQL tracing options have been centralized and extended using the dbms_monitor package.  The examples below show a few possible variations for enabling and disabling SQL trace in Oracle 10g.

-- Oracle 10g

SQL> EXEC DBMS_MONITOR.session_trace_enable;
SQL> EXEC DBMS_MONITOR.session_trace_enable(waits=>TRUE, binds=>FALSE);
SQL> EXEC DBMS_MONITOR.session_trace_disable;

SQL> EXEC DBMS_MONITOR.session_trace_enable(session_id=>1234, serial_num=>1234);
SQL> EXEC DBMS_MONITOR.session_trace_enable(session_id =>1234, serial_num=>1234, waits=>TRUE,
binds=>FALSE);
SQL> EXEC DBMS_MONITOR.session_trace_disable(session_id=>1234, serial_num=>1234);

SQL> EXEC DBMS_MONITOR.client_id_trace_enable(client_id=>'tim_hall');
SQL> EXEC DBMS_MONITOR.client_id_trace_enable(client_id=>'tim_hall', waits=>TRUE,
binds=>FALSE);
SQL> EXEC DBMS_MONITOR.client_id_trace_disable(client_id=>'tim_hall');

SQL> EXEC DBMS_MONITOR.serv_mod_act_trace_enable(service_name=>'db10g',
module_name=>'test_api', action_name=>'running');
SQL> EXEC DBMS_MONITOR.serv_mod_act_trace_enable(service_name=>'db10g',
module_name=>'test_api', action_name=>'running', waits=>TRUE, binds=>FALSE);
SQL> EXEC DBMS_MONITOR.serv_mod_act_trace_disable(service_name=>'db10g', module_name=>'test_api', action_name=>'running');

The package provides the conventional session level tracing along with two new variations.  First, tracing can be enabled on multiple sessions based on the value of the client_identifier column of the v$session view, set using the dbms_session package. 

Second, tracing can be activated for multiple sessions based on various combinations of the service_name, module, action columns in the v$session view, set using the dbms_application_info package, along with the instance_name in RAC environments.  With all the possible permutations and default values, this provides a high degree of flexibility.

trcsess

Activating trace on multiple sessions means that trace information is spread throughout many trace files.  For this reason Oracle 10g introduced the trcsess utility, allowing trace information from multiple trace files to be identified and consolidated into a single trace file.  The trcsess usage is listed below.

trcsess [output=<output file name >]  [session=<session ID>] [clientid=<clientid>] [service=<service name>] [action=<action name>] [module=<module name>] <trace file names>
output=<output file name> output destination default being standard output.
session=<session Id> session to be traced.
Session id is a combination of session Index & session serial number e.g. 8.13.
clientid=<clientid> clientid to be traced.
service=<service name> service to be traced.
action=<action name> action to be traced.
module=<module name> module to be traced.
<trace_file_names> Space separated list of trace files with wild card '*' supported.

With all these options, the consolidated trace file can be as broad or as specific as needed.

tkprof

The SQL trace files produced by the methods discussed previously can be read in their raw form, or they can be translated by the tkprof utility into a more human readable form.  The output below lists the usage notes from the tkprof utility in Oracle 10g.

$ 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 parse
    prscu   number of buffers for current read during parse
     prsmis  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

$

The waits parameter was only added in Oracle 9i, so prior to this version wait information had to be read from the raw trace file.  The values of bind variables must be read from the raw files as they are not displayed in the tkprof output.

The following section shows an example of gathering SQL trace for a session as an example of the whole process.

Get the Complete Oracle Utility Information  The landmark book "Advanced Oracle Utilities The Definitive Reference"  contains over 600 pages of filled with valuable information on Oracle's secret utilities. This book includes scripts and tools to hypercharge Oracle 11g performance and you can buy it for 30% off directly from the publisher.