Oracle8(TM) Server Tuning
Release 8.0

A54638-01

Library

Product

Contents

Index

Prev Next

22
The SQL Trace Facility and TKPROF

The SQL trace facility and TKPROF are two basic performance diagnostic tools which can help you monitor and tune applications that run against the Oracle Server. This chapter covers:

Note: The output of the EXPLAIN PLAN command reflects the behavior of the Oracle optimizer. Because the optimizer is likely to evolve between releases of the Oracle Server, output from the EXPLAIN PLAN command will also evolve. Similarly, the SQL trace facility and TKPROF program are also subject to change in future releases of the Oracle Server. Such changes will be documented in future versions of Oracle manuals.

Introduction

The SQL trace facility and TKPROF enable you to accurately assess the efficiency of the SQL statements your application runs. For best results, use these tools together rather than using EXPLAIN PLAN alone. This section covers:

About the SQL Trace Facility

The SQL trace facility provides performance information on individual SQL statements. It generates the following statistics for each statement:

You can enable the SQL trace facility for a session or for an instance. When the SQL trace facility is enabled, performance statistics for all SQL statements executed in a user session or in an instance are placed into a trace file.

The additional overhead of running the SQL trace facility against an application with performance problems is normally insignificant, compared with the inherent overhead caused by the application's inefficiency.

About TKPROF

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

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

How to Use the SQL Trace Facility and TKPROF

Follow these steps to use the SQL trace facility and TKPROF.

  1. Set initialization parameters for trace file management.
  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 ins step 2 into a readable output file. This step can 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.

In the following sections each of these steps is discussed in depth.

Step 1: Setting Initialization Parameters for Trace File Management

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

Before enabling the SQL trace facility, you should:

  1. Check settings of the TIMED_STATISTICS, USER_DUMP_DEST, and MAX_DUMP_FILE_SIZE parameters.
    Table 22-1: SQL Trace Facility Initialization Parameters
    Parameter   Notes  

    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. This is a dynamic parameter.  

    MAX_DUMP_FILE_SIZE  

    When the SQL trace facility is enabled at the instance level, every call to the server produces a text line in an operating system file. The maximum size of these files (in operating system blocks) is limited by the initialization parameter MAX_DUMP_FILE_SIZE. 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 must fully specify the destination for the trace file 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.This value can be modified with ALTER SYSTEM SET USER_DUMP_DEST=newdir.  

  2. Devise a way of recognizing the resulting trace file.
