21 Using Application Tracing Tools

Oracle Database provides several tracing tools that can help you monitor and analyze applications running against an Oracle database.

End-to-End Application Tracing can identify the source of an excessive workload, such as a high load SQL statement, by client identifier, service, module, action, session, instance, or an entire database. This isolates the problem to a specific user, service, session, or application component.

21.1 End-to-End Application Tracing

End-to-End Application Tracing simplifies the process of diagnosing performance problems in multitier environments. In these environments, a request from an end client is routed to different database sessions by the middle tier, making it difficult to track a client across database sessions. End-to-End Application Tracing uses a client ID to uniquely trace a specific end client through all tiers to the database.

This feature could identify the source of an excessive workload, such as a high-load SQL statement, and enables you to contact the specific user responsible. Also, a user having problems can contact you. You can then identify what this user session is doing at the database level.

End-to-End Application Tracing also simplifies management of application workloads by tracking specific modules and actions in a service. End-to-End Application Tracing can identify workload problems for the following:

Client identifier

This specifies an end user based on the logon ID, such as HR.HR.

Service

This specifies either a single application (such as ACCTG for an accounting application), or a group of applications with common attributes, service level thresholds, and priorities.

Module

This specifies a functional block, such as Accounts Receivable or General Ledger, of an application.

Action

This specifies an action, such as an INSERT or UPDATE operation, in a module.

Session

This represents the state of a current user login to a database.

Instance

This represents the combination of the system global area (SGA) and background processes.

After tracing information is written to files, you can consolidate this information with the trcsess utility and diagnose it with an analysis utility such as TKPROF.

To create services on single-instance Oracle databases, use the DBMS_SERVICE.CREATE_SERVICE procedure or set the SERVICE_NAMES initialization parameter.

The module and action names are set by the application developer. For example, you would use the SET_MODULE and SET_ACTION procedures in the DBMS_APPLICATION_INFO package to set these values in a PL/SQL program.

The recommended interface for End-to-End Application Tracing is Oracle Enterprise Manager. Using Enterprise Manager, you can view the top consumers for each consumer type, and enable or disable statistics gathering and SQL tracing for specific consumers. Whenever possible, you should use Enterprise Manager to manage End-to-End Application Tracing, as described in Oracle Database 2 Day + Performance Tuning Guide. If Oracle Enterprise Manager is unavailable, then you can manage this feature using the DBMS_MONITOR APIs, as described in the following sections:

Regarding statistics gathering, when you change the module or action using these procedures, the change takes effect when the next user call is executed in the session. For example, if a module is set to module1 in a session, and if the module is reset to module2 in a user call in the session, then the module remains module1 during this user call. The module is changed to module2 in the next user call in the session.

21.1.2 Viewing Gathered Statistics for End-to-End Application Tracing

You can display the statistics that have been gathered with several dynamic views.

The accumulated global statistics for the currently enabled statistics can be displayed with the DBA_ENABLED_AGGREGATIONS view.

The accumulated statistics for a specified client identifier can be displayed in the V$CLIENT_STATS view.

The accumulated statistics for a specified service can be displayed in V$SERVICE_STATS view.

The accumulated statistics for a combination of specified service, module, and action can be displayed in the V$SERV_MOD_ACT_STATS view.

The accumulated statistics for elapsed time of database calls and for CPU use can be displayed in the V$SERVICEMETRIC view.

21.1.3 Enabling and Disabling for End-to-End Tracing

To enable tracing for client identifier, service, module, action, session, instance or database, execute the appropriate procedures in the DBMS_MONITOR package. You can enable tracing for specific diagnosis and workload management by the following criteria:

In this example, OE.OE is the client identifier for which SQL tracing is to be enabled. The TRUE argument specifies that wait information will be present in the trace. The FALSE argument specifies that bind information will not be present in the trace.

The CLIENT_ID_TRACE_DISABLE procedure disables tracing globally for the database for a given client identifier. To disable tracing, for the previous example:

EXECUTE DBMS_MONITOR.CLIENT_ID_TRACE_DISABLE(client_id => 'OE.OE');

21.1.3.2 Tracing for Service, Module, and Action

The SERV_MOD_ACT_TRACE_ENABLE procedure enables SQL tracing for a given combination of service name, module, and action globally for a database, unless an instance name is specified in the procedure.

