Oracle tkprof utility : How to generate and read

We saw how to enable trace in Oracle in an earlier post. The trace files obtained from the method are in raw form which can be converted into a more readable format using the tkprof utility in Oracle (Transient Kernel PROFile utility)

Table of Contents

tkprof utility in Oracle

TKPROF is a tool for producing formatted reports from SQL Trace files (also known as event 10046 trace files).
Each SQL (and PL/SQL) statement appearing in the trace file has its information summarized and collected in one place in the TKPROF report.

This information includes: the number of parse, execution & fetch operations, total CPU & elapsed times, buffers read in consistent (query) and current mode, blocks read from disk and row counts, Row Source operations, execution plans, library cache misses, parsing user id & optimizer mode
The most important part of tkprof is the sort option. This helps us identify the most resource-intensive SQL statements and helps target efficiently the SQL tuning process

The syntax is given below

tkprof
Usage: tkprof tracefile outputfile [explain= ] [table= ]
[print= ] [insert= ] [sys= ] [sort= ]
table=schema.tablename   Use 'schema.tablename' with 'explain=' option.
explain=user/password    Connect to ORACLE and issue EXPLAIN PLAN.
print=integer    List only the first 'integer' SQL statements.
aggregate=yes|no
insert=filename  List SQL statements and data inside INSERT statements.
sys=no           TKPROF does not list SQL statements run as user SYS.
record=filename  Record non-recursive statements found in the trace file.
waits=yes|no     Record summary for any wait events found in the trace file.
sort=option      Set of zero or more of the following sort options:
prscnt  number of times parse was called
prscpu  CPU time parsing
prsela  elapsed time parsing    
prsdsk  number of disk reads during parse 
prsqry  number of buffers for consistent read during 
parseprscu   number of buffers for current read during 
parseprsmis  number of misses in library cache during 
parseexecnt  number of execute was called 
execpu  CPU time spent executing exeela  elapsed time executing 
exedsk  number of disk reads during execute 
exeqry  number of buffers for consistent read during execute
execu   number of buffers for current read during execute
exerow  number of rows processed during execute
exemis  number of library cache misses during execute
fchcnt  number of times fetch was called
fchcpu  cpu time spent fetching
fchela  elapsed time fetching
fchdsk  number of disk reads during fetch
fchqry  number of buffers for consistent read during fetch
fchcu   number of buffers for current read during fetch
fchrow  number of rows fetched
userid  userid of user that parsed the cursor

Since we are usually interested in tuning statements that take more time to run as time is the most important property in the tuning, so most commonly used sort options are the ones ordering according to elapsed times consumed for the parse, execute, and fetch phases

sort=prsela,exeela,fchela

tkprof examples

If you just want the tkprof without any filter
tkprof file.trc file.txt

If you just want the tkprof without recursive SQL  statement
What is recursive calls:f 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

tkprof file.trc file.txt sys=no

If you just want the tkprof with latest explain from the user executing it
tkprof file.trc file.txt sys=no explain=userid/password 

If you just want the tkprof  with sort
tkprof file.trc file.txt sys=no explain=userid/password sort=prsela,exeela,fchela

This print 10 sql only
tkprof .trc elaps.prf sys=no explain=apps/ sort=(prsela,exeela,fchela) print=10

This print all the sql
tkprof .trc elaps.prf sys=no explain=apps/apps sort=prsela,exeela,fchela

Example content of tkprof file