Be sure you know how to distinguish the trace files by name. Oracle writes them to the user dump destination specified by USER_DUMP_DEST. However, this directory may soon contain many hundreds of files, usually with generated names. It may be difficult to match trace files back to the session or process which created them. You can tag trace files by including in your programs a statement like SELECT `program name' FROM DUAL. You can then trace each file back to the process that created it.
  1. 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.
  2. 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.

Step 2: Enabling the SQL Trace Facility

You can enable the SQL trace facility for a session or for the instance. This section covers:

Attention: Because running the SQL trace facility increases system overhead, you should enable it only when tuning your SQL statements, and disable it when you are finished.

Enabling the SQL Trace Facility for Your Current Session

To enable the SQL trace facility for your current session, enter:

ALTER SESSION SET SQL_TRACE = TRUE;

Alternatively, you can enable the SQL trace facility for your session by using the DBMS_SESSION.SET_SQL_TRACE procedure.

To disable the SQL trace facility for your session, enter:

ALTER SESSION SET SQL_TRACE = FALSE;

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

Note: 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.

Enabling the SQL Trace Facility for a Different User Session

To enable the SQL trace facility for a session other than your current session, you can call the procedure DBMS_SYSTEM.SET_SQL_TRACE_IN_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 question, which you can obtain from the V$SESSION view. In the WHERE clause you can specify sessions by referencing the value of the OSUSER, USERNAME, or PROGRAM column in V$SESSION. For example, the following Server Manager line mode session obtains the session ID and serial number for the operating system user jausten and then enables SQL trace for that user's session:

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

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

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

To enable SQL trace in stored procedures, use this SQL statement:

DBMS_SESSION.SET_SQL_TRACE (TRUE);

Enabling the SQL Trace Facility for an Instance

To enable the SQL trace facility for your instance, set the value of the SQL_TRACE initialization parameter to TRUE. Statistics will be collected for all sessions.

Once the SQL trace facility has been enabled for the instance, you can disable it for an individual session by entering:

ALTER SESSION SET SQL_TRACE = FALSE;

Step 3: Formatting Trace Files with TKPROF

This section covers:

TKPROF accepts as input a trace file produced by the SQL trace facility and produces a formatted output file. TKPROF can also be used to generate execution plans.

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

TKPROF does not report COMMITs and ROLLBACKs that are recorded in the trace file.

Sample TKPROF Output

Sample output from TKPROF is as follows:

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) SCOTT


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 includes the following information:

TKPROF also provides a summary of user level statements and recursive SQL calls for the trace file.

Syntax of TKPROF

Invoke TKPROF using this syntax:

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

Use the following arguments with TKPROF:

Table 22-2: TKPROF Arguments
Argument   Meaning  

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.  

AGGREGATE  

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

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. TKPROF will take longer to process a large trace file if the EXPLAIN option is used.  

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 all rows in the table, uses it for the EXPLAIN PLAN command (which writes more rows into the table), and then deletes those 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 Oracle8 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 order of first use.

The sort options are 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  

PRSMIS  

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.  

TKPROF Statement Examples

This section provides two brief examples of TKPROF usage. For an extensive example of TKPROF output, see "Sample TKPROF Output" on page 22-7.

Example 1

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

TKPROF ora53269.trc ora 53269.prf
SORT = (PRSDSK, EXEDSK, FCHDSK)
PRINT = 10

Example 2

This example runs TKPROF, accepts a trace file named dlsun12_jane_fg_svrmgr_007.trc, and writes a formatted output file named outputa.prf:

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

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

Note the other parameters in this example:

Step 4: Interpreting TKPROF Output

This section provides pointers for interpreting TKPROF output.

While TKPROF provides a very useful analysis, the most accurate measure of efficiency is the actual performance of the application in question. Note that 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.

See Also: Oracle8 Server Reference Manual for a description of statistics in V$SYSSTAT and V$SESSTAT.

Tabular Statistics

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. The step for which each row contains statistics is identified by the value of the call column:

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 other columns of the SQL trace facility output are combined statistics for all parses, all executes, and all fetches of a statement. These values are zero (0) if TIMED_STATISTICS is not turned on. The sum of query and current is the total number of buffers accessed.

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 retrieved in current mode for statements such as INSERT, UPDATE, and DELETE.  

Rows

Statistics about the processed rows appear in the "rows" column.

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 in order 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 SYS command line parameter to NO suppresses the listing of recursive calls in the output file.

Library Cache Misses

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, TKPROF does not list the statistic. In the example, the statement resulted in one library cache miss for the parse step and no misses for the execute step.

User Issuing the SQL Statement

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 the statement was issued by more than one user, 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.

Execution Plan

If you specify the EXPLAIN parameter on the TKPROF command line, TKPROF uses the EXPLAIN PLAN command 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.

See Also: Chapter 21, "The EXPLAIN PLAN Command" for more information on interpreting execution plans.

Deciding What Statements to Tune

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

SELECT * FROM emp, dept WHERE emp.deptno = dept.deptno;

call count cpu elapsed disk query current rows
---- ------- ------- --------- -------- -------- ------- ------
Parse 11 0.08 0.18 0 0 0 0
Execute 11 0.23 0.66 0 3 6 2
Fetch 35 6.70 6.83 100 12326 2 824
------------------------------------------------------------------
total 57 7.01 7.67 100 12329 8 826

Misses in library cache during parse: 0

10 user SQL statements in session.
0 internal SQL statements in session.
10 SQL statements in session.

If it is acceptable to expend 7.01 CPU seconds to insert, update or delete 2 rows 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 from this summary that 1 unnecessary parse call was made (because there were more parse calls than SQL statements) and that array fetch operations were performed. (You know this because more rows were fetched than there were fetches performed.)

Finally, you can see that very little physical I/O was performed; this is suspicious and probably means that the same database blocks were being continually re-visited.

Having established that the process has used excessive resource, the next step is to discover which SQL statements are the culprits. Normally only a small percentage of the SQL statements in any process need to be tuned, and these are the ones which use the greatest resource.

The examples which follow were all produced with TIMED_STATISTICS=TRUE. However, with the exception of locking problems and inefficient PL/SQL loops, neither the CPU nor the elapsed time are necessary to find the problem statements. The key is the number of block visits both query (that is, subject to read consistency) and current (not subject to read consistency). Segment headers and blocks which are going to be updated are always acquired in current mode, but all query and sub-query processing requests the data in query mode. These are precisely the same measures as the instance statistics consistent gets and db block gets.

The SQL parsed as SYS is recursive SQL used to maintain the dictionary cache, and is not normally of great benefit; if the number of internal SQL statements looks high it may be worth checking to see what has been going on. (There may be excessive space management overhead.)

Step 5: Storing SQL Trace Facility Statistics

This section covers:

You may want to keep a history of the statistics generated by the SQL trace facility for your 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

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

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, TKPROF does not generate a script.

Editing the TKPROF Output SQL Script

After TKPROF has created the SQL script, you may want to edit the script before running it.

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

The following CREATE TABLE statement creates the TKPROF_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:

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.  

The following query returns the statistics from the output table. These statistics correspond to the formatted output shown in the section "Step 4: Interpreting TKPROF Output" on page 22-12.

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  

Avoiding Pitfalls in TKPROF Interpretation

This section describes some fine points of TKPROF interpretation:

See Also: "EXPLAIN PLAN Restrictions" on page 21-16 for information about TKPROF and bind variables.

Finding the Statements Which Constitute the Bulk of the Load

Look at the totals and try to identify the statements which constitute the bulk of the load.

Do not attempt to perform many different jobs within a single query. It is more effective to separate out the different queries which should be used when certain optional parameters are present, and when the parameters provided contain wild cards.

If certain parameters are not specified by the report user, the query uses bind variables which have been set to "%" to cause the LIKE clauses in the query to operate as if they were not there. It would be more efficient to run a query in which these clauses are not present.

Note: TKPROF cannot tell the TYPE of the bind variables simply by looking at the text of the SQL statement. It assumes that TYPE is CHARACTER; if this is not the case, you should put appropriate type conversions in the SQL statement.

The Argument Trap

Especially where the LIKE operator is used, the query may be markedly less efficient for certain values, or types of value, in a bind variable. This is because the optimizer must make an assumption about the probable selectivity without knowing the value. If you are not aware of the values being bound at run time then it is possible to fall into the "argument trap".

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.

select NAME_ID
from CQ_NAMES where NAME = 'FLOOR'
call count cpu elapsed disk query current rows
---- ----- --- ------- ---- ----- ------- ----
Parse 1 0.11 0.21 0 0 0 0
Execute 1 0.00 0.00 0 0 0 0
Fetch 1 0.15 0.24 4 150 0 1
Misses in library cache during parse: 1
Parsing user id: 13 (DJONES)
Rows Execution Plan
---- --------- ----
0 SELECT STATEMENT
1 TABLE ACCESS (BY ROWID) OF 'CQ_NAMES'
2 INDEX (RANGE SCAN) OF 'CQ_NAMES_NAME' (NON_UNIQUE)

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.

select NAME_ID
from CQ_NAMES where NAME = 'FLOOR'

call count cpu elapsed disk query current rows
-------- ------- -------- --------- ------- ------ ------- ----
Parse 1 0.04 0.12 0 0 0 0
Execute 1 0.01 0.01 0 0 0 0
Fetch 1 0.32 0.32 38 44 3 1

Misses in library cache during parse: 0
Parsing user id: 13 (JAUSTEN

Rows Execution Plan
------- ---------------------------------------------------
0 SELECTSTATEMENT
3519 TABLE ACCESS (BY ROWID) OF 'CQ_NAMES'
0 INDEX (RANGE SCAN) OF 'CQ_NAMES_NAME' (NON-UNIQUE)

Two statistics suggest that the query may have been executed via 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.

The Time Trap

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

update CQ_NAMES set ATTRIBUTES = lower(ATTRIBUTES)
where ATTRIBUTES = :att

call count cpu elapsed disk query current rows
-------- ------- -------- --------- -------- -------- ------- ------ ----
Parse 1 0.08 0.24 0 0 0 0
Execute 1 0.63 19.63 33 526 13 7
Fetch 0 0.00 0.00 0 0 0 0

Misses in library cache during parse: 1
Parsing user id: 13 (JAUSTEN)

Rows Execution Plan
------- ---------------------------------------------------
0 UPDATE STATEMENT
3519 TABLE ACCESS (FULL) OF 'CQ_NAMES' 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. Comparative data is essential when the interference is only contributing a short delay (or a small increase in block visits in the previous example). On the other hand, if the interference is only contributing a modest overhead, and the statement is essentially efficient, its statistics may never have to be subjected to analysis.

The Trigger Trap

The resources reported for a statement include those for all of the SQL issued while the statement was being processed. They therefore include any resources used within a trigger, along with the resources used by any other recursive SQL (such as that used in space allocation). With the SQL trace facility enabled, TKPROF will report these resources twice. Avoid trying to tune the DML statement, if the resource is actually being consumed at a lower level of recursion.

You may need to inspect the raw trace file to see exactly where the resource is being expended. The entries for recursive SQL follow the PARSING IN CURSOR entry for the user's statement. Within the trace file, the order is less easily defined.

The "Correct" Version

For comparison with the output which results from one of these traps having sprung, here is the TKPROF output for the indexed query with the index in place and without any contention effects.

select NAME_ID
from CQ_NAMES where NAME = 'FLOOR'

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

Misses in library cache during parse: 0
Parsing user id: 13 (JAUSTEN)

Rows Execution Plan
------- ---------------------------------------------------
0 SELECT STATEMENT
1 TABLE ACCESS (BY ROWID) OF 'CQ_NAMES'
2 INDEX (RANGE SCAN) OF 'CQ_NAMES_NAME' (NON-UNIQUE)

One of the marked features of this correct version is that the parse call took 10 milliseconds of both elapsed and CPU time, but the query apparently took no time at all to execute and no time at all to perform the fetch. In fact, no parse took place because the query was already available in parsed form within the shared SQL area. These anomalies are due to the clock tick of 10 msec being too long to reliably record simple and efficient queries.

TKPROF Sample Output

This section provides an extensive example of TKPROF output. Note that portions have been edited out for the sake of brevity.

Header


Copyright (c) Oracle Corporation 1979, 1997.  All rights reserved.
Trace file: v80_ora_2758.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
******************************************************************************** The following statement encountered a error during parse: select deptno, avg(sal) from emp e group by deptno
having exists (select deptno from dept
where dept.deptno = e.deptno
and dept.budget > avg(e.sal)) order by 1 Error encountered: ORA-00904
********************************************************************************

Body


alter session set sql_trace = true
call     count       cpu    elapsed       disk      query    current        rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 0 0.00 0.00 0 0 0 0
Execute 1 0.00 0.15 0 0 0 0
Fetch 0 0.00 0.00 0 0 0 0
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 1 0.00 0.15 0 0 0 0 Misses in library cache during parse: 0
Misses in library cache during execute: 1
Optimizer goal: CHOOSE
Parsing user id: 8 (SCOTT) . . .
******************************************************************************** select emp.ename, dept.dname from emp, dept
where emp.deptno = dept.deptno call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.12 0.14 2 0 2 0
Execute 1 0.00 0.00 0 0 0 0
Fetch 1 0.00 0.00 2 2 4 14
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 3 0.12 0.14 4 2 6 14 Misses in library cache during parse: 1
Optimizer goal: CHOOSE
Parsing user id: 8 (SCOTT) Rows Execution Plan
------- ---------------------------------------------------
0 SELECT STATEMENT GOAL: CHOOSE
14 MERGE JOIN
4 SORT (JOIN)
4 TABLE ACCESS (FULL) OF 'DEPT'
14 SORT (JOIN)
14 TABLE ACCESS (FULL) OF 'EMP' ******************************************************************************** select a.ename name, b.ename manager from emp a, emp b
where a.mgr = b.empno(+) call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.01 0.01 0 0 0 0
Execute 1 0.00 0.00 0 0 0 0
Fetch 1 0.01 0.01 1 54 2 14
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 3 0.02 0.02 1 54 2 14 Misses in library cache during parse: 1
Optimizer goal: CHOOSE
Parsing user id: 8 (SCOTT) Rows Execution Plan
------- ---------------------------------------------------
0 SELECT STATEMENT GOAL: CHOOSE
13 NESTED LOOPS (OUTER)
14 TABLE ACCESS (FULL) OF 'EMP'
13 TABLE ACCESS (BY ROWID) OF 'EMP'
26 INDEX (RANGE SCAN) OF 'EMP_IND' (NON-UNIQUE) . . . ******************************************************************************** select ename,job,sal
from emp
where sal =
(select max(sal)
from emp) 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 16 4 1
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 3 0.00 0.00 0 16 4 1 Misses in library cache during parse: 1
Optimizer goal: CHOOSE
Parsing user id: 8 (SCOTT) Rows Execution Plan
------- ---------------------------------------------------
0 SELECT STATEMENT GOAL: CHOOSE
14 FILTER
14 TABLE ACCESS (FULL) OF 'EMP'
14 SORT (AGGREGATE)
14 TABLE ACCESS (FULL) OF 'EMP' ******************************************************************************** select deptno
from emp
where job = 'clerk'
group by deptno
having count(*) >= 2 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 1 2 0
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 3 0.00 0.00 0 1 2 0 Misses in library cache during parse: 1
Optimizer goal: CHOOSE
Parsing user id: 8 (SCOTT) Rows Execution Plan
------- ---------------------------------------------------
0 SELECT STATEMENT GOAL: CHOOSE
0 FILTER
0 SORT (GROUP BY)
14 TABLE ACCESS (FULL) OF 'EMP' ******************************************************************************** select dept.deptno,dname,job,ename
from dept,emp
where dept.deptno = emp.deptno(+)
order by dept.deptno 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 2 4 15
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 3 0.00 0.00 0 2 4 15 Misses in library cache during parse: 1
Optimizer goal: CHOOSE
Parsing user id: 8 (SCOTT) Rows Execution Plan
------- ---------------------------------------------------
0 SELECT STATEMENT GOAL: CHOOSE
14 MERGE JOIN (OUTER)
4 SORT (JOIN)
4 TABLE ACCESS (FULL) OF 'DEPT'
14 SORT (JOIN)
14 TABLE ACCESS (FULL) OF 'EMP' ******************************************************************************** select grade,job,ename,sal
from emp,salgrade
where sal between losal and hisal
order by grade,job call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.06 0.08 2 18 1 0
Execute 1 0.00 0.00 0 0 0 0
Fetch 1 0.01 0.01 1 11 12 14
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 3 0.07 0.09 3 29 13 14 Misses in library cache during parse: 1
Optimizer goal: CHOOSE
Parsing user id: 8 (SCOTT) Rows Execution Plan
------- ---------------------------------------------------
0 SELECT STATEMENT GOAL: CHOOSE
14 SORT (ORDER BY)
14 NESTED LOOPS
5 TABLE ACCESS (FULL) OF 'SALGRADE'
70 TABLE ACCESS (FULL) OF 'EMP' ******************************************************************************** select lpad(' ',level*2)||ename org_chart,level,empno,mgr,job,deptno
from emp
connect by prior empno = mgr
start with ename = 'clark'
or ename = 'blake'
order by deptno call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.01 0.01 0 0 0 0
Execute 1 0.00 0.00 0 0 0 0
Fetch 1 0.01 0.01 0 1 2 0
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 3 0.02 0.02 0 1 2 0 Misses in library cache during parse: 1
Optimizer goal: CHOOSE
Parsing user id: 8 (SCOTT) Rows Execution Plan
------- ---------------------------------------------------
0 SELECT STATEMENT GOAL: CHOOSE
0 SORT (ORDER BY)
0 CONNECT BY
14 TABLE ACCESS (FULL) OF 'EMP'
0 TABLE ACCESS (BY ROWID) OF 'EMP'
0 TABLE ACCESS (FULL) OF 'EMP' ******************************************************************************** create table tkoptkp (a number, b number) call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.00 0.00 0 0 0 0
Execute 1 0.01 0.01 1 0 1 0
Fetch 0 0.00 0.00 0 0 0 0
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 2 0.01 0.01 1 0 1 0 Misses in library cache during parse: 1
Optimizer goal: CHOOSE
Parsing user id: 8 (SCOTT) Rows Execution Plan
------- ---------------------------------------------------
0 CREATE TABLE STATEMENT GOAL: CHOOSE . . . ******************************************************************************** insert into tkoptkp
values
(1,1) call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.07 0.09 0 0 0 0
Execute 1 0.01 0.20 2 2 3 1
Fetch 0 0.00 0.00 0 0 0 0
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 2 0.08 0.29 2 2 3 1 Misses in library cache during parse: 1
Optimizer goal: CHOOSE
Parsing user id: 8 (SCOTT) Rows Execution Plan
------- ---------------------------------------------------
0 INSERT STATEMENT GOAL: CHOOSE . . . ******************************************************************************** insert into tkoptkp select * from tkoptkp call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.00 0.00 0 0 0 0
Execute 1 0.02 0.04 0 2 3 12
Fetch 0 0.00 0.00 0 0 0 0
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 2 0.02 0.04 0 2 3 12 Misses in library cache during parse: 1
Optimizer goal: CHOOSE
Parsing user id: 8 (SCOTT) Rows Execution Plan
------- ---------------------------------------------------
0 INSERT STATEMENT GOAL: CHOOSE
12 TABLE ACCESS (FULL) OF 'TKOPTKP' ******************************************************************************** select *
from
tkoptkp where a > 2 call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.01 0.01 0 0 0 0
Execute 1 0.00 0.00 0 0 0 0
Fetch 1 0.00 0.00 0 1 2 12
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 3 0.01 0.01 0 1 2 12 Misses in library cache during parse: 1
Optimizer goal: CHOOSE
Parsing user id: 8 (SCOTT) Rows Execution Plan
------- ---------------------------------------------------
0 SELECT STATEMENT GOAL: CHOOSE
24 TABLE ACCESS (FULL) OF 'TKOPTKP' ********************************************************************************

Summary


OVERALL TOTALS FOR ALL NON-RECURSIVE STATEMENTS
call     count       cpu    elapsed       disk      query    current        rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 18 0.40 0.53 30 182 3 0
Execute 19 0.05 0.41 3 7 10 16
Fetch 12 0.05 0.06 4 105 66 78
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 49 0.50 1.00 37 294 79 94 Misses in library cache during parse: 18
Misses in library cache during execute: 1 OVERALL TOTALS FOR ALL RECURSIVE STATEMENTS call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 69 0.49 0.60 9 12 8 0
Execute 103 0.13 0.54 0 0 0 0
Fetch 213 0.12 0.27 40 435 0 162
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 385 0.74 1.41 49 447 8 162 Misses in library cache during parse: 13 19 user SQL statements in session.
69 internal SQL statements in session.
88 SQL statements in session.
17 statements EXPLAINed in this session.
********************************************************************************
Trace file: v80_ora_2758.trc
Trace file compatibility: 7.03.02
Sort options: default 1 session in tracefile.
19 user SQL statements in trace file.
69 internal SQL statements in trace file.
88 SQL statements in trace file.
41 unique SQL statements in trace file.
17 SQL statements EXPLAINed using schema:
SCOTT.prof$plan_table
Default table was used.
Table was created.
Table was dropped.
1017 lines in trace file.




Prev

Next
Oracle
Copyright © 1997 Oracle Corporation.

All Rights Reserved.

Library

Product

Contents

Index