In this example, the service ACCTG is specified. The module or action name is not specified. The TRUE argument specifies that wait information will be present in the trace. The FALSE argument specifies that bind information will not be present in the trace. The inst1 instance is specified to enable tracing only for that instance.

To enable tracing for all actions for a given combination of service and module:

The SERV_MOD_ACT_TRACE_DISABLE procedure disables the trace at all enabled instances for a given combination of service name, module, and action name globally. For example, the following disables tracing for the first example in this section:

While the DBMS_MONITOR package can only be invoked by a user with the DBA role, any user can also enable SQL tracing for their own session by using the DBMS_SESSION package. A user can invoke the SESSION_TRACE_ENABLE procedure to enable session-level SQL trace for the user's session. For example:

In this example, the inst1 instance is specified to enable tracing for that instance. The TRUE argument specifies that wait information will be present in the trace. The FALSE argument specifies that bind information will not be present in the trace. This example results in SQL tracing of all SQL in the inst1 instance.

The DATABASE_TRACE_ENABLE procedure overrides all other session-level traces, but will be complementary to the client identifier, service, module, and action traces. All new sessions will inherit the wait and bind information specified by this procedure until the DATABASE_TRACE_DISABLE procedure is called. When this procedure is invoked with the instance_name parameter specified, it will reset the session-level SQL trace for the named instance. If this procedure is invoked without the instance_name parameter specified, then it will reset the session-level SQL trace for the entire database.

The DATABASE_TRACE_DISABLE procedure disables the tracing for an entire instance or database. For example:

In this example, all session-level SQL tracing will be disabled for the inst1 instance. To disable the session-level SQL tracing for an entire database, invoke the DATABASE_TRACE_DISABLE procedure without specifying the instance_name parameter:

EXECUTE DBMS_MONITOR.DATABASE_TRACE_DISABLE();

21.1.4 Viewing Enabled Traces for End-to-End Tracing

An Oracle Enterprise Manager report or the DBA_ENABLED_TRACES view can display outstanding traces. In the DBA_ENABLED_TRACES view, you can determine detailed information about how a trace was enabled, including the trace type. The trace type specifies whether the trace is enabled for client identifier, session, service, database, or a combination of service, module, and action.

21.2 Using the trcsess Utility

The trcsess utility consolidates trace output from selected trace files based on several criteria:

Session ID

Client ID

Service name

Action name

Module name

After trcsess merges the trace information into a single output file, the output file could be processed by TKPROF.

trcsess is useful for consolidating the tracing of a particular session for performance or debugging purposes. Tracing a specific session is usually not a problem in the dedicated server model as a single dedicated process serves a session during its lifetime. You can see the trace information for the session from the trace file belonging to the dedicated server serving it. However, in a shared server configuration a user session is serviced by different processes from time to time. The trace pertaining to the user session is scattered across different trace files belonging to different processes. This makes it difficult to get a complete picture of the life cycle of a session.

21.2.1 Syntax for trcsess

output specifies the file where the output is generated. If this option is not specified, then the utility writes to standard output.

session consolidates the trace information for the session specified. The session identifier is a combination of session index and session serial number, such as 21.2371. You can locate these values in the V$SESSION view.

clientid consolidates the trace information given client ID.

service consolidates the trace information for the given service name.

action consolidates the trace information for the given action name.

module consolidates the trace information for the given module name.

trace_files is a list of all the trace file names, separated by spaces, in which trcsess should look for trace information. You can use the wildcard character (*) to specify the trace file names. If you do not specify trace files, then trcsess takes all the files in the current directory as input.

You must specify one of the session, clientid, service, action, or module options. If more then one of the session, clientid, service, action, or module options is specified, then the trace files which satisfies all the criteria specified are consolidated into the output file.

21.2.2 Sample Output of trcsess

This sample output of trcsess shows the consolidation of traces for a particular session. In this example the session index and serial number equals 21.2371.

You can invoke trcsess with various options. In the following case, all files in current directory are taken as input:

21.3 Understanding SQL Trace and TKPROF

The SQL Trace facility and TKPROF let you accurately assess the efficiency of the SQL statements an application runs. For best results, use these tools with EXPLAINPLAN rather than using EXPLAINPLAN alone.

