The SQL Trace Facility

• parse, execute, and fetch counts

• CPU and elapsed times

• physical reads and logical reads

• number of rows processed

• misses on the library cache

You can run the TKPROF program to format the contents of the trace file and place the output into a readable output file. As options, TKPROF can also

• determine the execution plans of SQL statements

• create a SQL script that stores the statistics in the database

Using the SQL Trace Facility

1. Set initialization parameters to prepare Oracle for using the SQL trace facility.

2. Enable the SQL trace facility for the desired session and run your application. This step produces a trace file containing statistics for the SQL statements issued by the application.

3. Run TKPROF to translate the trace file created in Step 2 into a readable output file. This step can also optionally create a SQL script that stores the statistics in the database.

4. Interpret the output file created in Step 3.

5. Optionally, run the SQL script produced in Step 3 to store the statistics in the database.

Setting Initialization Parameters for the SQL Trace Facility

	TIMED_STATISTICS This parameter enables and disables the collection of timed statistics, such as CPU and elapsed times, by the SQL trace facility, as well as the collection of certain statistics in the dynamic performance tables. The default value of FALSE disables timing. A value of TRUE enables timing. Enabling timing causes extra timing calls for low-level operations.
	MAX_DUMP_FILE_SIZE This parameter specifies the maximum size of trace files in operating system blocks. The default is 500. If you find that your trace output is truncated, increase the value of this parameter before generating another trace file.
	USER_DUMP_DEST This parameter specifies the destination for the trace file. The destination must be fully specified according to the conventions of your operating system. The default value for this parameter is the default destination for system dumps on your operating system.

Enabling the SQL Trace Facility

• an individual session

• the instance

Enabling Tracing for a Session

ALTER SESSION
    SET SQL_TRACE = TRUE;

To disable the SQL trace facility for your session, issue this SQL statement:

ALTER SESSION
    SET SQL_TRACE = FALSE;

You can also enable the SQL trace facility for your session by using the DBMS_SESSION.SET_SQL_TRACE procedure.

You may need to modify your application to contain the ALTER SESSION command. For example, to issue the ALTER SESSION command in Oracle Forms, invoke Oracle Forms using the -s option, or invoke Oracle Forms (Design) using the statistics option. For more information on Oracle Forms, see the Oracle Forms Reference manual.

The SQL trace facility is also automatically disabled for your session when your application disconnects from Oracle.

Calling the DBMS_SYSTEM.SET_SQL_TRACE_IN_SESSION procedure enables the SQL trace facility for a session other than your current session. This procedure allows you to gather statistics for a different user's session. This can be useful for database administrators who are not located near their users or who do not have access to the application code to set SQL trace from within an application. This procedure requires the session id and serial number of the user session in which you wish to enable SQL trace.

You can obtain the session id and serial number from the V$SESSION view. The following is an example of a Server Manager line mode session that obtains the session id and serial number for the user JFRAZZIN and then enables SQL trace for that user's session:

SVRMGR> SELECT sid, serial#, osuser 
	 2>	FROM v$session
	 3>	WHERE osuser = 'jfrazzin';

SID        SERIAL#    OSUSER         
---------- ---------- ---------------
         8         12 jfrazzin       
1 row selected.

SVRMGR> EXECUTE dbms_system.set_sql_trace_in_session(8,12,TRUE);
Statement processed.

Enabling the SQL Trace Facility for an Instance

Once the SQL trace facility has been enabled for the instance, it may be disabled for an individual session with this SQL statement:

ALTER SESSION
SET SQL_TRACE = FALSE;

Generating Trace Files

Because Oracle writes these trace files to the user dump destination, be sure you know how to distinguish them by name.

If your operating system retains multiple versions of files, be sure your version limit is high enough to accommodate the number of trace files you expect the SQL trace facility to generate.

The generated trace files may be owned by an operating system user other than yourself. This user must make the trace files available to you before you can use TKPROF to format them.

Once the SQL trace facility has generated a number of trace files, you can either:

• run TKPROF on each individual trace file, producing a number of formatted output files, one for each session

• append the trace files together and then run TKPROF on the result to produce a formatted output file for the entire instance.

Running TKPROF

If you invoke TKPROF with no arguments, online help is displayed.

Use the following arguments with TKPROF:

filename1	Specifies the input file, a trace file containing statistics produced by the SQL trace facility. This file can be either a trace file produced for a single session or a file produced by appending together individual trace files from multiple sessions.
filename2	Specifies the file to which TKPROF writes its formatted output.
EXPLAIN	Determines the execution plan for each SQL statement in the trace file and writes these execution plans to the output file. TKPROF determines execution plans by issuing the EXPLAIN PLAN command after connecting to Oracle with the user and password specified in this parameter. The specified user must have CREATE SESSION system privileges.
TABLE	Specifies the schema and name of the table into which TKPROF temporarily places execution plans before writing them to the output file. If the specified table already exists, TKPROF deletes its rows, uses it for the EXPLAIN PLAN command, and then deletes its rows. If this table does not exist, TKPROF creates it, uses it, and then drops it.
	The specified user must be able to issue INSERT, SELECT, and DELETE statements against the table. If the table does not already exist, the user must also be able to issue CREATE TABLE and DROP TABLE statements.
	For the privileges to issue these statements, see the Oracle7 Server SQL Reference.
	This option allows multiple individuals to run TKPROF concurrently with the same user in the EXPLAIN value. These individuals can specify different TABLE values and avoid destructively interfering with each other's processing on the temporary plan table.
	If you use the EXPLAIN parameter without the TABLE parameter, TKPROF uses the table PROF$PLAN_TABLE in the schema of the user specified by the EXPLAIN parameter. If you use the TABLE parameter without the EXPLAIN parameter, TKPROF ignores the TABLE parameter.
INSERT	Creates a SQL script that stores the trace file statistics in the database. TKPROF creates this script with the name filename3. This script creates a table and inserts a row of statistics for each traced SQL statement into the table.
SYS	Enables and disables the listing of SQL statements issued by the user SYS, or recursive SQL statements into the output file. The default value of YES causes TKPROF to list these statements. The value of NO causes TKPROF to omit them.
	Note that this parameter does not affect the optional SQL script. The SQL script always inserts statistics for all traced SQL statements, including recursive SQL statements.
SORT	Sorts the traced SQL statements in descending order of the specified sort option before listing them into the output file. If more than one option is specified, the output is sorted in descending order by the sum of the values specified in the sort options. If you omit this parameter, TKPROF lists statements into the output file in ascending order of when each was first issued.
	The sort options are
	PRSCNT number of times parsed
	PRSCPU CPU time spent parsing
	PRSELA elapsed time spent parsing
	PRSDSK number of physical reads from disk during parse
	PRSQRY number of consistent mode block reads during parse
	PRSCU number of current mode block reads during parse
	PRSMIS number of library cache misses during parse
	EXECNT number of executes
	EXECPU CPU time spent executing
	EXEELA elapsed time spent executing
	EXEDSK number of physical reads from disk during execute
	EXEQRY number of consistent mode block reads during execute
	EXECU number of current mode block reads during execute
	EXEROW number of rows processed during execute
	EXEMIS number of library cache misses during execute
	FCHCNT number of fetches
	FCHCPU CPU time spent fetching
	FCHELA elapsed time spent fetching
	FCHDSK number of physical reads from disk during fetch
	FCHQRY number of consistent mode block reads during fetch
	FCHCU number of current mode block reads during fetch
	FCHROW number of rows fetched
PRINT	Lists only the first integer sorted SQL statements into the output file. If you omit this parameter, TKPROF lists all traced SQL statements. Note that this parameter does not affect the optional SQL script. The SQL script always inserts statistics for all traced SQL statements.
RECORD	Creates a SQL script with the specified filename with all of the non-recursive SQL in the trace file. This can be used to replay the user events from the trace file.

Example

This example runs TKPROF, accepts a trace file named DLSUN12_JOHN_FG_SVRMGR_007.TRC, and writes a formatted output file named OUTPUTA.PRF:

TKPROF DLSUN12_JOHN_FG_SVRMGR_007.TRC OUTPUTA.PRF
EXPLAIN=SCOTT/TIGER TABLE=SCOTT.TEMP_PLAN_TABLE_A INSERT=STOREA.SQL SYS=NO SORT=(EXECPU,FCHCPU) PRINT=10

This example is likely to be longer than a single line on your terminal screen and you may have to use continuation characters, depending on your operating system.

Note the other parameters in this example:

