Friday, November 7, 2014

How to generate a trace file for a SQL query

How to generate a trace file for a SQL query

set time on;

set timing on;

ALTER SESSION SET TRACEFILE_IDENTIFIER = "MY_TRACE2_SESSION";

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

SET SERVEROUTPUT ON

SELECT  * from emp;

ALTER SESSION SET EVENTS '10046 trace name context off';

Thursday, November 6, 2014

Orace performance tuning Master Note

Master Note: Database Performance Overview (Doc ID 402983.1)

Purpose
Questions and Answers
Pro-Active Problem Avoidance and Diagnostic Collection
Performance Information Centres
Troubleshooting Guides
Common Problem Topics
Slow Database Performance
Concurrency Issues
Database Hangs/Spins
Session Hangs/Spins
Locking Issues
Deadlock
Pre-Upgrade Planning
Post-Upgrade Performance Issue Resolution
Debugging Waits for Various Events
Library Cache/Mutex Contention/Cursor Type Events:
Other Types:
Common Causes of Performance issues
Cursor Sharing/High Version Counts for Cursors
High CPU usage
Issues With waits for 'log file sync'
WAITED TOO LONG FOR A ROW CACHE ENQUEUE LOCK!
Buffer Busy/Cache Buffers Chains Latch waits
SYSAUX Issues
Performance Diagnostics References
General Diagnostics Overview
AWR/Statspack
10046 Trace
Systemstates/Hanganalyze
Errorstacks for Performance Issues
PStack
PL/SQL Profiler
OS Watcher
LTOM
Trace/Result Interpretation
Performance (and other) Webcasts
Performance and Scalability White Papers and Documentation
Interacting With Performance Support
Community: Database Tuning
References

Applies to:

Oracle Database - Standard Edition - Version 7.0.16.0 and later
Oracle Database - Personal Edition - Version 7.1.4.0 and later
Oracle Database - Enterprise Edition - Version 6.0.0.0 and later
Enterprise Manager for Oracle Database - Version 8.1.7.4 and later
Information in this document applies to any platform.

Purpose

This Document provides an overview reference to content that pertains to the resolution of Performance issues affecting the whole database.

For the Database Performance Frequently Asked Questions FAQ,information regarding Performance Related Features or  issues involving individual SQL statements, see:
Document 1360119.1 FAQ: Database Performance Frequently Asked Questions
Document 1361401.1 Where to Find Information About Performance Related Features

Document 199083.1 Master Note: SQL Query Performance Overview
Document 1516494.2 Information Center: SQL Query Performance Overview
Document 398838.1 FAQ: SQL Query Performance - Frequently Asked Questions

Questions and Answers

Pro-Active Problem Avoidance and Diagnostic Collection

Although some problems may be unforeseen, in many cases problems may be avoidable if signs are detected early enough. Additionally, if an issue does occur, it is no use collecting information about that issue after the event. For information on suggested preparations to avoid issues and in case diagnostics are required, see:
Document 1482811.1 Best Practices: Proactively Avoiding Database and Query Performance Issues
Document 1477599.1 Best Practices Around Data Collection For Performance Issues

Performance Information Centres

Performance Information Centres provide access to various aspects of performance issues:
Document 1512292.2 Information Center: Database Performance Overview
Document 1516494.2 Information Center: SQL Query Performance Overview

Troubleshooting Guides

There are a number of troubleshooting guides that can help resolve various issues:
Document 1543445.2 Troubleshooting Assistant: Troubleshooting Performance Issues
Document 1542678.2 Troubleshooting Assistant: SQL Performance Issues

Document 1528847.1 Troubleshooting: Avoiding and Resolving Database Performance Related Issues After Upgrade
Document 60.1 Troubleshooting Assistant: Oracle Database ORA-00060 Errors on Single Instance (Non-RAC) Diagnosing Using Deadlock Graphs in ORA-00060 Trace Files

