The Basics of TKPROF

How to enable tracing for tkprof. Generate the trace/tkprof file and examine the contents.

SQL> create table timtest as select * from dba_objects;
Table created.

-- Set up the time statistics and tracing for events.

SQL> alter session set timed_statistics=true;
Session altered.
SQL> alter session set events '10046 trace name context forever, level 12';
Session altered.
-- or --
SQL> exec dbms_monitor.session_trace_enable(binds=>true,waits=>true);
PL/SQL procedure successfully completed.

-- generate some activity

SQL> select count(*) from timtest;
SQL> select * from timtest
where owner = 'SYS'

The trace file is in the udump. Or can befound using the following sql:

SQL> select rtrim(c.value,'/') '/' d.instance_name '_ora_' ltrim(to_char(a.spid)) '.trc' from v$process a, v$session b, v$parameter c, v$instance d
where a.addr = b.paddr
and b.audsid = sys_context( 'userenv', 'sessionid')
and c.name = 'user_dump_dest'
/
RTRIM(C.VALUE,'/')'/'D.INSTANCE_NAME'_ORA_'LTRIM(TO_CHAR(A.SPID))
----------------------------------------------------------------------------
/u01/app/oracle/admin/CXNTEST/udump/CXNTEST1_ora_23581.trc

To make it even easyier to identify the name of the trace file you can issue the
following command to add some text to the name of the file before you turn tracing on.

alter session set tracefile_identifier = "MY_TRACE";

Exit your session to close off the trace file.

Now we can run tkprof from the command line and view the output file

linux> tkprof cxntest1_ora_23581.trc tk.prf sort=prsela,exeela,fchela
linux> more tk.prf

>select * from timtestwhere owner = 'SYS'

call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.00 0.00 0 1 0 0
Execute 1 0.00 0.00 0 0 0 0
Fetch 11639 0.43 0.43 0 12248 0 23275
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 11641 0.44 0.43 0 12249 0 23275

How to read this table:

Parse: This phase is where Oracle finds the query in the shared pool (soft parse) or creates a new plan for the quert (hard parse).

Execute: This Phase is the work done by Oracle on the OPEN and EXECUTE statement of the query. For a select statement, this will be empty in many cases. For an UPDATE/DELETE/INSERT statement, this will be where the work is done.

Fetch: For a SELECT statement, this phase is where most of the work is done and visible. For an UPDATE/DELETE/INSERT statement, it will show no work.

Count: How many times this phase of the query was performed. In a properly written application, all of your SQL will have a parse count of 1 and an execute count of 1 or more. You do not want to parse more than once.

CPU: The amount of CPU time spent on this phase of the statement in thousands of a second.

Elapsed: The amount of wall-clock time spent on this phase. When the elapsed time is greater than the CPU time, that means we spent some time waiting for an event.

Disk: How many physical I/O were performed during this phase of the query. In other words, how many blocks read from disk.

Query: How many logical I/O were performed during this phase of the query. Those blocks that may have been reconstructed from rollback segments, so we would see them as they existed when the query began. Also known as consistent reads (CR). In most cases you will see that the logical I/O out number the physical I/O.

Current: How many logical I/O's were performed to retrieve blocks as they are right now. Known as current reads (CU). We will most frequently see these during modification DML operations. Such as updates and deletes, as opposed to when you query a table and Oracle retrieves the block as of the time the query began.

Rows: The number of rows processed or affected by that phase. During a modification, you will see the Rows value in the Execute phase. During a select query, this value appears in the fetch phase.


Helpful tkprof options:

SYS=NO

Disables the listing of SQL statements issued by the user SYS, or recursive SQL statements. This is helpful when reviewing trace data where we only want to pay attention to the foreground (or user) statements. Note that the overall totals for all recursive statements will be displayed at the end of the tkprof file. 


AGGREGATE=NO


By default tkprof will aggregate or combine sql statement that are the same. If we wish to assess the efficiency of the same sql each time it is run and not in an aggregated format, we can use AGGREGATE=NO.

SORT

Very handy to pin point and order the output file to where the response time is spent. See the oracle docs to see all the options there are to sort. However not sorting the output file (by omitting the SORT option) can be helpful to get a feel of the user or application flow that you are analyzing. 


Below is an example of using tkprof to produce a output file with no recursive statements, and not aggregating statements which are the same. The SORT has been omitted so the statements will appear in order they appear in the trace file.

linux> tkprof tracefile.trc outputfile.prf SYS=NO AGGREGATE=NO

*************************
keywords tkrof trace
*************************