TKPROF

TKPROF stands for Transient Kernel PROFiler.

The TKPROF program converts Oracle trace files into a more readable form. If you have a problem query you can use TKPROF to get more information. To get the most out of the utility you must enable timed statistics by setting the init.ora parameter or performing the following command:

SQL> ALTER SYSTEM SET TIMED_STATISTICS = TRUE;
System altered.

SQL> @D:\oracle\product\10.2.0\db_1\RDBMS\ADMIN\utlxplan.sql;
Table created.

SQL> CREATE PUBLIC SYNONYM PLAN_TABLE FOR SYS.PLAN_TABLE;
Synonym created.

SQL> GRANT SELECT, INSERT, UPDATE, DELETE ON SYS.PLAN_TABLE TO PUBLIC;
Grant succeeded.

SQL> conn hr/hr@rock
Connected.

SQL> ALTER SESSION SET SQL_TRACE = TRUE;
Session altered.
SQL> select count(*) from cat;
COUNT(*)
----------
20

SQL> ALTER SESSION SET SQL_TRACE = FALSE;
Session altered.

A trace file will be created at D:\oracle\product\10.2.0\admin\rock\udump, the new trace file is rock_ora_4844.trc. This can then be interpreted using TKPROF at the commmand prompt as follows:

H:\>tkprof D:\oracle\product\10.2.0\admin\rock\udump\rock_ora_4844.trc D:\oracle\product\10.2.0\admin\rock\udump\hr.txt explain=hr/hr@rock table=sys.plan_table

The resulting output file contains the following type of information for all SQL statements processed, including the ALTER SESSION commands:

----------------------------------------------------------------------------------------
TKPROF: Release 10.2.0.1.0 - Production on Tue May 12 11:38:44 2009
Copyright (c) 1982, 2005, Oracle. All rights reserved.
Trace file: D:\oracle\product\10.2.0\admin\rock\udump\rock_ora_4844.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
********************************************************************************
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.00-------0-------0---------0----------0-----
Fetch----0------0.00----0.00-------0-------0---------0----------0-----
------- ------ -------- ---------- ---------- ---------- ---------- ---------
total-----1-------0.00----0.00-------0------0----------0----------0-----

Misses in library cache during parse: 0
Misses in library cache during execute: 1
Optimizer mode: ALL_ROWS
Parsing user id: 169 (HR)
********************************************************************************
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.00------0-------0----------0---------0-----
Fetch----1-----0.00----0.00------ 0-------2----------0---------1-----
------- ------ -------- ---------- ---------- ---------- ---------- --------
total-----3-----0.00----0.00-------0-------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=0 pw=0 time=22 us)
********************************************************************************
select count(*)
from cat

call -----count---cpu---elapsed---disk-----query----current---- rows--
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse-----1-----0.00---0.06------0--------0---------0---------0--------
Execute--1------0.00---0.00------0--------0---------0---------0--------
Fetch----2------0.00---0.01------0---------968------0----------1--------
------- ------ -------- ---------- ---------- ---------- ---------- -----------
total-----4------0.00----0.07-----0---------968------0----------1--------
Misses in library cache during parse: 1
Optimizer mode: ALL_ROWS
Parsing user id: 169 (HR)

Rows Row Source Operation
------- ---------------------------------------------------
1 SORT AGGREGATE (cr=968 pr=0 pw=0 time=10364 us)
20 FILTER (cr=968 pr=0 pw=0 time=10117 us)
45 TABLE ACCESS FULL OBJ$ (cr=920 pr=0 pw=0 time=9744 us)
0 TABLE ACCESS CLUSTER TAB$ (cr=48 pr=0 pw=0 time=266 us)
16 INDEX UNIQUE SCAN I_OBJ# (cr=32 pr=0 pw=0 time=126 us)(object id 3)

error during execute of EXPLAIN PLAN statement
ORA-01039: insufficient privileges on underlying objects of the view
parse error offset: 84
********************************************************************************
ALTER SESSION SET SQL_TRACE = FALSE
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-----0------0.00---0.00-----0--------0---------0----------0------
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total------2-------0.00---0.00-----0-------0---------0----------0-------
Misses in library cache during parse: 1
Optimizer mode: ALL_ROWS
Parsing user id: 169 (HR)

********************************************************************************
OVERALL TOTALS FOR ALL NON-RECURSIVE STATEMENTS
call -----count---cpu---elapsed---disk-----query----current---- rows--
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse----2-------0.00---0.06-----0--------0----------0--------0-------
Execute--3-------0.00---0.00-----0--------0----------0--------0-------
Fetch-----2-------0.00---0.01-----0--------968-------0---------1------
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total------7--------0.00---0.07----0--------968--------0--------1-------

Misses in library cache during parse: 2
Misses in library cache during execute: 1

OVERALL TOTALS FOR ALL RECURSIVE STATEMENTS
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---------0----------1-----
------- ------ -------- ---------- ---------- ---------- ------- ----------
total-----3------0.00----0.00-----0--------2---------0----------1------

Misses in library cache during parse: 1
Misses in library cache during execute: 1
3 user SQL statements in session.
1 internal SQL statements in session.
4 SQL statements in session.
0 statements EXPLAINed in this session.
********************************************************************************
Trace file: D:\oracle\product\10.2.0\admin\rock\udump\rock_ora_4844.trc
Trace file compatibility: 10.01.00
Sort options: default

1 session in tracefile.
3 user SQL statements in trace file.
1 internal SQL statements in trace file.
4 SQL statements in trace file.
4 unique SQL statements in trace file.
56 lines in trace file.
7 elapsed seconds in trace file.

----------------------------------------------------------------------------------------
http://www.oracle-base.com/articles/8i/TKPROFAndOracleTrace.php