Common Problem Topics

  • Slow Database Performance

    If the database is performing slowly see the following:

    Document 1362329.1 How To Investigate Slow Database Performance Issues
  • Concurrency Issues

    If you have problems with the concurrency of transactions, initially treat this as a "Slow Database Performance" issue and refer to the following:

    Document 1362329.1 How To Investigate Slow Database Performance Issues
  • Database Hangs/Spins

    If the database encounters what looks like a hang or a spin conditions refer to the following:

    Document 452358.1 How to Collect Diagnostics for Database Hanging Issues
    Document 68738.1 No Response from the Server, Does it Hang or Spin?

    Document 392037.1 Database Hangs. Sessions wait for 'resmgr:cpu quantum'
  • Session Hangs/Spins

    If an individual session appears to hang or spin conditions refer to the relevant sections in the following articles:

    Document 1362329.1 How To Investigate Slow Database Performance Issues
    Document 352648.1 How to Diagnose high CPU usage problems
  • Locking Issues

    If sessions encounter locking conflicts refer to the following:

    Document 1392319.1 Master Note: Locks, Enqueues and Deadlocks
    Document 15476.1 FAQ about Detecting and Resolving Locking Conflicts

    Document 62354.1 TX Transaction locks - Example wait scenarios
    Document 33453.1 REFERENTIAL INTEGRITY AND LOCKING
    • Deadlock

      ORA-60 is an application error which usually occurs because a consistent locking strategy has not been followed throughout an application.

      Please refer to the following articles for more information:

      Document 1509919.1 Master Note for Database Error ORA-00060
      Document 18251.1 OERR: ORA 60 "deadlock detected while waiting for resource"
      Document 62365.1 What to do with "ORA-60 Deadlock Detected" Errors

      Please ensure that you are encountering none of the conditions in these articles.
  • Pre-Upgrade Planning

    For upgrades to 11g, there is a useful webcast entitled "11G Upgrade Best Practices" :
    This recorded seminar provides an overview of tips and best practices for upgrading your database to 11G. It starts with general Challenges and Support Best Practices, but moves on to performance specifics such as AWR and STATSPACK, SQL Plan Management, and Real Application Testing.

    This webcast can be found here:


    For advice on planning your upgrade see:

    Document 785351.1 Oracle 11gR2 Upgrade Companion
    Document 601807.1 Oracle 11gR1 Upgrade Companion
    Document 466181.1 10g Upgrade Companion

    Document 465787.1 Managing CBO Stats during an upgrade to 10g or 11g

    For more general upgrade related information see:

    Document 1392633.1 Things to Consider before upgrading to 11.2.0.3 to avoid performance or wrong results
    Document 1320966.1 Things to Consider before upgrading to 11.2.0.2 to avoid performance or wrong results

    Document 1464274.1 Master Note for Real Application Testing Option
    Document 762540.1 Consolidated Reference List Of Notes For Migration / Upgrade Service Requests
  • Post-Upgrade Performance Issue Resolution

    To troubleshoot performance issues encountered after upgrading a database see:
    Document 1528847.1 Troubleshooting: Avoiding and Resolving Database Performance Related Issues After Upgrade
  • Debugging Waits for Various Events

    There are numerous articles to help you debug issues with wait event contention. The most common of these being:

    Library Cache/Mutex Contention/Cursor Type Events:

    Document 1356828.1 FAQ: 'cursor: mutex ..' / 'cursor: pin ..' / 'library cache: mutex ..' Type Wait Events
    Document 1377998.1 Troubleshooting: Waits for Mutex Type Events
    Document 1349387.1 Troubleshooting 'cursor: pin S wait on X' waits
    Document 1357946.1 Troubleshooting 'library cache: mutex X' waits.

    Other Types:

    Document 1376916.1 Troubleshooting: "Log File Sync" Waits

    Document 1342917.1 Troubleshooting 'latch: cache buffers chains' Wait Contention
    Document 34405.1 WAITEVENT: "buffer busy waits" Reference Note

    Document 223117.1 Troubleshooting I/O-related waits

    Document 1415999.1 Troubleshooting: Virtual Circuit Waits
  • Common Causes of Performance issues

    • Cursor Sharing/High Version Counts for Cursors

      The failure to share cursors effectively can have a highly detrimental affect on a database. For example, having hundreds of versions of the same cursor is likely to be wasting space, is unlikely to promote good performance and, in extreme cases, can cause contention issues.
      For issues linked to Cursor related waits see:

      Document 1356828.1 FAQ: 'cursor: mutex ..' / 'cursor: pin ..' / 'library cache: mutex ..' Type Wait Events

      Also, see the following articles for more information and help with troubleshooting issues:

      Document 296377.1Troubleshooting: High Version Count Issues
      Document 438755.1 High SQL Version Counts - Script to determine reason(s)

      Document 62143.1 Understanding and Tuning the Shared Pool
    • High CPU usage

      In cases where CPU usage of individual sessions or the whole database is high, refer to the following:

      Document 352648.1 How to Diagnose High CPU Usage Problems to the Module Level
      Document 273646.1 How to diagnose the high CPU utilization of ORACLE.EXE in Windows environment

      Note that High CPU usage can be caused by many factors including contention for cursors (see above), inefficient SQL and may be associated with excessive buffer reads etc.
    • Issues With waits for 'log file sync'

      If your system is waiting for the redo log files to synchronise with the disk, the following articles can help:

      Document 1376916.1 Troubleshooting: "Log File Sync" Waits

      Document 34592.1 WAITEVENT: "log file sync" Reference Note

      Document 857576.1 How to Minimise Waits for 'Log File Sync'?
      Document 1278149.1 High Log File Sync Wait Events, LGWR Posting Slow Write Times, Low IO Waits

      Document 1064487.1 Script to Collect Log File Sync Diagnostic Information (lfsdiag.sql)
  • WAITED TOO LONG FOR A ROW CACHE ENQUEUE LOCK!

    This Issue occurs when the database detects that a waiter has waited for a resource for longer than a particular threshold. The message "WAITED TOO LONG FOR A ROW CACHE ENQUEUE LOCK!" appears in the alert log and trace and systemstates are dumped.

    Typically this is caused by two (or more) incompatible operations being run simltaneously. See:

    Document 278316.1 Troubleshooting: "WAITED TOO LONG FOR A ROW CACHE ENQUEUE LOCK!"
  • Buffer Busy/Cache Buffers Chains Latch waits

    Buffer Busy waits occur when a session wants to access a database block in the buffer cache but it cannot as the buffer is "busy".

    Cache Buffers Chains Latch waits are caused by contention where multiple sessions waiting to read the same block.

    Typical solutions are to look for SQL that accesses the blocks in question and determine if the repeated reads are necessary.

    Document 1342917.1 Troubleshooting 'latch: cache buffers chains' Wait Contention

    Document 34405.1 WAITEVENT: "buffer busy waits" Reference Note
    Document 155971.1 Resolving Intense and "Random" Buffer Busy Wait Performance Problems:
    Document 163424.1 How To Identify a Hot Block Within The Database Buffer Cache
  • SYSAUX Issues

    SYSAUX is a mandatory tablespace in 10g which stores all auxiliary database metadata related to various product options and features. Of particular interest to Performance is the storage of Automatic Workload Repository (AWR) data:

    Document 552880.1 General Guidelines for SYSAUX Space Issues

    Document 1055547.1 SYSAUX Grows Because Optimizer Stats History is Not Purged
    Document 387914.1 WRH$_ACTIVE_SESSION_HISTORY Does Not Get Purged

    Document 554831.1 How to Control the Set of Top SQLs Captured During AWR Snapshot Generation
    Document 1292724.1 SYSAUX Tablespace Grows Rapidly

Performance Diagnostics References

  • Errorstacks for Performance Issues

    Document 1364257.1 How to Collect Errorstacks for use in Diagnosing Performance Issues
  • PStack

    Document 70609.1  How To Display Information About Processes on SUN Solaris
  • PL/SQL Profiler

    Document 243755.1 Implementing and Using the PL/SQL Profiler
  • OS Watcher

    OS Watcher (OSW) is a collection of UNIX shell scripts intended to collect and archive operating system and network metrics to aid support in diagnosing performance issues.

    Document 301137.1 OS Watcher User Guide
  • LTOM

    The Lite Onboard Monitor (LTOM) is a java program designed as a proactive, real-time diagnostic platform and provides real-time automatic problem detection and data collection.

    Document 352363.1 LTOM - The On-Board Monitor User Guide
    Document 461050.1 The LTOM Graph (LTOMg) User Guide
    Document 461228.1 The LTOM Graph FAQ

    Document 461052.1 LTOM System Profiler - Sample Output
    Document 977975.1 Diagnose LTOM Connection Problems
  • Trace/Result Interpretation

    The following articles can help with the interpretation of various diagnostics:

    Document 390374.1 - Oracle Performance Diagnostic Guide (OPDG)
    Document 39817.1 Interpreting Raw SQL_TRACE and DBMS_SUPPORT.START_TRACE output

    http://www.oracle.com/technetwork/database/focus-areas/performance/statspack-opm4-134117.pdf

Performance (and other) Webcasts

