Oracle TKProf Usage

The TKProf facility accepts as input a SQL trace file and produces a formatted output file.

TKPROF filename_source filename_output EXPLAIN=[username/password] SYS=[YES/No] TABLE=[tablename] 
filename_source: The trace file that needs to be formatted.
filename_output: The output file where the formatted file will be written.
EXPLAIN: This option causes TKProf to generate an execution plan for each SQL statement in the trace file as though it was been parsed at the time the TKProf is being run. TKProf connects as the user [username] and uses the EXPLAIN PLAN command to generate an execution plan for each traced SQL statement. These explain plans are written to the output file. Note that in later releases, the raw trace file automatically records the explain plan that was used at execution time and TKProf will automatically output this plan. If the EXPLAIN option is selected then two explain plans appear in the TKProf output. The first explain plan is the plan that was used at execution time. The second plan is the plan that was generated dynamically at the time the TKProf runs. If session settings etc have changed between the execution time and when the trace file is TKProffed then the first and second plans may differ.
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 its rows then uses it for the EXPLAIN PLAN command and then deletes its rows. If this table does not exist, TKProf creates, uses, then drops it. This parameter is ignored if the EXPLAIN parameter isn't used.
SYS: Enables and disables the listing of SQL statements issued by the user SYS (recursive SQL statements) into the output file. The default value is YES.

We create a SQL Trace by using following command:-

#Enable tracing.
alter session set tracefile_identifier='10046';
alter session set timed_statistics = true;
alter session set statistics_level=all;
alter session set max_dump_file_size = unlimited;
alter session set events '10046 trace name context forever,level 12';


select * from all_objects;

#Disable tracing
alter session set events '10046 trace name context off';

Since we are tracing current session the tracefile can be identified by following query:-

select tracefile from v$process join v$session on (addr=paddr)
where sys_context('userenv','sessionid') = audsid

This tracefile contains lot of data but doesn’t appear to be quite eye friendly. Once tracefile is identified use following tkprof command to get a tkprof formatted output.

tkprof ORCL11_ora_12383_10046.trc tkprof.out explain=admin/admin table=sys.plan_table

This would generate a tkprof formatted file tkprof.out, something like:

TKPROF: Release - Development on Thu Dec 27 05:39:56 2018
Copyright (c) 1982, 2017, Oracle and/or its affiliates. All rights reserved.
Trace file: tracefile_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

SQL ID: 4m94ckmu16f9k Plan Hash: 3910148636
select count(*)
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 0 0 1
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 4 0.00 0.00 0 0 0 1
Misses in library cache during parse: 1
Optimizer mode: ALL_ROWS
Parsing user id: SYS
Number of plan statistics captured: 1
Rows (1st) Rows (avg) Rows (max) Row Source Operation
---------- ---------- ---------- ---------------------------------------------------
1 1 1 SORT AGGREGATE (cr=0 pr=0 pw=0 time=21 us starts=1)
1 1 1 FAST DUAL (cr=0 pr=0 pw=0 time=1 us starts=1 cost=2 size=0 card=1)
Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total Waited
---------------------------------------- Waited ---------- ------------
Disk file operations I/O 1 0.00 0.00
SQLNet message to client 2 0.00 0.00 SQLNet message from client 2 10.63 10.63

In the next post we would see how to interpret the output of a tkprof formatted tracefile.

One thought on “Oracle TKProf Usage

  1. Pingback: Understanding TKProf output | Oracle Database Internal Mechanism

Leave a Reply

Fill in your details below or click an icon to log in: Logo

You are commenting using your account. Log Out /  Change )

Twitter picture

You are commenting using your Twitter account. Log Out /  Change )

Facebook photo

You are commenting using your Facebook account. Log Out /  Change )

Connecting to %s

This site uses Akismet to reduce spam. Learn how your comment data is processed.