21.3.1 Understanding the SQL Trace Facility

The SQL Trace facility provides performance information on individual SQL statements. It generates the 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

Wait event data for each SQL statement, and a summary for each trace file

If the cursor for the SQL statement is closed, then SQL Trace also provides row source information that includes:

Number of rows, number of consistent reads, number of physical reads, number of physical writes, and time elapsed for each operation on a row

Although it is possible to enable the SQL Trace facility for a session or for an instance, it is recommended that you use the DBMS_SESSION or DBMS_MONITOR packages instead. When the SQL Trace facility is enabled for a session or for an instance, performance statistics for all SQL statements executed in a user session or in the instance are placed into trace files. Using the SQL Trace facility can have a severe performance impact and may result in increased system overhead, excessive CPU usage, and inadequate disk space.

Oracle Database provides the trcsess command-line utility that consolidates tracing information from several trace files based on specific criteria, such as session or client ID. See "Using the trcsess Utility".

21.3.2 Understanding TKPROF

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

Create a SQL script that stores the statistics in the database

Determine the execution plans of SQL statements

Note:

If the cursor for a SQL statement is not closed, then TKPROF output does not automatically include the actual execution plan of the SQL statement. In this situation, you can use the EXPLAIN option with TKPROF to generate an execution plan.

TKPROF reports each statement executed with the resources it has consumed, the number of times it was called, and the number of rows which it processed. This information lets you easily locate those statements that are using the greatest resource. With experience or with baselines available, you can assess whether the resources used are reasonable given the work done.

When the SQL Trace facility is enabled for a session, Oracle Database generates a trace file containing statistics for traced SQL statements for that session. When the SQL Trace facility is enabled for an instance, Oracle Database creates a separate trace file for each process. Before enabling the SQL Trace facility:

Check the settings of the TIMED_STATISTICS, MAX_DUMP_FILE_SIZE, and DIAGNOSTIC_DEST initialization parameters, as indicated in Table 21-1.

Specifies the location of the Automatic Diagnostic Repository (ADR) Home. The diagnostic files for each database instance are located in this dedicated directory. Oracle Database Reference for information about the DIAGNOSTIC_DEST initialization parameter.

MAX_DUMP_FILE_SIZE

When the SQL Trace facility is enabled at the database instance level, every call to the database writes a text line in a file in the operating system's file format. The maximum size of these files in operating system blocks is limited by this initialization parameter. The default is UNLIMITED. See Oracle Database Administrator's Guide to learn how to control the trace file size.

TIMED_STATISTICS

Enables and disables the collection of timed statistics, such as CPU and elapsed times, by the SQL Trace facility, and the collection of various statistics in the V$ views.

If STATISTICS_LEVEL is set to TYPICAL or ALL, then the default value of TIMED_STATISTICS is TRUE. If STATISTICS_LEVEL is set to BASIC, then the default value is FALSE. See Oracle Database Reference for information about the STATISTICS_LEVEL initialization parameter.

Enabling timing causes extra timing calls for low-level operations. This is a dynamic parameter. It is also a session parameter. See Oracle Database Reference for information about the TIMED_STATISTICS initialization parameter.

Devise a way of recognizing the resulting trace file.

Be sure you know how to distinguish the trace files by name. You can tag trace files by including in your programs a statement like SELECT'program_name'FROMDUAL. You can then trace each file back to the process that created it.

You can also set the TRACEFILE_IDENTIFIER initialization parameter to specify a custom identifier that becomes part of the trace file name. For example, you can add my_trace_id to subsequent trace file names for easy identification with the following:

The input and output files are the only required arguments. If you invoke TKPROF without arguments, then the tool displays online help. Use the arguments in Table 21-2 with TKPROF.

Table 21-2 TKPROF Arguments

Argument

Description

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 concatenating individual trace files from multiple sessions.

filename2

Specifies the file to which TKPROF writes its formatted output.

WAITS

Specifies whether to record summary for any wait events found in the trace file. Values are YES or NO. The default is YES.

SORT

Sorts traced SQL statements in descending order of specified sort option before listing them into the output file. If multiple options are specified, then the output is sorted in descending order by the sum of the values specified in the sort options. If you omit this parameter, then TKPROF lists statements into the output file in order of first use. Sort options are listed as follows:

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.