• The EXPLAIN value causes TKPROF to connect as the user SCOTT and use the EXPLAIN PLAN command to generate the execution plan for each traced SQL statement.

• The TABLE value causes TKPROF to use the table TEMP_PLAN_TABLE_A in the schema SCOTT as a temporary plan table.

• The INSERT value causes TKPROF to generate a SQL script named STOREA.SQL that stores statistics for all traced SQL statements in the database.

• The SYS parameter with the value of NO causes TKPROF to omit recursive SQL statements from the output file.

• The SORT value causes TKPROF to sort the SQL statements in order of the sum of the CPU time spent executing and the CPU time spent fetching rows before writing them to the output file.

• The PRINT value of 10 causes TKPROF to write statistics for the first 10 sorted SQL statements to the output file.

Interpretting TKPROF Output

SELECT * FROM emp, dept WHERE emp.deptno = dept.deptno;
  
call   count      cpu    elapsed     disk    query current    rows
---- -------  -------  --------- -------- -------- -------  ------
Parse      1     0.16      0.29         3       13       0       0
Execute    1     0.00      0.00         0        0       0       0
Fetch      1     0.03      0.26         2        2       4      14 
 
Misses in library cache during parse: 1 
Parsing user id: 8 
 
Rows     Execution Plan
-------  --------------------------------------------------- 
     14  MERGE JOIN
      4    SORT JOIN
      4      TABLE ACCESS (FULL) OF 'DEPT'
     14    SORT JOIN
     14      TABLE ACCESS (FULL) OF 'EMP'

For this statement, TKPROF output has these parts:

• the text of the SQL statement

• the SQL trace statistics in tabular form

• the number of library cache misses for the parsing and execution of the statement

• the user initially parsing the statement

• the execution plan generated by EXPLAIN PLAN

SQL Trace Facility Statistics

Parse	This step translates the SQL statement into an execution plan. This step includes checks for proper security authorization and checks for the existence of tables, columns, and other referenced objects.
Execute	This step is the actual execution of the statement by Oracle. For INSERT, UPDATE, and DELETE statements, this step modifies the data. For SELECT statements, the step identifies the selected rows.
Fetch	This step retrieves rows returned by a query. Fetches are only performed for SELECT statements.

The step for which each row contains statistics is identified by the value of the call column.

The other columns of the SQL trace facility output are combined statistics for all parses, all executes, and all fetches of a statement:

count	Number of times a statement was parsed, executed, or fetched.
cpu	Total CPU time in seconds for all parse, execute, or fetch calls for the statement.
elapsed	Total elapsed time in seconds for all parse, execute, or fetch calls for the statement.
disk	Total number of data blocks physically read from the datafiles on disk for all parse, execute, or fetch calls.
query	Total number of buffers retrieved in consistent mode for all parse, execute, or fetch calls. Buffers are usually retrieved in consistent mode for queries.
current	Total number of buffers retrieved in current mode. Buffers are often retrieved in current mode for INSERT, UPDATE, and DELETE statements.
	The sum of query and current is the total number of buffers accessed.
rows	Total number of rows processed by the SQL statement. This total does not include rows processed by subqueries of the SQL statement.
	For SELECT statements, the number of rows returned appears for the fetch step.
	For UPDATE, DELETE, and INSERT statements, the number of rows processed appears for the execute step.

Resolution of Statistics Since timing statistics have a resolution of one hundredth of a second, any operation on a cursor that takes a hundredth of a second or less may not be timed accurately. Keep this in mind when interpreting statistics. In particular, be careful when interpreting the results from simple queries that execute very quickly.

Recursive Calls Sometimes to execute a SQL statement issued by a user, Oracle must issue additional statements. Such statements are called recursive calls or recursive SQL statements. For example, if you insert a row into a table that does not have enough space to hold that row, Oracle makes recursive calls to allocate the space dynamically. Recursive calls are also generated when data dictionary information is not available in the data dictionary cache and must be retrieved from disk.

If recursive calls occur while the SQL trace facility is enabled, TKPROF produces statistics for the recursive SQL statements and clearly marks them as recursive SQL statements in the output file. Note that the statistics for a recursive SQL statement are included in the listing for that statement, not in the listing for the SQL statement that caused the recursive call. So when you are calculating the total resources required to process a SQL statement, you should consider the statistics for that statement as well as those for recursive calls caused by that statement. Note that setting the TKPROF command line parameter to NO suppresses the listing of recursive calls in the output file.

