Use EXPLAIN PLAN and TKPROF To Tune Your Applications

tkprof

[explain=] [sys=n] \
[insert=] [record=] [sort=]

If you invoke TKPROF with no arguments at all, you will get a help screen listing all of the options. This is especially helpful because TKPROF offers many sort capabilities, but you select the desired sort by specifying a cryptic keyword. The help screen identifies all of the sort keywords.

In its simplest form, you run TKPROF specifying the name of a SQL trace file and an output filename. TKPROF will read the trace file and generate a report file with the output filename you specified. TKPROF will not connect to the database, and the report will not include execution plans for the SQL statements. SQL statements that were executed by the SYS user recursively (to dynamically allocate an extent in a dictionary-managed tablespace, for example) will be included in the report, and the statements will appear in the report approximately in the order in which they were executed in the database session that was traced.

If you include the explain keyword, TKPROF will connect to the database and execute an EXPLAIN PLAN statement for each SQL statement found in the trace file. The execution plan results will be included in the report file. As we will see later, TKPROF merges valuable information from the trace file into the execution plan display, making this just about the most valuable way to display an execution plan. Note that the username you specify when running TKPROF should be the same as the username connected in the database session that was traced. You do not need to have a plan table in order to use the explain keyword—TKPROF will create and drop its own plan table if needed.

If you specify sys=n, TKPROF will exclude from the report SQL statements initiated by Oracle as the SYS user. This will make your report look tidier because it will only contain statements actually issued by your application. The theory is that Oracle internal SQL has already been fully optimized by the kernel developers at Oracle Corporation, so you should not have to deal with it. However, using sys=n will exclude potentially valuable information from the TKPROF report. Suppose the SGA is not properly sized on the instance and Oracle is spending a lot of time resolving dictionary cache misses. This would manifest itself in lots of time spent on recursive SQL statements initiated by the SYS user. Using sys=n would exclude this information from the report.

SQL*Plus: Release 10.2.0.4.0 - Production on Mon Sep 27 14:33:22 2010

Copyright (c) 1982, 2007, Oracle. All Rights Reserved.


Connected to:
Oracle Database 10g Enterprise Edition Release 10.2.0.4.0 - Production
With the Partitioning, OLAP, Data Mining and Real Application Testing options

SQL> archive log list
Database log mode Archive Mode
Automatic archival Enabled
Archive destination /arch
Oldest online log sequence 160
Next log sequence to archive 162
Current log sequence 162
SQL> conn scott/tiger
Connected.
SQL> select * from tab;

TNAME TABTYPE CLUSTERID
------------------------------ ------- ----------
DEPT TABLE
EMP TABLE
BONUS TABLE
SALGRADE TABLE
IREPS_REVOKED_CERTS_MASTER TABLE

SQL> ALTER SESSION /* Module glpost.c */ SET sql_trace = TRUE;

Session altered.

SQL> select * from DEPT;

DEPTNO DNAME LOC
---------- -------------- -------------
10 ACCOUNTING NEW YORK
20 RESEARCH DALLAS
30 SALES CHICAGO
40 OPERATIONS BOSTON

SQL> exit
Disconnected from Oracle Database 10g Enterprise Edition Release 10.2.0.4.0 - Production
With the Partitioning, OLAP, Data Mining and Real Application Testing options
[oracle@crisreplication ~]$ cd /u01/app/oracle/
admin/ oradata/ oraInventory_24nov09.tar.gz product/
flash_recovery_area/ oraInventory/ oraInventory.tar.gz utlfile/
[oracle@crisreplication ~]$ cd /u01/app/oracle/admin/trialrep/udump/
[oracle@crisreplication udump]$ ls -ltr
[oracle@crisreplication udump]$ tkprof trialrep_ora_15837.trc trialrep_ora_15837.html

TKPROF: Release 10.2.0.4.0 - Production on Mon Sep 27 14:35:23 2010

Copyright (c) 1982, 2007, Oracle. All rights reserved.


[oracle@crisreplication udump]$ tkprof trialrep_ora_15837.trc trialrep_ora_15837.html explain=scott/tiger sys=n

TKPROF: Release 10.2.0.4.0 - Production on Mon Sep 27 14:35:47 2010

Copyright (c) 1982, 2007, Oracle. All rights reserved.


[oracle@crisreplication udump]$


TKPROF: Release 10.2.0.4.0 - Production on Mon Sep 27 14:35:47 2010

Copyright (c) 1982, 2007, Oracle. All rights reserved.

Trace file: trialrep_ora_15837.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 *
from
DEPT


call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.01 0.06 0 0 0 0
Execute 1 0.00 0.00 0 0 0 0
Fetch 2 0.00 0.06 6 8 0 4
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 4 0.01 0.13 6 8 0 4

Misses in library cache during parse: 1
Optimizer mode: ALL_ROWS
Parsing user id: 57 (SCOTT)

Rows Row Source Operation
------- ---------------------------------------------------
4 TABLE ACCESS FULL DEPT (cr=8 pr=6 pw=0 time=67168 us)


Rows Execution Plan
------- ---------------------------------------------------
0 SELECT STATEMENT MODE: ALL_ROWS
4 TABLE ACCESS MODE: ANALYZED (FULL) OF 'DEPT' (TABLE)




********************************************************************************

OVERALL TOTALS FOR ALL NON-RECURSIVE STATEMENTS

call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.01 0.06 0 0 0 0
Execute 1 0.00 0.00 0 0 0 0
Fetch 2 0.00 0.06 6 8 0 4
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 4 0.01 0.13 6 8 0 4

Misses in library cache during parse: 1


OVERALL TOTALS FOR ALL RECURSIVE STATEMENTS

call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 15 0.01 0.13 0 0 0 0
Execute 69 0.06 0.14 0 0 0 0
Fetch 80 0.01 0.06 0 216 0 471
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 164 0.09 0.34 0 216 0 471

Misses in library cache during parse: 14
Misses in library cache during execute: 14

1 user SQL statements in session.
69 internal SQL statements in session.
70 SQL statements in session.
1 statement EXPLAINed in this session.
********************************************************************************
Trace file: trialrep_ora_15837.trc
Trace file compatibility: 10.01.00
Sort options: default

1 session in tracefile.
1 user SQL statements in trace file.
69 internal SQL statements in trace file.
70 SQL statements in trace file.
15 unique SQL statements in trace file.
1 SQL statements EXPLAINed using schema:
SCOTT.prof$plan_table
Default table was used.
Table was created.
Table was dropped.
648 lines in trace file.
0 elapsed seconds in trace file.