A series of Performance (and General Datbase topic) related webcasts, including topics such as SQLHC, SQLTXPLAIN and OSWBB, can be found here:
Document 1456176.1 Oracle Database Advisor Webcast Archives

Performance and Scalability White Papers and Documentation

Performance and Scalability White Papers:
http://www.oracle.com/technetwork/database/focus-areas/performance/index.html
For White papers concerning Real Application Testing (RAT) and SQL Performance Analyzer (SPA) see:
Document 1546337.1 Real Application Testing (RAT): Recommended White Papers
Links to the main Tuning and Performance documentation:
Document 1195363.1 Database Performance and SQL Tuning Documentation on OTN

Interacting With Performance Support

Document 210014.1 How to Log a Good Performance Service Request
Document 166650.1 Working Effectively With Global Customer Support

Community: Database Tuning

A community has been set up for My Oracle Support (MOS) users moderated by Oracle. The goal of this community is to exchange database related Tuning knowledge and concepts. The community can be found via the following article:
Document 1383594.1 Collaborate With MOS Database Tuning Community Members

References

NOTE:1320966.1 - Things to Consider Before Upgrading to 11.2.0.2 to Avoid Poor Performance or Wrong Results
NOTE:461228.1 - The LTOM Graph FAQ
NOTE:175006.1 - Steps to generate HANGANALYZE trace files (9i and below)
NOTE:18251.1 - OERR: ORA 60 "deadlock detected while waiting for resource"
NOTE:452358.1 - How to Collect Diagnostics for Database Hanging Issues
NOTE:199083.1 - * Master Note: SQL Query Performance Overview
NOTE:223117.1 - Troubleshooting I/O-related waits
NOTE:68738.1 - No Response from the Server, Does it Hang or Spin?

NOTE:387914.1 - WRH$_ACTIVE_SESSION_HISTORY Does Not Get Purged
NOTE:390374.1 - Oracle Performance Diagnostic Guide (OPDG)
NOTE:392037.1 - Database 'Hangs'. Sessions Wait for 'resmgr:cpu quantum'
NOTE:166650.1 - Working Effectively With Support Best Practices
NOTE:461050.1 - The LTOM Graph (LTOMg) User Guide
NOTE:1357946.1 - Troubleshooting 'library cache: mutex X' waits.
NOTE:352648.1 - How to Diagnose High CPU Usage Problems to the Module Level
NOTE:554831.1 - How to Control the Set of Top SQLs Captured During AWR Snapshot Generation
NOTE:398838.1 - FAQ: SQL Query Performance - Frequently Asked Questions
NOTE:465787.1 - How to: Manage CBO Statistics During an Upgrade from 10g or 9i into 11g
NOTE:376442.1 - * How To Collect 10046 Trace (SQL_TRACE) Diagnostics for Performance Issues
NOTE:39817.1 - Interpreting Raw SQL_TRACE output
NOTE:62365.1 - Troubleshooting "ORA-00060 Deadlock Detected" Errors
NOTE:785351.1 - Oracle 11gR2 Upgrade Companion
NOTE:857576.1 - How to Minimise Waits for 'Log File Sync'
NOTE:94224.1 - FAQ- Statspack Complete Reference
NOTE:70609.1 - How To Display Information About Processes on SUN Solaris
NOTE:977975.1 - Diagnose LTOM Connection Problems
NOTE:1055547.1 - SYSAUX Grows Because Optimizer Stats History is Not Purged
NOTE:34592.1 - WAITEVENT: "log file sync" Reference Note
NOTE:352363.1 - LTOM - The On-Board Monitor User Guide
NOTE:601807.1 - Oracle 11gR1 Upgrade Companion
NOTE:210014.1 - How to Log a Good Performance Service Request
NOTE:1377446.1 - * Troubleshooting Performance Issues
NOTE:243755.1 - Script to produce HTML report with top consumers out of PL/SQL Profiler DBMS_PROFILER data
NOTE:1528847.1 - Troubleshooting: Avoiding and Resolving Database Performance Related Issues After Upgrade
NOTE:1392633.1 - Things to Consider Before Upgrading to 11.2.0.3 to Avoid Poor Performance or Wrong Results
NOTE:466181.1 - Oracle 10g Upgrade Companion
NOTE:1361401.1 - Where to Find Information About Performance Related Features
NOTE:1362329.1 - How To Investigate Slow or Hanging Database Performance Issues
NOTE:1363422.1 - Automatic Workload Repository (AWR) Reports - Start Point
NOTE:1364257.1 - How to Collect Errorstacks for use in Diagnosing Performance Issues.
NOTE:163424.1 - How To Identify a Hot Block Within The Database Buffer Cache.
NOTE:1360119.1 - * FAQ: Database Performance Frequently Asked Questions
NOTE:552880.1 - General Guidelines for SYSAUX Space Issues
NOTE:1278149.1 - Intermittent Long 'log file sync' Waits, LGWR Posting Long Write Times, I/O Portion of Wait Minimal

NOTE:1195363.1 - Database Performance and SQL Tuning Documentation on OTN
NOTE:121779.1 - Taking Systemstate Dumps when You cannot Connect to Oracle
NOTE:62143.1 - Troubleshooting: Tuning the Shared Pool and Tuning Library Cache Latch Contention
NOTE:1415999.1 - Troubleshooting: Virtual Circuit Waits

NOTE:1064487.1 - Script to Collect Log File Sync Diagnostic Information (lfsdiag.sql)
NOTE:438452.1 - Performance Tools Quick Reference Guide
NOTE:438755.1 - High SQL Version Counts - Script to determine reason(s)
NOTE:461052.1 - LTOM System Profiler - Sample Output
NOTE:278316.1 - Troubleshooting: "WAITED TOO LONG FOR A ROW CACHE ENQUEUE LOCK! "
NOTE:15476.1 - FAQ: Detecting and Resolving Locking Conflicts and Ora-00060 errors
NOTE:1392319.1 - Master Note: Locks, Enqueues and Deadlocks (ORA-00060)
NOTE:155971.1 - Resolving Intense and "Random" Buffer Busy Wait Performance Problems
NOTE:1376916.1 - Troubleshooting: "log file sync" Waits
NOTE:1292724.1 - Suggestions if your SYSAUX Tablespace grows rapidly or too large
NOTE:62354.1 - Waits for 'Enq: Tx - Row Lock Contention' - Wait Scenario Examples
NOTE:1377998.1 - Troubleshooting: Waits for Mutex Type Events
NOTE:1383594.1 - Collaborate with MOS Database Tuning Community Members
NOTE:762540.1 - Consolidated Reference List Of Notes For Migration / Upgrade Service Requests
NOTE:1356828.1 - FAQ: 'cursor: mutex ..' / 'cursor: pin ..' / 'library cache: mutex ..' Type Wait Events
NOTE:1509919.1 - Master Note for Database Error ORA-00060 "deadlock detected while waiting for resource"

