The TKPROF facility accepts as input an SQL trace file and produces a formatted output file. Note that TKPROF can be run on individual or
appended trace files to produce the formatted output file.
The example above generated the following output in file homedev_ora_39896_10046.output.
TKPROF: Release 10.2.0.4.0 - Production on Tue Sep 27 10:30:53 2011
Copyright (c) 1982, 2007, Oracle. All rights reserved.
Trace file: homedev_ora_39896_10046.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
********************************************************************************
select text
from
view$ where rowid=:1
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.00 0.00 0 0 0 0
Execute 1 0.00 0.13 0 0 0 0
Fetch 1 0.00 0.01 1 2 0 1
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 3 0.00 0.14 1 2 0 1
Misses in library cache during parse: 1
Misses in library cache during execute: 1
Optimizer mode: CHOOSE
Parsing user id: SYS (recursive depth: 1)
Rows Row Source Operation
------- ---------------------------------------------------
1 TABLE ACCESS BY USER ROWID VIEW$ (cr=1 pr=1 pw=0 time=15350 us)
Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total Waited
---------------------------------------- Waited ---------- ------------
db file sequential read 1 0.00 0.00
********************************************************************************
select /*+ rule */ bucket_cnt, row_cnt, cache_cnt, null_cnt, timestamp#,
sample_size, minimum, maximum, distcnt, lowval, hival, density, col#,
spare1, spare2, avgcln
from
hist_head$ where obj#=:1 and intcol#=:2
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.00 0.00 0 0 0 0
Execute 1 0.00 0.09 0 0 0 0
Fetch 1 0.00 0.00 0 2 0 0
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 3 0.00 0.09 0 2 0 0
Misses in library cache during parse: 0
Optimizer mode: RULE
Parsing user id: SYS (recursive depth: 2)
Rows Row Source Operation
------- ---------------------------------------------------
0 TABLE ACCESS BY INDEX ROWID HIST_HEAD$ (cr=2 pr=0 pw=0 time=45 us)
0 INDEX RANGE SCAN I_HH_OBJ#_INTCOL# (cr=2 pr=0 pw=0 time=37 us)(object id 257)
Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total Waited
---------------------------------------- Waited ---------- ------------
SQL*Net message to client 1 0.00 0.00
SQL*Net message from client 1 31.84 31.84
********************************************************************************
select count(*)
from
fin_edatt_students_info_vw
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.00 0.07 0 0 0 0
Execute 1 0.00 0.01 0 0 0 0
Fetch 1 0.00 1.94 0 0 0 1
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 3 0.00 2.03 0 0 0 1
Misses in library cache during parse: 1
Optimizer mode: ALL_ROWS
Parsing user id: 1059
Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total Waited
---------------------------------------- Waited ---------- ------------
HS message to agent 4 1.91 1.91
SQL*Net message to client 2 0.00 0.00
SQL*Net message from client 1 0.00 0.00
********************************************************************************
OVERALL TOTALS FOR ALL NON-RECURSIVE STATEMENTS
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.00 0.07 0 0 0 0
Execute 1 0.00 0.01 0 0 0 0
Fetch 1 0.00 1.94 0 0 0 1
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 3 0.00 2.03 0 0 0 1
Misses in library cache during parse: 1
Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total Waited
---------------------------------------- Waited ---------- ------------
SQL*Net message to client 3 0.00 0.00
SQL*Net message from client 2 31.84 31.85
HS message to agent 4 1.91 1.91
OVERALL TOTALS FOR ALL RECURSIVE STATEMENTS
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 2 0.00 0.00 0 0 0 0
Execute 2 0.00 0.22 0 0 0 0
Fetch 2 0.00 0.01 1 4 0 1
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 6 0.00 0.24 1 4 0 1
Misses in library cache during parse: 1
Misses in library cache during execute: 1
Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total Waited
---------------------------------------- Waited ---------- ------------
db file sequential read 1 0.00 0.00
1 user SQL statements in session.
2 internal SQL statements in session.
3 SQL statements in session.
********************************************************************************
Trace file: homedev_ora_39896_10046.trc
Trace file compatibility: 10.01.00
Sort options: default
1 session in tracefile.
1 user SQL statements in trace file.
2 internal SQL statements in trace file.
3 SQL statements in trace file.
3 unique SQL statements in trace file.
82 lines in trace file.
2 elapsed seconds in trace file.
Interpretting TKPROF Output
===========================
The EXPLAIN PLAN Command
------------------------
The EXPLAIN PLAN command displays the execution plan chosen by the
Oracle optimizer for SELECT, UPDATE, INSERT, and DELETE statements.
A statement's execution plan is the sequence of operations that Oracle
performs to execute the statement. By examining the execution plan, you
can see exactly how Oracle executes your SQL statement. This information
can help you determine whether the SQL statement you have written takes
advantage of the indexes available. For the syntax of the EXPLAIN PLAN
command, see the Oracle7 Server SQL Reference Manual.
Creating the Output Table
-------------------------
Before you can issue an EXPLAIN PLAN statement, there must exist a table
to hold its output, you do either of the following:
* Run the SQL script "UTLXPLAN.SQL" to create a sample
output table called PLAN_TABLE in your schema.
* Issue a CREATE TABLE statement to create an output
with any name you choose. You can then issue an
EXPLAIN PLAN statement and direct its output to this
table. Any table used to store the output of the
EXPLAIN PLAN command must have the same column names
and datatypes as the PLAN_TABLE.
SQL Trace Facility 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:
* PARSE
This step translates the SQL statement into an execution plan.
This includes checks for proper security authorization and
checks or 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 & CURRENT is he 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 in
the output file.
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.
No comments:
Post a Comment