Performance Tuning Basics 5 : Trace and TKPROF – Part 1: Trace

Tracing a SQL statement, generating TKPROF of the trace and understanding it carefully are some key steps that you will have to do when faced with a tough to break performance issue. This post will describe the methodology of this process.

Tkprof is very useful for diagnosing performance issues. It essentially formats a trace file into a more readable format for performance analysis. The DBA can then identify and resolve performance issues such as poor SQL, indexing, and wait events.

Putting all information about trace, tkprof and analysis of tkprof will make this port very lengthy so we will break this topic into below posts.

This post will cover Part 1: Tracing and various methods to generate trace file in Oracle Database as well as Oracle database linked to Oracle EBS Applications.

Part 1: Trace and the methods to generate trace
Part 2: Generating TKPROF from trace file
Part 3: Analyzing TKPROF files
Part 4: Using Trace Analyzer (TRCANLZR) Tool

Basic definition of trace and tkprof are:

TRACE:

A trace file is a raw set of data produced by the Oracle Database. You can say trace is an Oracle feature that can be enabled to generate a raw text file containing the internal SQL activity when a program is executed.

The internal activity obtained when tracing SQL activity contains following statistics for each statement:

Parse, execute, and fetch counts
CPU and elapsed times
Physical reads and logical reads
Number of rows processed
Misses on the library cache
Username under which each parse occurred
Each commit and rollback

TKPROF:

TKPROF reformats the raw data present in trace file so that it is easier to review the report. tkprof does not control the contents of a trace file. tkprof is valuable for detailed trace file analysis.

There are two essential goals when you analyze a tkprof file:

Find out the SQL/Operation which is taking highest time
Find out the SQL/Operation which is taking highest resources.

No doubt analyzing tkprof is the hardest part and we will discuss that in Part 3 post mentioned above.

KEY DATABASE INITIALIZATION PARAMETER RELATED TO TRACE

Prior to tracing, below are few parameters that need to be set so that the trace information is complete.

TIMED_STATISTICS : This parameter must be set to TRUE.
MAX_DUMP_FILE_SIZE : Should be large enough to allow the file to be completely written. It is best to set max_dump_file_size=UNLIMITED.
STATISTICS_LEVEL: Should be set to ALL

Below commands can be executed to set these required parameters.

SQL> alter system set MAX_DUMP_FILE_SIZE=UNLIMITED;
SQL> alter system set TIMED_STATISTICS=TRUE;
SQL> alter system set STATISTICS_LEVEL=ALL;

“statistics_level=all” set here may not be absolutely necessary but has been chosen over “TYPICAL” so as to have the most comprehensive information for diagnosis.

LEVEL 8 vs LEVEL 12 TRACE

By default level 8 (with waits) should be used. The reason for elapsed time can then be analyzed by waits (e.g. Physical I/O, locks/contention, User action etc.).

Level 12 also gives bind variable information, which can be useful in some circumstances (if the values used in predicates and filters are needed). However, this can add significant overhead and produce a much larger file, particularly if there are a large number of executions (or bulk binding on fewer executions) and/or a high number of bind variables. So only use level 12 if binds are needed. Consider that there could also be secure or sensitive data contained in bind values.

Other levels are

Level1: Standard SQL Trace
Level 4: Includes Bind Variables
Level 16 – STAT lines are written to the trace file for each execution (equivalent to plan_stat=ALL_EXECUTIONS)
Level 32 – Never write row source statistics (STAT lines) to the trace file (equivalent to plan_stat=NEVER)
Level 64 – Row source statistics (STAT lines) are written to the trace file for every minute of DB time consumed by the SQL statement (equivalent to plan_stat=ADAPTIVE) (11.2.0.2/patch 8328200 only).

Level 8 (with waits) is the default choice, because it gives the wait event statistics (Number of Times Waited, Maximum Wait Time and Total Wait Time) for each SQL.

If the bind values are required then obtain trace at level 12 (with binds and waits). However, this can add significant overhead and produce a much larger file, particularly if there are a large number of executions (or bulk binding on fewer executions) and/or a high number of bind variables.