Library Cache Misses

User Issuing the SQL Statement

Execution Plan

Storing SQL Trace Facility Statistics

• a CREATE TABLE statement that creates an output table named TKPROF_TABLE

• INSERT statements that add rows of statistics, one for each traced SQL statement, to the TKPROF_TABLE

Generating the TKPROF Output SQL Script

Editing the TKPROF Output SQL Script

• If you have already created an output table for previously collected statistics and you want to add new statistics to the existing table, remove the CREATE TABLE statement from the script. The script will then insert the new rows into the existing table.

• If you have created multiple output tables, perhaps to store statistics from different databases in different tables, edit the CREATE TABLE and INSERT statements to change the name of the output table.

Querying the Output Table

CREATE TABLE tkprof_table
    (date_of_insert    DATE,
    cursor_num        NUMBER,
    depth             NUMBER,
    user_id           NUMBER,
    parse_cnt         NUMBER,
    parse_cpu         NUMBER,
    parse_elap        NUMBER,
    parse_disk        NUMBER,
    parse_query       NUMBER,
    parse_current     NUMBER,
    parse_miss        NUMBER,
    exe_count         NUMBER,
    exe_cpu           NUMBER,
    exe_elap          NUMBER,
    exe_disk          NUMBER,
    exe_query         NUMBER,
    exe_current       NUMBER,
    exe_miss          NUMBER,
    exe_rows          NUMBER,
    fetch_count       NUMBER,
    fetch_cpu         NUMBER,
    fetch_elap        NUMBER,
    fetch_disk        NUMBER,
    fetch_query       NUMBER,
    fetch_current     NUMBER,
    fetch_rows        NUMBER,
    clock_ticks       NUMBER,
    sql_statement     LONG)

These columns help you identify a row of statistics by these columns:

SQL_STATEMENT	The column value is the SQL statement for which the SQL trace facility collected the row of statistics. Note that because this column has datatype LONG, you cannot use it in expressions or WHERE clause conditions.
DATE_OF_INSERT	The column value is the date and time when the row was inserted into the table. Note that this value is not exactly the same as the time the statistics were collected by the SQL trace facility. Most output table columns correspond directly to the statistics that appear in the formatted output file. For example the PARSE_CNT column value corresponds to the count statistic for the parse step in the output file.
DEPTH	This column value indicates the level of recursion at which the SQL statement was issued. For example, a value of 1 indicates that a user issued the statement. A value of 2 indicates Oracle generated the statement as a recursive call to process a statement with a value of 1 (a statement issued by a user). A value of n indicates Oracle generated the statement as a recursive call to process a statement with a value of n-1.
USER_ID	This column value identifies the user issuing the statement. This value also appears in the formatted output file.
CURSOR_NUM	This column value is used by Oracle to keep track of the cursor to which each SQL statement was assigned. Note that the output table does not store the statement's execution plan.

Example

This query returns the statistics from the output table. These statistics correspond to the formatted output shown in the section "Interpretting TKPROF Output" .

		    SELECT * FROM tkprof_table;

		    DATE_OF_INSERT CURSOR_NUM DEPTH USER_ID PARSE_CNT PARSE_CPU PARSE_ELAP

		    -------------- ---------- ----- ------- --------- --------- ---------- 

		    27-OCT-1993             1     0       8         1        16         29

 		    PARSE_DISK PARSE_QUERY PARSE_CURRENT PARSE_MISS EXE_COUNT EXE_CPU 

		    ---------- ----------- ------------- ---------- --------- ------- 

		             3          13             0          1         1       0 

 		    EXE_ELAP EXE_DISK EXE_QUERY EXE_CURRENT EXE_MISS EXE_ROWS FETCH_COUNT 

		    -------- -------- --------- ----------- -------- -------- ----------- 

		           0        0         0           0        0        0           1 

 		    FETCH_CPU FETCH_ELAP FETCH_DISK FETCH_QUERY FETCH_CURRENT FETCH_ROWS 

		    --------- ---------- ---------- ----------- ------------- ---------- 

		            3         26          2           2             4         14 

 		    SQL_STATEMENT 

		    ---------------------------------------------------------------------

 		    SELECT * FROM EMP, DEPT WHERE EMP.DEPTNO = DEPT.DEPTNO