USERID

Userid of user that parsed the cursor.

PRINT

Lists only the first integer sorted SQL statements from the output file. If you omit this parameter, then TKPROF lists all traced SQL statements. This parameter does not affect the optional SQL script. The SQL script always generates insert data for all traced SQL statements.

AGGREGATE

If you specify AGGREGATE = NO, then TKPROF does not aggregate multiple users of the same SQL text.

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. This parameter does not affect the optional SQL script. The SQL script always inserts statistics for all traced SQL statements, including recursive SQL statements.

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 exists, then TKPROF deletes all rows in the table, uses it for the EXPLAINPLAN statement (which writes more rows into the table), and then deletes those rows. If this table does not exist, then 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 exist, then the user must also be able to issue CREATETABLE and DROPTABLE statements. For the privileges to issue these statements, see the Oracle Database SQL Language 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, then 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, then TKPROF ignores the TABLE parameter.

If no plan table exists, TKPROF creates the table PROF$PLAN_TABLE and then drops it at the end.

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 EXPLAINPLAN statement after connecting to Oracle Database with the user and password specified in this parameter. The specified user must have CREATESESSION system privileges.TKPROF takes longer to process a large trace file if the EXPLAIN option is used.

RECORD

Creates a SQL script with the specified filename4 with all of the nonrecursive SQL in the trace file. You can use this script to replay the user events from the trace file.

WIDTH

An integer that controls the output line width of some TKPROF output, such as the explain plan. This parameter is useful for post-processing of TKPROF output.

21.4.3.3 Examples of TKPROF Statement

This section provides two brief examples of TKPROF usage. For an complete example of TKPROF output, see "Sample TKPROF Output".

21.4.3.3.1 TKPROF Example 1

If you are processing a large trace file using a combination of SORT parameters and the PRINT parameter, then you can produce a TKPROF output file containing only the highest resource-intensive statements. For example, the following statement prints the 10 statements in the trace file that have generated the most physical I/O:

This example is likely to be longer than a single line on the screen, and you might need to use continuation characters, depending on the operating system.

Note the other parameters in this example:

The EXPLAIN value causes TKPROF to connect as the user scott and use the EXPLAINPLAN statement to generate the execution plan for each traced SQL statement. You can use this to get access paths and row source counts.

Note:

If the cursor for a SQL statement is not closed, then TKPROF output does not automatically include the actual execution plan of the SQL statement. In this situation, you can use the EXPLAIN option with TKPROF to generate an execution plan.

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. In this way, you can ignore internal Oracle Database statements such as temporary table operations.

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. For greatest efficiency, always use SORT parameters.

While TKPROF provides a very useful analysis, the most accurate measure of efficiency is the actual performance of the application in question. At the end of the TKPROF output is a summary of the work done in the database engine by the process during the period that the trace was running.

21.4.4.1 Tabular Statistics in TKPROF

TKPROF lists the statistics for a SQL statement returned by the SQL Trace facility in rows and columns. Each row corresponds to one of three steps of SQL statement processing. Statistics are identified by the value of the CALL column. See Table 21-3.

Table 21-3 CALL Column Values

CALL Value

Meaning

PARSE

Translates the SQL statement into an execution plan, including checks for proper security authorization and checks for the existence of tables, columns, and other referenced objects.

EXECUTE

Actual execution of the statement by Oracle. For INSERT, UPDATE, and DELETE statements, this modifies the data. For SELECT statements, this identifies the selected rows.

FETCH

Retrieves rows returned by a query. Fetches are only performed for SELECT statements.

The other columns of the SQL Trace facility output are combined statistics for all parses, all executes, and all fetches of a statement. The sum of query and current is the total number of buffers accessed, also called Logical I/Os (LIOs). See Table 21-4.

Table 21-4 SQL Trace Statistics for Parses, Executes, and Fetches.

SQL Trace Statistic

Meaning

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. This value is zero (0) if TIMED_STATISTICS is not turned on.

ELAPSED

Total elapsed time in seconds for all parse, execute, or fetch calls for the statement. This value is zero (0) if TIMED_STATISTICS is not turned on.

DISK

Total number of data blocks physically read from the data files 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. Usually, buffers are retrieved in consistent mode for queries.

CURRENT