PARENT / CHILD TRACES

To reduce the elapsed time, some batch processes utilise multiple child processes. For example in case of EBS application

A parent concurrent request may spawn multiple child requests.
The autopatch (adpatch) and online patching (adop) tools used on patches and upgrades can use multiple workers (AD Workers).

Note that all children/workers may not carry out the same activity and that the workload may not be divided out equally. So, in this case, all child or worker SQL trace files should ideally be obtained along with any parent SQL trace file. As a minimum, SQL traces for the parent and some children (that exhibit the performance issue) will be needed.

TRACE FILE LOCATIONS

Prior to 11g Release 1:

SQL trace files for user sessions are written to the directory specified in the initialization parameter user_dump_dest.
SQL trace files for background processes are written to the directory specified in the initialization parameter background_dump_dest.

For 11g Release 1 and above SQL trace files are written to the directory

<diagnostic_dest>/diag/rdbms/<dbname>/<instname>/trace
Where <diagnostic_dest> is specified in the initialization parameter diagnostic_dest.
This can be obtained by running the SQL:

SELECT value FROM V$DIAG_INFO WHERE NAME = 'Diag Trace';

TRACE FILE NAMING CONVENTIONS

The trace file name is normally

<instance>_ora_<ospid>_<identifier>.trc

Where:

<instance> is the database instance name specified by the initialization parameter db_name (v$parameter.db_name).
<ospid> is the OS Process ID identified by the column v$process.spid
<identifier> is the trace file identifier. The identifier will be

In case of Oracle E-Business Suite

For SQL traces obtained through Forms or Self Service (OAF) the user name and request id (e.g. SYSADMIN_123456) will be present in the SQL traces from the concurrent programs.
For the agent listener related traces, the component id and timestamp (preceded by the string WFAL) (e.g. WFAL_10002_20130403 for the Workflow Deferred Agent Listener) will be present in the SQL traces.
For SQL Trace obtained using the Profile Option method or SQL*Plus, the trace file identifier explicitly set (using ALTER SESSION SET TRACEFILE_IDENTIFIER) will be present in the trace files.
Alternatively, the OS Process ID (spid) could be used to identify the trace file or grep can be used on UNIX/LINUX to search files for key SQL strings or script/module names.

SQL_TRACE

SQL_TRACE is the main method for collecting SQL Execution information in Oracle. It records a wide range of information and statistics that can be used to tune SQL operations.

TRACING AT SESSION LEVEL

SQL_TRACE can also be enabled/disabled at the system/session by issuing the following SQL statement:

ALTER SESSION SET SQL_TRACE = TRUE/FALSE;

In 11g and higher, sql_trace is also an event and can be set with event syntax. Example:

alter session set events 'sql_trace bind=true';
alter session set events 'sql_trace bind=true, wait=true';

TRACING AT SQL_ID LEVEL

In Oracle 11.1 and above trace can be restricteed to a specific SQL ID by specifying a filter:

ALTER SYSTEM SET EVENTS sql_trace [sql: sql_id=4k1jlmn567cr7] bind=true, wait=true';

Multiple SQL IDs can be specified using the | symbol as a separator:

ALTER SYSTEM SET EVENTS sql_trace [sql: sql_id=5t6ygtsa3d356|6fa43fgg0rrtp] bind=true, wait=true';

TRACING AT DATABASE LEVEL

SQL_TRACE can be set at the instance level by using the initialisation parameter SQL_TRACE:

TRUE – Enable statistics to be collected for all sessions.
FALSE – Disable statistics to be collected for all sessions.

ALTER SYSTEM SET SQL_TRACE = TRUE/FALSE;

10046 TRACE EVENT

10046 is special EVENT code. The 10046 trace is the equivalent of setting SQL_TRACE=TRUE. The advantage of using the event is that extra details may be output to the trace file depending on the level specified with the event.

10046 EVENT levels are same as discussed earlier: 1, 4, 8,16, 32, 64.

Example Syntax:

Session level:
 alter session set events '10046 trace name context forever';    <= LEVEL 1 BASIC TRACE
 alter session set events '10046 trace name context forever, level 8'; <=  LEVEL 8 (WAITS) TRACE)
 alter session set events '10046 trace name context forever,level 12'; <= LEVEL 12 (BINDS & WAITS) TRACE
 alter session set events '10046 trace name context off';     <= SWITCH OFF THE TRACE

System-wide tracing can be enabled as follows:

alter system set events '10046 trace name context forever,level 12';

The setting can be disabled in all sessions by using the following command:

alter system set events '10046 trace name context off';

You can also set system level trace by setting the event in the init file. Example

event="10046 trace name context forever,level 4"

The setting can be disabled by removing the parameter and restarting the instance or by using an alter system command as follows:

alter system set events '10046 trace name context off';

Please note that usually we don’t do it at database level as it traces all database sessions which can prove a huge overhead for database and file system. System-wide 10046 tracing may be useful for scenarios where a problem session is known to occur but cannot be identified in advance. In this situation, tracing can be enabled for a short period of time, the problem can then be reproduced and tracing disabled and the resultant traces searched for evidence of the problem

AUTOTRACE

The autotrace command is used to view the execution plan and some useful statistics for a SQL statement within a SQL*Plus session.
Keep in mind that the Autotrace needs to be initiated in the SQL*Plus session prior to executing the statement.
The Autotrace command syntax is:

SET AUTOTRACE [OPTIONS] [EXPLAIN/STATISTICS]

Example:

SQL> set autotrace traceonly explain 
SQL> select * from EMP;

TRACING USING DBMS_MONITOR / DBMS_SESSION

Using DBMS_MONITOR tracing can be enabled based on a specified client identifier or a hierarchical combination of service name, module name and action name. Tracing can also be enabled on a session level.

The tracing for a client identifier, or service/module/action is persistent across session disconnects and database shutdown and can apply to all instances. Tracing will stay enabled until disabled using DBMS_MONITOR.

SESSION_TRACE_ENABLE

SESSION_TRACE_ENABLE enables SQL tracing for a given database session on the local instance.

For Enable Tracing

exec dbms_monitor.session_trace_enable(session_id => x, serial_num => y, waits=>(TRUE|FALSE),binds=>(TRUE|FALSE) );

For Disable Tracing

exec dbms_monitor.session_trace_disable(session_id => x, serial_num => y);

The default of waits is TRUE and the default of binds is FALSE. Tracing will be stopped when the session disconnects or by executing the above command.

DBMS_SESSION can also be used to trace any database session easily. Whereas the DBMS_MONITOR package can only be invoked by a user with the DBA role, users can also enable SQL tracing for their own session by invoking the DBMS_SESSION.SESSION_TRACE_ENABLE procedure

1. Log on to the database SQL*Plus as system or sys user.
2. Find out the serial#, session id from v$session table for the user and run below command to start tracing