TKPROF: Release 11.2.0.4.0 - Production on Tue Jan 17 14:12:41 2013
Copyright (c) 1982, 2007, Oracle.  All rights reserved.
Trace file: TEST_ora_15941.trc
Sort options: execpu  fchcpu
********************************************************************************
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
********************************************************************************
SQL ID: 6w82ggrtysx
Plan Hash: 2325776775
SELECT FUNCTION_NAME    FROM FND_USER_DESKTOP_OBJECTS  WHERE USER_ID = :b1  AND APPLICATION_ID = :b2  AND  RESPONSIBILITY_ID = :b3  AND TYPE = 'FUNCTION'  AND ROWNUM <= 10 ORDER BY SEQUENCE
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        2      0.00       0.00          0          4          0           1
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        4      0.00       0.00          0          4          0           1
Misses in library cache during parse: 0
Optimizer mode: ALL_ROWS
Parsing user id: 173  (APPS)
Number of plan statistics captured: 1
Rows (1st) Rows (avg) Rows (max)  Row Source Operation
---------- ---------- ----------  ---------------------------------------------------
1          1          1  SORT ORDER BY (cr=4 pr=0 pw=0 time=0 us cost=6 size=41 card=1)
1          1          1   COUNT STOPKEY (cr=4 pr=0 pw=0 time=0 us)
1          1          1    TABLE ACCESS BY INDEX ROWID FND_USER_DESKTOP_OBJECTS (cr=4 pr=0 pw=0 time=0 us cost=5 size=41 card=1)
1          1          1     INDEX RANGE SCAN FND_USER_DESKTOP_OBJECTS_N1 (cr=3 pr=0 pw=0 time=0 us cost=3 size=0 card=3)(object id 33596)
Rows     Execution Plan
-------  ---------------------------------------------------
0  SELECT STATEMENT   MODE: ALL_ROWS
1   SORT (ORDER BY)
1    COUNT (STOPKEY)
1     TABLE ACCESS   MODE: ANALYZED (BY INDEX ROWID) OF
'FND_USER_DESKTOP_OBJECTS' (TABLE)
1      INDEX   MODE: ANALYZED (RANGE SCAN) OF
'FND_USER_DESKTOP_OBJECTS_N1' (INDEX)
Elapsed times include waiting on following events:
Event waited on                             Times   Max. Wait  Total Waited
----------------------------------------   Waited  ----------  ------------
SQL*Net message to client                       5        0.00          0.00
SQL*Net message from client                     5        0.00          0.00********************************************************************************
SQL ID: 276ut2ywqux
Plan Hash: 3856112528
select object_name, icon_name
from
fnd_desktop_objects
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        3      0.00       0.00          0          6          0          47
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        5      0.00       0.00          0          6          0          47
Misses in library cache during parse: 0
Optimizer mode: ALL_ROWS
Parsing user id: 173  (APPS)
Number of plan statistics captured: 1
Rows (1st) Rows (avg) Rows (max)  Row Source Operation
---------- ---------- ----------  ---------------------------------------------------
47         47         47  TABLE ACCESS FULL FND_DESKTOP_OBJECTS (cr=6 pr=0 pw=0 time=0 us cost=2 size=1175 card=47)
Rows     Execution Plan
-------  ---------------------------------------------------
0  SELECT STATEMENT   MODE: ALL_ROWS
47   TABLE ACCESS   MODE: ANALYZED (FULL) OF 'FND_DESKTOP_OBJECTS'
(TABLE)

Oracle trcsess utility

When using shared server sessions, many processes are involved. 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.
The trcsess utility consolidates trace output from selected trace files based on several criteria

trcsess  [output=output_file_name] [session=session_id] [clientid=client_id] [service=service_name] [action=action_name] [module=module_name] [trace_files]

trcsess output=main.trc service=TEST  *trc

After the consolidated trace file has been generated you can execute tkprof on it.

How to read the tkprof file in Oracle

Once the tkprof is generated, Now we need to read it. Tkprof will contain several sql statement sections and it depends on the options chosen while generating the tkprof

Each sql statement section covers below important details

The text of the SQLs executed.
The execution count, elapsed time, CPU time, physical reads (disk), logical reads (query/current) and the number of rows returned for each SQL. This is further broken down into Parse, Execute and Fetch stages.

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.
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 runtime execution plan for each SQL with the actual row source operation counts for each execution plan line. It only does this if the row source statistics for the SQL have been written to the trace (See Extended SQL Trace). These statistics will not be included in any case if timed_statistics is not TRUE.

The execution plan will also contain the actual tables accessed if the SQL uses views or synonyms.
Library cache misses. These are “hard parses”; no execution plan is available in library cache and the optimizer has to determine an execution plan.
The row source operation counts show the following for each execution plan line: rows, consistent reads (cr), physical reads (pr), physical writes(pw), time

cr: Blocks retrieved through a logical read in the consistent mode
pr: Number of blocks read through a physical disk read
pw: Number of blocks written with a physical write to a disk
time: Total time (in milliseconds) spent processing the operation
cost: Estimated cost of the operation
size: Estimated amount of data (bytes) returned by the operation
card: Estimated number of rows returned by the operation

The times waited, maximum wait and total waited for each database wait event, both for each SQL and for the whole period of the trace. It only does this if the level is 8 (with waits) or 12 (with waits and binds). At least level 8 is recommended because it gives this extra information.

You can easily find the longest sql and then work on tuning it

How to read the tkprof files in Oracle Sql Developer

If you have any SQL Trace (.trc) output files, you can display them in SQL Developer as an alternative to using the TKPROF program to format the contents of the trace file. To open a .trc file in SQL Developer and see an attractive, effective display of the information, click File, then Open, and specify the file; or drag the file’s name or icon into the SQL Developer window.

You can then examine the information in the List View, Statistics View, and History panes, with each pane including options for filtering and controlling the display.

How to read the tkprof files in Excel

Oracle has provided an Excel worksheet available through the link: Download Excel Macro (2M/xls) which has a macro “SetTKProf” that parses a TKProf file and applies filters for “Logical Reads”, “Elapsed Time”, “CPU Time”, “Countof Exectns”, “Physical Reads”, “Rows” and “%ge Recs Returned”.

Output
Statement;
table of quantitative information;
Misses in library cache during parse;
Optimizer goal;
Parsing user id;
Explain Plan;

There is also a table at the top of the sheet which displays a list of the highest values for each column in descending order to allow quick identification of the values to be looked at in the filters.

The normal way of working with this will be to open the TKProf file with Excel and then run the macro. However, occasionally a TKProf file will contain embedded TAB characters which will cause the macro to fail, in these cases open the file with Notepad or a similar program ,Cut and Paste the text into a blank Excel Worksheet and then run the Macro.