Total number of buffers retrieved in current mode. Buffers are retrieved in current mode for statements such as INSERT, UPDATE, and DELETE.

Statistics about the processed rows appear in the ROWS column. See Table 21-5.

Table 21-5 SQL Trace Statistics for the ROWS Column

SQL Trace Statistic

Meaning

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.

Note:

The row source counts are displayed when a cursor is closed. In SQL*Plus, there is only one user cursor, so each statement executed causes the previous cursor to be closed; therefore, the row source counts are displayed. PL/SQL has its own cursor handling and does not close child cursors when the parent cursor is closed. Exiting (or reconnecting) causes the counts to be displayed.

21.4.4.2 Row Source Operations

Row source operations provide the number of rows processed for each operation executed on the rows and additional row source information, such as physical reads and writes. The following is a sample:

In addition, wait events are summed for the entire trace file at the end of the file.

To ensure that wait events information is written to the trace file for the session, run the following SQL statement:

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

21.4.4.4 Interpreting the Resolution of Statistics

Timing statistics have a resolution of one hundredth of a second; therefore, any operation on a cursor that takes a hundredth of a second or less might 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.

21.4.4.5 Understanding Recursive Calls

Sometimes, to execute a SQL statement issued by a user, Oracle Database 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, then Oracle Database 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, then TKPROF produces statistics for the recursive SQL statements and marks them clearly as recursive SQL statements in the output file. You can suppress the listing of Oracle Database internal recursive calls (for example, space management) in the output file by setting the SYS command-line parameter to NO. 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, consider the statistics for that statement and those for recursive calls caused by that statement.

Note:

Recursive SQL statistics are not included for SQL-level operations.

21.4.4.6 Library Cache Misses in TKPROF

TKPROF also lists the number of library cache misses resulting from parse and execute steps for each SQL statement. These statistics appear on separate lines following the tabular statistics. If the statement resulted in no library cache misses, then TKPROF does not list the statistic. In "Sample TKPROF Output", the statement resulted in one library cache miss for the parse step and no misses for the execute step.

21.4.4.7 Statement Truncation in SQL Trace

The following SQL statements are truncated to 25 characters in the SQL Trace file:

SET ROLE
GRANT
ALTER USER
ALTER ROLE
CREATE USER
CREATE ROLE

21.4.4.8 Identification of User Issuing the SQL Statement in TKPROF

TKPROF also lists the user ID of the user issuing each SQL statement. If the SQL Trace input file contained statistics from multiple users, and if the statement was issued by multiple users, then TKPROF lists the ID of the last user to parse the statement. The user ID of all database users appears in the data dictionary in the column ALL_USERS.USER_ID.

21.4.4.9 Execution Plan in TKPROF

If you specify the EXPLAIN parameter on the TKPROF statement line, then TKPROF uses the EXPLAINPLAN statement to generate the execution plan of each SQL statement traced. TKPROF also displays the number of rows processed by each step of the execution plan.

Note:

Trace files generated immediately after instance startup contain data that reflects the activity of the startup process. In particular, they reflect a disproportionate amount of I/O activity as caches in the system global area (SGA) are filled. For the purposes of tuning, ignore such trace files.

21.4.4.10 Deciding Which Statements to Tune

You need to find which SQL statements use the most CPU or disk resource. If the TIMED_STATISTICS parameter is on, then you can find high CPU activity in the CPU column. If TIMED_STATISTICS is not on, then check the QUERY and CURRENT columns.

With the exception of locking problems and inefficient PL/SQL loops, neither the CPU time nor the elapsed time is necessary to find problem statements. The key is the number of block visits, both query (that is, subject to read consistency) and current (that is, not subject to read consistency). Segment headers and blocks that are going to be updated are acquired in current mode, but all query and subquery processing requests the data in query mode. These are precisely the same measures as the instance statistics CONSISTENTGETS and DBBLOCKGETS. You can find high disk activity in the disk column.

The following listing shows TKPROF output for one SQL statement as it appears in the output file:

If it is acceptable to have 7.01 CPU seconds and to retrieve 824 rows, then you need not look any further at this trace output. In fact, a major use of TKPROF reports in a tuning exercise is to eliminate processes from the detailed tuning phase.