execute dbms_session.set_sql_trace_in_session(sid, seria#, TRUE);

3. Let user perform required actions which need to be traced.
4. Disable the trace using below command:

execute the command dbms_session.set_sql_trace_in_session(sid, seria#, FALSE);

5. This will generate a .trc file in the database’s trace directory.

CLIENT_ID_TRACE_ENABLE

In multi-tier environments, a request from an end client is routed to different database sessions by the middle tier. This means that the association between the end client and the database session is non-static. Prior to version 10g, there was no easy way to keep track of a client across different database sessions. End-to-end tracing makes this possible by introducing a new attribute, CLIENT_IDENTIFIER, which uniquely identifies a given end client. The client identifier is visible in the CLIENT_IDENTIFIER column of V$SESSION. It is also visible through the system context.

To Enable Tracing

execute dbms_monitor.client_id_trace_enable ( client_id =>'client_id', waits => (TRUE|FALSE), binds => (TRUE|FALSE) );

To Disable Tracing

execute dbms_monitor.client_id_trace_disable ( client_id =>'client_id');

Combining trace files with TRCSESS

Some trace operations produce multiple trace files. The trcsess utility is very useful for consolidating sql_trace / 10046 files and eventually feeding them to the tkprof utility for processing. It was introduced in Oracle 10g. TRCSESS combines trace files according to certain session or client identifiers.

Syntax

trcsess [output=<output file name >] [session=<session ID>] [clientid=<clientid>] [service=<service name>] [action=<action name>] [module=<module name>] <trace file names>

A way to determine which attributes have tracing enabled can be tracked in DBA_ENABLED_TRACES.

Example:

SQL> select trace_type, primary_id, QUALIFIER_ID1, waits, binds from DBA_ENABLED_TRACES;

ORADEBUG

oradebug is excellent utility to trace a process after it has started. If trace from a running session is required then oradebug can be used to attach to the session and initiate 10046 tracing.

Below are the steps to utilize the oradebug utility:

1. Identify the PID/SPID for the session that need to be traced

For example, run below SQL to find the OS process id (spid) for the target session:

select p.PID,p.SPID,s.SID from v$process p,v$session s where s.paddr = p.addr and s.sid = &SESSION_ID;

SPID : operating system Process identifier (os pid)
PID : Oracle Process identifier (ora pid)

2. Apply the trace using oradebug

connect / as sysdba
oradebug setospid <SPID>
oradebug unlimit
oradebug event 10046 trace name context forever,level 12

Remember to replace the <SPID> value with the actual os pid.

You can use PID (Oracle Process identifier ) also rather than the ‘SPID’ to execute oradebug:

connect / as sysdba
oradebug setorapid <PID>
oradebug unlimit
oradebug event 10046 trace name context forever,level 12

Remember to replace the example <PID> value with the actual ora pid.

3. Disable oradebug tracing once tracing is finished

oradebug event 10046 trace name context off

The tracefile name will be something like <instance><spid>_<stid>.trc.

TRACING AT USER LEVEL USING TRIGGER

There may be some situations where it is necessary to trace the activity of a specific user. In this case a logon trigger could be used.
An example is provided below:

CREATE OR REPLACE TRIGGER SYS.set_trace
AFTER LOGON ON DATABASE
WHEN (USER like '&USERNAME')
DECLARE
lcommand varchar(200);
BEGIN
EXECUTE IMMEDIATE 'alter session set tracefile_identifier=''From_Trigger'''; 
EXECUTE IMMEDIATE 'alter session set statistics_level=ALL'; 
EXECUTE IMMEDIATE 'alter session set max_dump_file_size=UNLIMITED';
EXECUTE IMMEDIATE 'alter session set events ''10046 trace name context forever, level 12''';
END set_trace;
/

TRACING IN ORACLE EBS

Since we work a lot with Oracle EBS so we are describing below the methods of trace generation in Oracle EBS. You can apply tracing in Oracle EBS Application using below methods.

– – – – – – – – – – – – – – – – – – – – – – – – – – – – – – – – – – – – – – – – – – – – – – – – – – – – – – – – – – – –

1. FORM LEVEL TRACE

To enable a SQL Trace for Forms:

1. Log in to the environment that will be traced.
2. Set the profile option “Utilities:Diagnostics“ (internal name DIAGNOSTICS) user-level value to “Yes”.
3. Choose the relevant responsibility for the form and navigate to the form that will be traced.
4. Enable SQL Trace using the menu option : Help > Diagnostics > Trace > Trace with waits. Also select “Unlimited Trace File Size” to ensure an unlimited size for the trace file.
Note that you will have below options to select from LOV:

Regular Trace
Trace with Binds
Trace with Waits
Trace with Binds and Waits

We have seen that “trace with Waits” proves sufficient most of the times.
5. The trace file name and location are displayed in a dialog box. Make a note of the trace file name. This trace will be on the database tier.
6. Execute the required actions on the Form.
7. When complete, exit the form and log out.
8. Disable SQL Trace using the menu option : Help > Diagnostics > Trace > No Trace
9. Obtain the raw trace file from the trace file location.
10. Use the tkprof command to produce a formatted file

– – – – – – – – – – – – – – – – – – – – – – – – – – – – – – – – – – – – – – – – – – – – – – – – – – – – – – – – – – – –
2. HTML/SELF-SERVICE LEVEL TRACING

This is also sometimes referred to as OAF (Oracle Applications Framework) after the technology framework used on these applications.

To enable a SQL Trace for HTML/Self Service (OAF):

1. Log in to the environment that will be traced.
2. Set the profile option “FND: Diagnostics“ (internal name FND_DIAGNOSTICS) user-level value to “Yes”.
3. Choose the relevant responsibility for the HTML-based application.
4. To enable SQL Trace click the “Diagnostics” icon at the top right of the page > Set Trace Level > Go > Trace with waits > Save.
5. Select “Home” and then execute the required actions.
6. When complete, disable the trace by clicking on the “Diagnostics” icon > Set Trace Level > Go > Disable Trace
7. The “process_ids” will be provided on the left hand side of the screen. Note these down. The tracefile_identifier is the userid.
8. Exit the HTML Application and log out.
9. Obtain the raw trace files
10. Use the tkprof command to produce a formatted file

3. CONCURRENT PROGRAM – REQUEST LEVEL TRACING

To enable a SQL Trace for a Concurrent Program at Request Level:

Note that this method is only available in R12 and 11.5.10 (with latest ATG patch levels).

1. Log in to the environment that will be traced.
2. Set the profile option “Concurrent: Allow Debugging“ (internal name FND_CONC_ALLOW_DEBUG) user-level value to “Yes”.
3. Navigate to the Submit Request window (e.g. Request > Run).
4. Select the Concurrent Request to be run.
5. Click on the “Debug Options” button. This will open a new HTML window
6. Enable SQL Trace by checking the “SQL Trace” Debug Option and then select Debug Option Value “SQL Trace with Waits” (level 8). Other levels are available (e.g. “SQL Trace with Binds and Waits” (level 12)).
7. Click the “OK” button to confirm the selection. A “Create Debug Rule : Debug Option” page is displayed. Click on the “OK” button again.
8. Submit the concurrent request.
9. Make a note of the request_id of the concurrent request.
10. Check the progress of the concurrent request in the requests window.
11. When the request has completed, obtain the raw trace files
12. Use the tkprof command to produce a formatted file.

Note : This facility is not available for request sets. The “Concurrent Program” or “Profile Option” methods below will need to be used.

If this method does not produce a trace file then check the My Oracle Support document “R12.1.x SQL Trace Does Not Get Created Using Debug Options from Submit Request Form (Document 1273539.1)”. This recommends patch 8743459 to fix the issue.

4. CONCURRENT PROGRAM – PROGRAM LEVEL TRACING

To enable a SQL Trace for a Concurrent Program at Program Level:

1. Log in to the environment that will be traced.
2. Choose the relevant responsibility for defining concurrent programs.
3. Navigate to the Concurrent > Program > Define window.
4. Query for the concurrent program to be traced.
5. Turn on SQL Trace for the concurrent program by checking the “Enable Trace” tick box.Note that this will enable a level 8 trace (with waits) when the program is run.
6. Navigate to the Submit Request window (e.g. Request > Run).
7. Submit a concurrent request for the concurrent program.
8. Make a note of the request_id of the concurrent request.
9. Check the progress of the concurrent request in the requests window.
10. When the request has completed navigate to the Concurrent > Program > Define window and disable the trace by un-checking the “Enable Trace” tick box.
11. Obtain the raw trace file
12. Use the tkprof command to produce a formatted file.

Note that the profile option “Utilities:SQL Trace” (internal name SQL_TRACE) can be used (by System Administrator) to enable SQL Trace for all concurrent programs for a user, responsibility, application or site. This is not recommended as it could produce a large number of trace files, and more specific levels at program and request level are available

5. USING PROFILE OPTION METHOD “Initialization SQL Statement – Custom”

If none of the methods above allows the trace to be captured for the required session then all sessions for a particular user can be traced by setting the profile option “Initialization SQL Statement – Custom” user-level value.

This method also allows the level to be specified. So is often used for concurrent programs where a level 12 trace (binds and waits) is required.

1. Log in to the environment that will be traced.
2. If trace is being enabled for the current (logged in) user account then navigate to the Profile > Personal window, otherwise navigate to the Profile > System window.
3. Query the profile “Initialization SQL Statement – Custom”(internal name FND_INIT_SQL).
4. Enter the following as the profile value and save.

BEGIN FND_CTL.FND_SESS_CTL(”,”,’TRUE’,’TRUE’,”,’ALTER SESSION SET TRACEFILE_IDENTIFIER=”test_identifier” STATISTICS_LEVEL=ALL MAX_DUMP_FILE_SIZE=unlimited EVENTS=”10046 TRACE NAME CONTEXT FOREVER, LEVEL 8”’);END;

Note:

Specify a meaningful identifier. In the example above “test_identifier” will appear at the end of the trace file name. Including the user name is recommended.
The quotes in the above statement are all single quotes. Take care that these are entered/pasted correctly into the profile.
If there is existing SQL in the profile then the above should be merged with the existing SQL.

5. Log in (again) to the application using the user account being traced. This is necessary because the Initialization SQL Statement is only executed at login.
6. Execute the actions to be traced.
7. Exit the application and log out.
8. Navigate to the profile form again, remove the SQL above (ensuring any original SQL remains) from the “Initialization SQL Statement – Custom” profile and save.
9. Obtain the raw trace files
10. Use the tkprof command to produce a formatted file.

Note that if SQL trace is enabled for a Concurrent Program (“Enable Trace” tick box filled in the Concurrent Program Define window) then this will produce a level 8 trace (from 11.5.10 onwards), even if level 12 (binds and waits) has been specified in the profile option (above). So the “Enable Trace” check box will need to be unchecked for any Concurrent Programs being traced this way.

FEW IMPORTANT POINTS TO KEEP IN MIND

Many times trace files can get huge and fill up the file system causing undesirable issues. Keep a tab on tracing process and always remove obsolete trace/tkprof files.
Enable tracing only on those sessions(SID) that are having problems.
Keep some sensible names for trace files so that you can identify it easily.

This is one of the post in Performance Tuning Fundamentals Series. Click on below links to read more posts from the series:

Performance Tuning Basics 1 : Selectivity and Cardinality
Performance Tuning Basics 2 : Parsing
Performance Tuning Basics 3 : Parent and Child Cursors
Performance Tuning Basics 4 : Bind Variables
Performance Tuning Basics 5 : Trace and TKPROF – Part 1: Trace
Performance Tuning Basics 6 : Trace and TKPROF – Part 2: Generating TKPROF
Performance Tuning Basics 7 : Trace and TKPROF – Part 3: Analyzing TKPROF Files
Performance Tuning Basics 8 : Trace File Analyzer (TRCA)
Performance Tuning Basics 9 : Optimizer Mode
Performance Tuning Basics 10 : Histograms
Performance Tuning Basics 11 : Steps to analyze a performance problem
Performance Tuning Basics 12 : Dynamic Performance Views
Performance Tuning Basics 13 : Automatic Workload Repository (AWR) Basics
Performance Tuning Basics 14 : Active Sessions History (ASH) Basics
Performance Tuning Basics 15 : AWR Report Analysis
Performance Tuning Basics 16 : Using SQL Tuning Health-Check Script (SQLHC)

Author
Recent Posts

Brijesh Gogia

I’m an experienced Cloud/Oracle Applications/DBA Architect with more than 15 years of full-time DBA/Architect experience. I have gained wide knowledge on Oracle and Non-Oracle software stack running on-prem and on Cloud and have worked on several big projects for multi-national companies. I enjoy working with leading-edge technology and have a passion for Cloud architecture, automation, database performance, and stability. Thankfully my work allows me time for researching new technologies (and to write about them).

Performance Tuning Basics 5 : Trace and TKPROF – Part 1: Trace

Related posts:

2 Comments