NOTE:781198.1 - Diagnostics for Database Performance Issues
NOTE:273646.1 - How to Diagnose High CPU Utilization of ORACLE.EXE in Windows Environment
NOTE:1342917.1 - Troubleshooting 'latch: cache buffers chains' Wait Contention
NOTE:1349387.1 - Troubleshooting 'cursor: pin S wait on X' waits.
NOTE:296377.1 - Troubleshooting: High Version Count Issues
NOTE:301137.1 - OSWatcher Black Box (Includes: [Video])
NOTE:33453.1 - Locking and Referential Integrity 
NOTE:34405.1 - WAITEVENT: "buffer busy waits" Reference Note

SQL trace

SQL trace, 10046, trcsess and tkprof in Oracle

Generating SQL Trace Files

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=>' ');

-- Available from SQL*Plus since 8i (commandline utility prior to this.
SQL> CONN sys/password AS SYSDBA;  -- User must have SYSDBA.
SQL> ORADEBUG SETMYPID;            -- Debug current session.
SQL> ORADEBUG SETOSPID 1234;       -- Debug session with the specified OS process.
SQL> ORADEBUG SETORAPID 123456;    -- Debug session with the specified Oracle process ID.

SQL> ORADEBUG EVENT 10046 TRACE NAME CONTEXT FOREVER, LEVEL 12;
SQL> ORADEBUG TRACEFILE_NAME;      -- Display the current trace file.
SQL> ORADEBUG EVENT 10046 TRACE NAME CONTEXT OFF;
 
-- 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_in_session(sid=>123, serial=>1234, waits=>TRUE, binds=>FALSE);
SQL> EXEC DBMS_SUPPORT.stop_trace_in_session(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 just 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 theV$SESSION view, set using the DBMS_SESSION package. Second, trace can be activated for multiple sessions based on various combinations of the service_name, module, action columns in the V$SESSIONview, 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.

Tracing Individual SQL Statements

SQL trace can be initiated for an individual SQL statement by substituting the required SQL_ID into the following statement.
SQL> ALTER SESSION SET EVENTS 'trace[rdbms.SQL_Optimizer.*][sql:sql_id]';
The SQL_ID of a statement can be found in the V$SQL or V$SQLSTAT view for recent SQL, or from the DBA_HIST_SQLSTAT view from the AWR repository for historical statements.

Identifying Trace Files

Oracle allows you to set the TRACEFILE_IDENTIFIER parameter at session level, allowing you to include some recognizable text into the trace file name.
ALTER SESSION SET TRACEFILE_IDENTIFIER = "MY_TEST_SESSION";
Even without this, we can easily identify the trace file for the current session using the USER_DUMP_DEST value with the instance name and the session's process id. The identify_trace_file.sql script combines these values to produce the expected trace file name.
SET LINESIZE 100
COLUMN trace_file FORMAT A60

SELECT s.sid,
       s.serial#,
       pa.value || '/' || LOWER(SYS_CONTEXT('userenv','instance_name')) ||    
       '_ora_' || p.spid || '.trc' AS trace_file
FROM   v$session s,
       v$process p,
       v$parameter pa
WHERE  pa.name = 'user_dump_dest'
AND    s.paddr = p.addr
AND    s.audsid = SYS_CONTEXT('USERENV', 'SESSIONID');
If you are using a windows environment you will need to alter the "/" to a "\" in the concatenated string.
Note. Identification of trace files is simpler in Oracle 11g due to the introduction of diagnostic views. The Oracle 11g version of the identify_trace_file.sql is shown below.
SET LINESIZE 100
COLUMN value FORMAT A60

SELECT value
FROM   v$diag_info
WHERE  name = 'Default Trace File';

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, which allows trace information from multiple trace files to be identified and consolidated into a single trace file. The trcsess usage is listed below.
trcsess [output=]  [session=] [clientid=]
        [service=] [action=] [module=] 

output= output destination default being standard output.
session= session to be traced.
Session id is a combination of session Index & session serial number e.g. 8.13.
clientid= clientid to be traced.
service= service to be traced.
action= action to be traced.
module= module to be traced.
 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 to give you an idea of the whole process.

Trace Example

The following script creates a test table and a procedure that populates it. This procedure will be the subject of our example trace.
CREATE TABLE sql_trace_test (
  id  NUMBER,
  description  VARCHAR2(50)
);

EXEC DBMS_STATS.gather_table_stats('test', 'sql_trace_test');

CREATE OR REPLACE PROCEDURE populate_sql_trace_test (p_loops  IN  NUMBER) AS
  l_number  NUMBER;
BEGIN
  FOR i IN 1 .. p_loops LOOP
    INSERT INTO sql_trace_test (id, description)
    VALUES (i, 'Description for ' || i);
  END LOOP;
  
  SELECT COUNT(*)
  INTO   l_number
  FROM   sql_trace_test;
  
  COMMIT;
  
  DBMS_OUTPUT.put_line(l_number || ' rows inserted.');
END;
/
SHOW ERRORS
Gathering the statistics on the empty table may seem odd, but this prevents any dynamic sampling being added to the trace file contents, which would only serve to complicate the file.
Next, we identify the trace file for the current session.
SQL> @identify_trace_file.sql

       SID    SERIAL# TRACE_FILE
---------- ---------- ------------------------------------------------------------
       130      26739 /u01/app/oracle/admin/DEV/udump/dev1_ora_367660.trc

1 row selected.

SQL>
Now we know the name of the trace file we can enable tracing, execute the procedure and disable tracing.
SQL> ALTER SESSION SET EVENTS '10046 trace name context forever, level 8';

Session altered.

SQL> SET SERVEROUTPUT ON
SQL> EXEC populate_sql_trace_test(p_loops => 5);
5 rows inserted.

PL/SQL procedure successfully completed.

SQL> ALTER SESSION SET EVENTS '10046 trace name context off';

Session altered.

SQL>
The contents of the file are listed below. The output looks a little confusing, but you can identify the individual statements and their associated waits and statistics.
/u01/app/oracle/admin/DEV/udump/dev1_ora_367660.trc
Oracle Database 10g Enterprise Edition Release 10.1.0.3.0 - Production
With the Partitioning, Oracle Label Security, OLAP and Data Mining options
ORACLE_HOME = /u01/app/oracle/product/10.1.0/db_1
System name: OSF1
Node name: dbserver.oracle-base.com
Release: V5.1
Version: 2650
Machine: alpha
Instance name: DEV1
Redo thread mounted by this instance: 1
Oracle process number: 16
Unix process pid: 367660, image: oracleDEV1@dbserver.oracle-base.com

*** 2005-04-05 09:46:51.499
*** ACTION NAME:() 2005-04-05 09:46:51.499
*** MODULE NAME:(SQL*Plus) 2005-04-05 09:46:51.499
*** SERVICE NAME:(SYS$USERS) 2005-04-05 09:46:51.499
*** SESSION ID:(130.26739) 2005-04-05 09:46:51.499
=====================
PARSING IN CURSOR #29 len=68 dep=0 uid=180 oct=42 lid=180 tim=11746409761792 hv=3847243385 ad='2bb57798'
ALTER SESSION SET EVENTS '10046 trace name context forever, level 8'
END OF STMT
EXEC #29:c=0,e=1024,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,tim=11746409761792
WAIT #29: nam='SQL*Net message to client' ela= 0 p1=1413697536 p2=1 p3=0
WAIT #29: nam='SQL*Net message from client' ela= 7358464 p1=1413697536 p2=1 p3=0
=====================
PARSING IN CURSOR #4 len=36 dep=0 uid=180 oct=47 lid=180 tim=11746417122304 hv=3425213768 ad='2c631cd8'
BEGIN DBMS_OUTPUT.ENABLE(2000); END;
END OF STMT
PARSE #4:c=0,e=1024,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,tim=11746417122304
EXEC #4:c=0,e=0,p=0,cr=0,cu=0,mis=0,r=1,dep=0,og=1,tim=11746417122304
WAIT #4: nam='SQL*Net message to client' ela= 0 p1=1413697536 p2=1 p3=0
WAIT #4: nam='SQL*Net message from client' ela= 6924288 p1=1413697536 p2=1 p3=0
=====================
PARSING IN CURSOR #18 len=51 dep=0 uid=180 oct=47 lid=180 tim=11746424051712 hv=2083693016 ad='27ecb338'
BEGIN populate_sql_trace_test(p_loops => 5); END;
END OF STMT
PARSE #18:c=0,e=3072,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=1,tim=11746424051712
=====================
PARSING IN CURSOR #19 len=86 dep=1 uid=180 oct=2 lid=180 tim=11746424052736 hv=3247833140 ad='28fa57f8'
INSERT INTO SQL_TRACE_TEST (ID, DESCRIPTION) VALUES (:B1 , 'Description for ' || :B1 )
END OF STMT
PARSE #19:c=0,e=1024,p=0,cr=0,cu=0,mis=1,r=0,dep=1,og=1,tim=11746424052736
=====================
PARSING IN CURSOR #23 len=69 dep=2 uid=0 oct=3 lid=0 tim=11746424053760 hv=1471956217 ad='2e7591f0'
select con#,obj#,rcon#,enabled,nvl(defer,0) from cdef$ where robj#=:1
END OF STMT
PARSE #23:c=0,e=1024,p=0,cr=0,cu=0,mis=1,r=0,dep=2,og=4,tim=11746424053760
EXEC #23:c=0,e=5120,p=0,cr=0,cu=0,mis=1,r=0,dep=2,og=4,tim=11746424059904
FETCH #23:c=0,e=0,p=0,cr=2,cu=0,mis=0,r=0,dep=2,og=4,tim=11746424059904
=====================
PARSING IN CURSOR #25 len=146 dep=2 uid=0 oct=3 lid=0 tim=11746424065024 hv=2107929772 ad='2e7b4b08'
select con#,type#,condlength,intcols,robj#,rcon#,match#,refact,nvl(enabled,0),rowid,cols,nvl(defer,0)
,mtime,nvl(spare1,0) from cdef$ where obj#=:1
END OF STMT
PARSE #25:c=0,e=5120,p=0,cr=0,cu=0,mis=1,r=0,dep=2,og=4,tim=11746424065024
=====================
PARSING IN CURSOR #27 len=210 dep=3 uid=0 oct=3 lid=0 tim=11746424102912 hv=864012087 ad='2e351f08'
select /*+ rule */ bucket_cnt, row_cnt, cache_cnt, null_cnt, timestamp#, sample_size, minimum, maximum,
distcnt, lowval, hival, density, col#, spare1, spare2, avgcln from hist_head$ where obj#=:1 and intcol#=:2
END OF STMT
PARSE #27:c=50000,e=36864,p=0,cr=0,cu=0,mis=1,r=0,dep=3,og=3,tim=11746424102912
EXEC #27:c=16667,e=4096,p=0,cr=0,cu=0,mis=1,r=0,dep=3,og=3,tim=11746424108032
FETCH #27:c=0,e=1024,p=0,cr=3,cu=0,mis=0,r=1,dep=3,og=3,tim=11746424109056
EXEC #27:c=0,e=0,p=0,cr=0,cu=0,mis=0,r=0,dep=3,og=3,tim=11746424109056
FETCH #27:c=0,e=0,p=0,cr=3,cu=0,mis=0,r=1,dep=3,og=3,tim=11746424109056
EXEC #27:c=0,e=0,p=0,cr=0,cu=0,mis=0,r=0,dep=3,og=3,tim=11746424110080
FETCH #27:c=0,e=0,p=0,cr=3,cu=0,mis=0,r=1,dep=3,og=3,tim=11746424110080
=====================
PARSING IN CURSOR #28 len=121 dep=3 uid=0 oct=3 lid=0 tim=11746424119296 hv=3150898423 ad='2e347db8'
select /*+ rule */ bucket, endpoint, col#, epvalue from histgrm$ where obj#=:1 and intcol#=:2 and row#=:3
order by bucket
END OF STMT
PARSE #28:c=0,e=9216,p=0,cr=0,cu=0,mis=1,r=0,dep=3,og=3,tim=11746424119296
EXEC #28:c=0,e=1024,p=0,cr=0,cu=0,mis=1,r=0,dep=3,og=3,tim=11746424121344
FETCH #28:c=0,e=1024,p=0,cr=3,cu=0,mis=0,r=3,dep=3,og=3,tim=11746424122368
EXEC #27:c=0,e=0,p=0,cr=0,cu=0,mis=0,r=0,dep=3,og=3,tim=11746424122368
FETCH #27:c=0,e=0,p=0,cr=3,cu=0,mis=0,r=1,dep=3,og=3,tim=11746424122368
EXEC #27:c=0,e=0,p=0,cr=0,cu=0,mis=0,r=0,dep=3,og=3,tim=11746424123392
FETCH #27:c=0,e=0,p=0,cr=3,cu=0,mis=0,r=1,dep=3,og=3,tim=11746424123392
EXEC #25:c=83334,e=61440,p=0,cr=18,cu=0,mis=1,r=0,dep=2,og=4,tim=11746424126464
FETCH #25:c=0,e=0,p=0,cr=2,cu=0,mis=0,r=0,dep=2,og=4,tim=11746424126464
=====================
PARSING IN CURSOR #12 len=169 dep=2 uid=0 oct=3 lid=0 tim=11746424128512 hv=1173719687 ad='2e7c2c50'
select col#, grantee#, privilege#,max(mod(nvl(option$,0),2)) from objauth$ where obj#=:1 and col# is not null
group by privilege#, col#, grantee# order by col#, grantee#
END OF STMT
PARSE #12:c=0,e=1024,p=0,cr=0,cu=0,mis=1,r=0,dep=2,og=4,tim=11746424128512
EXEC #12:c=0,e=3072,p=0,cr=0,cu=0,mis=1,r=0,dep=2,og=4,tim=11746424131584
FETCH #12:c=0,e=0,p=0,cr=2,cu=0,mis=0,r=0,dep=2,og=4,tim=11746424131584
=====================
PARSING IN CURSOR #26 len=151 dep=2 uid=0 oct=3 lid=0 tim=11746424131584 hv=4139184264 ad='2e7cc608'
select grantee#,privilege#,nvl(col#,0),max(mod(nvl(option$,0),2))from objauth$ where obj#=:1 group by grantee#,
privilege#,nvl(col#,0) order by grantee#
END OF STMT
PARSE #26:c=0,e=0,p=0,cr=0,cu=0,mis=0,r=0,dep=2,og=4,tim=11746424131584
EXEC #26:c=0,e=0,p=0,cr=0,cu=0,mis=0,r=0,dep=2,og=4,tim=11746424131584
FETCH #26:c=0,e=1024,p=0,cr=2,cu=0,mis=0,r=0,dep=2,og=4,tim=11746424132608
=====================
PARSING IN CURSOR #7 len=175 dep=2 uid=0 oct=3 lid=0 tim=11746424132608 hv=1729330152 ad='2f3597a8'
select u.name,o.name, t.update$, t.insert$, t.delete$, t.enabled  from obj$ o,user$ u,trigger$ t  where 
t.baseobject=:1 and t.obj#=o.obj# and o.owner#=u.user#  order by o.obj#
END OF STMT
PARSE #7:c=0,e=0,p=0,cr=0,cu=0,mis=0,r=0,dep=2,og=4,tim=11746424132608
EXEC #7:c=0,e=0,p=0,cr=0,cu=0,mis=0,r=0,dep=2,og=4,tim=11746424132608
FETCH #7:c=0,e=0,p=0,cr=2,cu=0,mis=0,r=0,dep=2,og=4,tim=11746424132608
STAT #7 id=1 cnt=0 pid=0 pos=1 obj=0 op='SORT ORDER BY (cr=2 pr=0 pw=0 time=0 us)'
STAT #7 id=2 cnt=0 pid=1 pos=1 obj=0 op='NESTED LOOPS  (cr=2 pr=0 pw=0 time=0 us)'
STAT #7 id=3 cnt=0 pid=2 pos=1 obj=0 op='NESTED LOOPS  (cr=2 pr=0 pw=0 time=0 us)'
STAT #7 id=4 cnt=0 pid=3 pos=1 obj=84 op='TABLE ACCESS BY INDEX ROWID TRIGGER$ (cr=2 pr=0 pw=0 time=0 us)'
STAT #7 id=5 cnt=0 pid=4 pos=1 obj=128 op='INDEX RANGE SCAN I_TRIGGER1 (cr=2 pr=0 pw=0 time=0 us)'
STAT #7 id=6 cnt=0 pid=3 pos=2 obj=18 op='TABLE ACCESS BY INDEX ROWID OBJ$ (cr=0 pr=0 pw=0 time=0 us)'
STAT #7 id=7 cnt=0 pid=6 pos=1 obj=36 op='INDEX UNIQUE SCAN I_OBJ1 (cr=0 pr=0 pw=0 time=0 us)'
STAT #7 id=8 cnt=0 pid=2 pos=2 obj=22 op='TABLE ACCESS CLUSTER USER$ (cr=0 pr=0 pw=0 time=0 us)'
STAT #7 id=9 cnt=0 pid=8 pos=1 obj=11 op='INDEX UNIQUE SCAN I_USER# (cr=0 pr=0 pw=0 time=0 us)'
EXEC #19:c=83334,e=86016,p=0,cr=29,cu=21,mis=1,r=1,dep=1,og=1,tim=11746424138752
EXEC #19:c=0,e=0,p=0,cr=0,cu=1,mis=0,r=1,dep=1,og=1,tim=11746424138752
EXEC #19:c=0,e=0,p=0,cr=0,cu=1,mis=0,r=1,dep=1,og=1,tim=11746424138752
EXEC #19:c=0,e=0,p=0,cr=0,cu=1,mis=0,r=1,dep=1,og=1,tim=11746424139776
EXEC #19:c=0,e=0,p=0,cr=0,cu=1,mis=0,r=1,dep=1,og=1,tim=11746424139776
=====================
PARSING IN CURSOR #29 len=35 dep=1 uid=180 oct=3 lid=180 tim=11746424140800 hv=3788777626 ad='2c84eb58'
SELECT COUNT(*) FROM SQL_TRACE_TEST
END OF STMT
PARSE #29:c=0,e=1024,p=0,cr=0,cu=0,mis=1,r=0,dep=1,og=1,tim=11746424140800
EXEC #29:c=0,e=1024,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=1,tim=11746424141824
FETCH #29:c=0,e=0,p=0,cr=7,cu=0,mis=0,r=1,dep=1,og=1,tim=11746424141824
=====================
PARSING IN CURSOR #4 len=6 dep=1 uid=180 oct=44 lid=180 tim=11746424141824 hv=255718823 ad='2e5363f0'
COMMIT
END OF STMT
PARSE #4:c=0,e=0,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=1,tim=11746424141824
XCTEND rlbk=0, rd_only=0
EXEC #4:c=0,e=0,p=0,cr=0,cu=1,mis=0,r=0,dep=1,og=1,tim=11746424141824
EXEC #18:c=83334,e=91136,p=0,cr=36,cu=26,mis=0,r=1,dep=0,og=1,tim=11746424142848
WAIT #18: nam='SQL*Net message to client' ela= 0 p1=1413697536 p2=1 p3=0
WAIT #18: nam='SQL*Net message from client' ela= 1024 p1=1413697536 p2=1 p3=0
=====================
PARSING IN CURSOR #7 len=52 dep=0 uid=180 oct=47 lid=180 tim=11746424143872 hv=1029988163 ad='2c2ec1b8'
BEGIN DBMS_OUTPUT.GET_LINES(:LINES, :NUMLINES); END;
END OF STMT
PARSE #7:c=0,e=0,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,tim=11746424143872
WAIT #7: nam='SQL*Net message to client' ela= 0 p1=1413697536 p2=1 p3=0
EXEC #7:c=0,e=0,p=0,cr=0,cu=0,mis=0,r=1,dep=0,og=1,tim=11746424144896
WAIT #7: nam='SQL*Net message from client' ela= 8560640 p1=1413697536 p2=1 p3=0
=====================
PARSING IN CURSOR #12 len=55 dep=0 uid=180 oct=42 lid=180 tim=11746432706560 hv=2655499671 ad='2a24eab8'
ALTER SESSION SET EVENTS '10046 trace name context off'
END OF STMT
PARSE #12:c=0,e=0,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,tim=11746432705536
EXEC #12:c=0,e=0,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,tim=11746432706560
The following command uses the tkprof utility to translate the trace file, placing the translated output in the translated.txt file.The explain and table parameters have been set to allow execution plans to be displayed and the sys parameter prevents recursive SQL being displayed.
$ cd /u01/app/oracle/admin/DEV/udump/
$ tkprof dev1_ora_367660.trc translated.txt explain=test/test table=sys.plan_table sys=no waits=yes

TKPROF: Release 10.1.0.3.0 - Production on Tue Apr 5 09:22:43 2005

Copyright (c) 1982, 2004, Oracle.  All rights reserved.


$
The contents of the translated file are displayed below.
TKPROF: Release 10.1.0.3.0 - Production on Tue Apr 5 09:53:50 2005

Copyright (c) 1982, 2004, Oracle.  All rights reserved.

Trace file: dev1_ora_367660.trc
Sort options: default

********************************************************************************
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
********************************************************************************

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


call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        0      0.00       0.00          0          0          0           0
Execute      1      0.00       0.00          0          0          0           0
Fetch        0      0.00       0.00          0          0          0           0
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        1      0.00       0.00          0          0          0           0

Misses in library cache during parse: 0
Optimizer mode: ALL_ROWS
Parsing user id: 180  (TEST)

Elapsed times include waiting on following events:
  Event waited on                             Times   Max. Wait  Total Waited
  ----------------------------------------   Waited  ----------  ------------
  SQL*Net message to client                       1        0.00          0.00
  SQL*Net message from client                     1        7.35          7.35
********************************************************************************

BEGIN DBMS_OUTPUT.ENABLE(2000); END;


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           1
Fetch        0      0.00       0.00          0          0          0           0
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        2      0.00       0.00          0          0          0           1

Misses in library cache during parse: 0
Optimizer mode: ALL_ROWS
Parsing user id: 180  (TEST)

Elapsed times include waiting on following events:
  Event waited on                             Times   Max. Wait  Total Waited
  ----------------------------------------   Waited  ----------  ------------
  SQL*Net message to client                       1        0.00          0.00
  SQL*Net message from client                     1        6.92          6.92
********************************************************************************

BEGIN populate_sql_trace_test(p_loops => 5); END;


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           1
Fetch        0      0.00       0.00          0          0          0           0
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        2      0.00       0.00          0          0          0           1

Misses in library cache during parse: 1
Optimizer mode: ALL_ROWS
Parsing user id: 180  (TEST)

Elapsed times include waiting on following events:
  Event waited on                             Times   Max. Wait  Total Waited
  ----------------------------------------   Waited  ----------  ------------
  SQL*Net message to client                       1        0.00          0.00
  SQL*Net message from client                     1        0.00          0.00
********************************************************************************

INSERT INTO SQL_TRACE_TEST (ID, DESCRIPTION) 
VALUES
 (:B1 , 'Description for ' || :B1 )


call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.00       0.00          0          0          0           0
Execute      5      0.00       0.00          0          1         25           5
Fetch        0      0.00       0.00          0          0          0           0
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        6      0.00       0.00          0          1         25           5

Misses in library cache during parse: 1
Misses in library cache during execute: 1
Optimizer mode: ALL_ROWS
Parsing user id: 180  (TEST)   (recursive depth: 1)

Rows     Execution Plan
-------  ---------------------------------------------------
      0  INSERT STATEMENT   MODE: ALL_ROWS

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

SELECT COUNT(*) 
FROM
 SQL_TRACE_TEST


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        1      0.00       0.00          0          7          0           1
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        3      0.00       0.00          0          7          0           1

Misses in library cache during parse: 1
Optimizer mode: ALL_ROWS
Parsing user id: 180  (TEST)   (recursive depth: 1)

Rows     Execution Plan
-------  ---------------------------------------------------
      0  SELECT STATEMENT   MODE: ALL_ROWS
      0   SORT (AGGREGATE)
      0    TABLE ACCESS   MODE: ANALYZED (FULL) OF 'SQL_TRACE_TEST' 
               (TABLE)

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

COMMIT


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          1           0
Fetch        0      0.00       0.00          0          0          0           0
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        2      0.00       0.00          0          0          1           0

Misses in library cache during parse: 0
Optimizer mode: ALL_ROWS
Parsing user id: 180  (TEST)   (recursive depth: 1)
********************************************************************************

BEGIN DBMS_OUTPUT.GET_LINES(:LINES, :NUMLINES); END;


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           1
Fetch        0      0.00       0.00          0          0          0           0
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        2      0.00       0.00          0          0          0           1

Misses in library cache during parse: 0
Optimizer mode: ALL_ROWS
Parsing user id: 180  (TEST)

Elapsed times include waiting on following events:
  Event waited on                             Times   Max. Wait  Total Waited
  ----------------------------------------   Waited  ----------  ------------
  SQL*Net message to client                       1        0.00          0.00
  SQL*Net message from client                     1        8.56          8.56
********************************************************************************

ALTER SESSION SET EVENTS '10046 trace name context off'


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        0      0.00       0.00          0          0          0           0
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        2      0.00       0.00          0          0          0           0

Misses in library cache during parse: 0
Optimizer mode: ALL_ROWS
Parsing user id: 180  (TEST)



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

OVERALL TOTALS FOR ALL NON-RECURSIVE STATEMENTS

call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        4      0.00       0.00          0          0          0           0
Execute      5      0.00       0.00          0          0          0           3
Fetch        0      0.00       0.00          0          0          0           0
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        9      0.00       0.00          0          0          0           3

Misses in library cache during parse: 1

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        8.56         22.84


OVERALL TOTALS FOR ALL RECURSIVE STATEMENTS

call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse       10      0.05       0.05          0          0          0           0
Execute     18      0.03       0.03          0          1         26           5
Fetch       12      0.00       0.00          0         35          0           9
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total       40      0.08       0.08          0         36         26          14

Misses in library cache during parse: 7
Misses in library cache during execute: 6

    8  user  SQL statements in session.
    7  internal SQL statements in session.
   15  SQL statements in session.
    2  statements EXPLAINed in this session.
********************************************************************************
Trace file: dev1_ora_367660.trc
Trace file compatibility: 10.01.00
Sort options: default

       1  session in tracefile.
       8  user  SQL statements in trace file.
       7  internal SQL statements in trace file.
      15  SQL statements in trace file.
      15  unique SQL statements in trace file.
       2  SQL statements EXPLAINed using schema:
           sys.plan_table
             Schema was specified.
             Existing table was used.
     146  lines in trace file.
      22  elapsed seconds in trace file.
For each statement executed by the session, the file contains a record of the parse, execute and fetch statistics, an execution plan where necessary and a list of session waits.

Trace Analyzer

In addition to TKPROF, Oracle provide another tool for analyzing SQL trace files called Trace Analyzer. This is available for download from Metalink and can be installed on any version of the database server from Oracle8i upwards.
Trace Analyzer reads a raw SQL Trace file generated by standard SQL Trace or by EVENT 10046 (Level 4, 8 or 12), and generates a comprehensive HTML report with performance related details: time summary, call summary (parse, execute, fetch), identification of top SQL, row source plan, explain plan, CBO statistics, wait events, values of bind variables, I/O summary per schema object, latches, hot blocks, etc.
The HTML report includes all the details found on TKPROF, plus additional information normally requested and used for a transaction performance analysis.

Query Contents of Trace Files

There are a number of ways to make trace files available to developers, but one simple way is to allow them query the contents of a trace file from SQL*Plus and spool it to a file on their local PC.
The following example creates a locked user with the necessary code to read the contents of specified trace files. This code is then made accessible to public and a directory object pointing to the trace location is created.
CONN / AS SYSDBA

-- Create locked user to hold code.
CREATE USER trace_user IDENTIFIED BY trace_user ACCOUNT LOCK;

-- Create a type and pipelined table function to read the specified trace file.
CREATE TYPE trace_user.t_trace_tab AS TABLE OF VARCHAR2(32767);
/

CREATE OR REPLACE FUNCTION trace_user.get_trace_file (p_trace_file IN VARCHAR2)
  RETURN trace_user.t_trace_tab PIPELINED
AS
  l_file UTL_FILE.file_type; 
  l_text VARCHAR2(32767);
BEGIN
  l_file := UTL_FILE.fopen('TRACE_DIR', p_trace_file, 'r', 32767);
  BEGIN
    LOOP
      UTL_FILE.get_line(l_file, l_text);
      PIPE ROW (l_text);
    END LOOP;
  EXCEPTION
    WHEN NO_DATA_FOUND THEN
      NULL;
  END;
  UTL_FILE.fclose(l_file);
  RETURN;
EXCEPTION
  WHEN OTHERS THEN
    PIPE ROW ('ERROR: ' || SQLERRM);
    IF UTL_FILE.is_open(l_file) THEN
      UTL_FILE.fclose(l_file);
    END IF;
    RETURN;
END;
/

-- Make the code accessible to PUBLIC.
GRANT EXECUTE ON trace_user.t_trace_tab TO PUBLIC;
GRANT EXECUTE ON trace_user.get_trace_file TO PUBLIC;
CREATE PUBLIC SYNONYM get_trace_file FOR trace_user.get_trace_file;

-- Create a directory object to the trace location.
CREATE OR REPLACE DIRECTORY trace_dir AS '/u01/app/oracle/diag/rdbms/db11g/DB11G/trace/';
GRANT READ ON DIRECTORY trace_dir TO trace_user;
With that in place we can see how a developer would create and return a trace file to their local PC.
-- Make sure the user has access to DBMS_MONITOR.
CONN / AS SYSDBA
GRANT EXECUTE ON dbms_monitor TO hr;

CONN hr/hr

-- Identify the current trace file.
SELECT value
FROM   v$diag_info
WHERE  name = 'Default Trace File';

VALUE
--------------------------------------------------------------------------------
/u01/app/oracle/diag/rdbms/db11g/DB11G/trace/DB11G_ora_6309.trc

SQL>

-- Turn of tracing.
EXEC DBMS_MONITOR.session_trace_enable(waits=>TRUE, binds=>FALSE);

-- Do something you wish to trace.
SET LINESIZE 100
COLUMN employee_name FORMAT A30
COLUMN department_name FORMAT A20
COLUMN manager_name FORMAT A30

SELECT e.first_name || ' ' || e.last_name AS employee_name,
       d.department_name,
       e2.first_name || ' ' || e2.last_name AS manager_name
FROM   employees e
       JOIN departments d ON e.department_id = d.department_id
       JOIN employees e2 ON e.manager_id = e2.employee_id
WHERE  d.department_name = 'Finance'
ORDER BY d.department_name;

EMPLOYEE_NAME                  DEPARTMENT_NAME      MANAGER_NAME
------------------------------ -------------------- ------------------------------
Nancy Greenberg                Finance              Neena Kochhar
Luis Popp                      Finance              Nancy Greenberg
Jose Manuel Urman              Finance              Nancy Greenberg
Ismael Sciarra                 Finance              Nancy Greenberg
John Chen                      Finance              Nancy Greenberg
Daniel Faviet                  Finance              Nancy Greenberg

6 rows selected.

SQL> 

-- Turn off tracing.
EXEC DBMS_MONITOR.session_trace_disable;

-- Spool the contents of the relevant trace file to a local file.
SET PAGESIZE 0 FEEDBACK OFF TRIMSPOOL ON TAB OFF
SPOOL C:\tracefile.trc

SELECT *
FROM   TABLE(get_trace_file('DB11G_ora_6309.trc'));

SPOOL OFF
SET PAGESIZE 14 FEEDBACK ON
The developer can now use a local installation of TKPROF or SQL Developer to translate the trace file.