You can also see that 10 unnecessary parse call were made (because there were 11 parse calls for this one statement) and that array fetch operations were performed. You know this because more rows were fetched than there were fetches performed. A large gap between CPU and elapsed timings indicates Physical I/Os (PIOs).

21.4.5 Step 5: Storing SQL Trace Facility Statistics

You might want to keep a history of the statistics generated by the SQL Trace facility for an application, and compare them over time. TKPROF can generate a SQL script that creates a table and inserts rows of statistics into it. This script contains:

A CREATETABLE 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.

After running TKPROF, you can run this script to store the statistics in the database.

21.4.5.1 Generating the TKPROF Output SQL Script

When you run TKPROF, use the INSERT parameter to specify the name of the generated SQL script. If you omit this parameter, then TKPROF does not generate a script.

21.4.5.2 Editing the TKPROF Output SQL Script

After TKPROF has created the SQL script, you might want to edit the script before running it. If you have created an output table for previously collected statistics, and if you want to add new statistics to this table, then remove the CREATETABLE statement from the script. The script then inserts the new rows into the existing table.

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

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.

This is the SQL statement for which the SQL Trace facility collected the row of statistics. Because this column has data type LONG, you cannot use it in expressions or WHERE clause conditions.

DATE_OF_INSERT

This is the date and time when the row was inserted into the table. This value is not exactly the same as the time the statistics were collected by the SQL Trace facility.

DEPTH

This indicates the level of recursion at which the SQL statement was issued. For example, a value of 0 indicates that a user issued the statement. A value of 1 indicates that Oracle Database generated the statement as a recursive call to process a statement with a value of 0 (a statement issued by a user). A value of n indicates that Oracle Database generated the statement as a recursive call to process a statement with a value of n-1.

USER_ID

This identifies the user issuing the statement. This value also appears in the formatted output file.

CURSOR_NUM

Oracle database uses this column value to keep track of the cursor to which each SQL statement was assigned.

The output table does not store the statement's execution plan. The following query returns the statistics from the output table. These statistics correspond to the formatted output shown in the section "Sample TKPROF Output".

21.5 Avoiding Pitfalls in TKPROF Interpretation

21.5.1 Avoiding the Argument Trap

If you are not aware of the values being bound at run time, then it is possible to fall into the argument trap. EXPLAINPLAN cannot determine the type of a bind variable from the text of SQL statements, and it always assumes that the type is varchar. If the bind variable is actually a number or a date, then TKPROF can cause implicit data conversions, which can cause inefficient plans to be executed. To avoid this situation, experiment with different data types in the query.

21.5.2 Avoiding the Read Consistency Trap

The next example illustrates the read consistency trap. Without knowing that an uncommitted transaction had made a series of updates to the NAME column, it is very difficult to see why so many block visits would be incurred.

Cases like this are not normally repeatable: if the process were run again, it is unlikely that another transaction would interact with it in the same way.

21.5.3 Avoiding the Schema Trap

This example shows an extreme (and thus easily detected) example of the schema trap. At first, it is difficult to see why such an apparently straightforward indexed query needs to look at so many database blocks, or why it should access any blocks at all in current mode.

Two statistics suggest that the query might have been executed with a full table scan. These statistics are the current mode block visits, plus the number of rows originating from the Table Access row source in the execution plan. The explanation is that the required index was built after the trace file had been produced, but before TKPROF had been run.

One of the marked features of this correct version is that the parse call took 10 milliseconds of CPU time and 20 milliseconds of elapsed time, but the query apparently took no time at all to execute and perform the fetch. These anomalies arise because the clock tick of 10 milliseconds is too long relative to the time taken to execute and fetch the data. In such cases, it is important to get lots of executions of the statements, so that you have statistically valid numbers.

21.5.4 Avoiding the Time Trap

Sometimes, as in the following example, you might wonder why a particular query has taken so long.

Again, the answer is interference from another transaction. In this case, another transaction held a shared lock on the table cq_names for several seconds before and after the update was issued. It takes a fair amount of experience to diagnose that interference effects are occurring. On the one hand, comparative data is essential when the interference is contributing only a short delay (or a small increase in block visits in the previous example). However, if the interference contributes only modest overhead, and if the statement is essentially efficient, then its statistics may not require analysis.

21.6 Sample TKPROF Output

This section provides an example of TKPROF output. Portions have been edited out for the sake of brevity.