tkprof
tkprof is one of the most useful utilities available to DBAs for diagnosing performance issues. It essentially formats a trace file into a more readable format for performance analysis. The DBA can then identify and resolve performance issues such as poor SQL, indexing, and wait events.
tkprof has been historically difficult to use for many reasons. First, the entire process of enabling tracing, finding trace files, and executing the utility against them is a burdensome task. Once the DBA finally has the trace file output the typical response is “Now what do I do”? Second, even though tkprof formats the data, it lacks any additional insight needed to remedy the problems revealed. In fact, problems are not even highlighted, thereby putting more work on the DBA to analyze the output, assess the problems, and determine what to do.
Why, When tkprof?
The DBA will use tkprof and session tracing when the database or a particular session is having performance problems. tkprof will generally be used infrequently, when researching a very particular performance issue. A user may complain that the response time for a session is abysmal compared to the prior week. Session tracing and tkprof can be used to see exactly what is happening on the database, enabling the DBA to take corrective action.
The utility can also be used to view SQL that is being executed for an application. In some situations, this will be the only mechanism a DBA will have to view SQL. These situations include the execution of encrypted PL/SQL code on the database or submission of SQL statements from third party applications.
Analyzing tkprof Results
So what should DBAs be looking for? Here’s a small checklist of items to watch for in tkprof formatted files:
- Compare the number of parses to number of executions. A well-tuned system will have one parse per n executions of a statement and will eliminate the re-parsing of the same statement.
- Search for SQL statements that do not use bind variables (:variable). These statements should be modified to use bind variables.
- Identify those statements that perform full table scans, multiple disk reads, and high CPU consumption. These performance benchmarks are defined by the DBA and need to be tailored to each database. What may be considered a high number of disk reads for an OLTP application may not even be minimal for a data warehouse implementation.
The tkprof process will be explained in six easy steps.
Step 1: Check the Environment
Before tracing can be enabled, the environment must first be configured by performing the following steps:
- Enable Timed Statistics – This parameter enables the collection of certain vital statistics such as CPU execution time, wait events, and elapsed times. The resulting trace output is more meaningful with these statistics. The command to enable timed statistics is:
ALTER SYSTEM SET TIMED_STATISTICS = TRUE;
- Check the User Dump Destination Directory – The trace files generated by Oracle can be numerous and large. These files are placed by Oracle in user_dump_dest directory as specified in the init.ora. The user dump destination can also be specified for a single session using the alter session command. Make sure that enough space exists on the device to support the number of trace files that you expect to generate.
SQL> select value
from v$parameter
where name = ‘user_dump_dest’;
VALUE
———————————
C:\oracle9i\admin\ORCL92\udump
Once the directory name is obtained, the corresponding space command (OS dependent) will report the amount of available space. Delete unwanted trace files before starting a new trace to free up the disk space.
Step 2: Turn Tracing On
The next step in the process is to enable tracing. By default, tracing is disabled due to the burden (5-10%) it places on the database. Tracing can be defined at the session level:
ALTER SESSION SET SQL_TRACE = TRUE;
DBMS_SESSION.SET_SQL_TRACE(TRUE);
A DBA may enable tracing for another user’s session by:
DBMS_SYSTEM.SET_SQL_TRACE_IN_SESSION(sid,serial#,true);
where the sid (Session ID) and serial# can be obtained from the v$session view. This package is owned by the SYS user and therefore the executor must be SYS or be granted EXECUTE the privilege by SYS user.
Once tracing is enabled, Oracle generates and stores the statistics in the trace file. The trace file name is version specific. Table 5.1 below contains the version naming conventions for foreground processes.
| Version |
Naming Convention |
Example |
| 7.3.4 |
snnn_pid.trc |
s000_4714.trc |
| 8.0.5 |
ora_pid_trc |
ora_2345.trc |
| 8.1.7 |
ora_pid_instance.trc |
ora_13737_asgard81.trc |
| 9.x |
instance_ora_pid.trc |
asgard91_ora_15313.trc |
Table 5.1 – Oracle Trace File Naming Conventions
Supplied with this information, the DBA can construct a query that will return the trace file for a given session or for all sessions attached to the database. The query below (Users_Trace_Files.sql) will show the trace file name for each process.
< users_trace_files.sql
column username format a10
column trace_file format a70
select b.username, c.value || ‘\’ || lower(d.value) || ‘_ora_’ ||
to_char(a.spid, ‘fm00000’) || ‘.trc’ “TRACE_FILE”
from v$process a, v$session b, v$parameter c, v$parameter d
where a.addr = b.paddr
and c.name = ‘user_dump_dest’
and d.name = ‘db_name’
and b.username is not null;
USERNAME TRACE_FILE
———- ——————————————————–
SYS C:\oracle9i\admin\ORCL92\udump\ORCL92_ora_03164.trc
SCOTT C:\oracle9i\admin\ORCL92\udump\ORCL92_ora_02264.trc
DAVE C:\oracle9i\admin\ORCL92\udump\ORCL92_ora_03578.trc
Notice that the trace files are for each session and not for each named user. Given that the SYS user has two connections to the database, the commands for each session would be in separate trace files.
The query can be modified to return the file name for the currently connected session. The script below will return the file name for the current session.
select c.value || ‘\’ || lower(d.value) || ‘_ora_’ ||
to_char(a.spid, ‘fm00000’) || ‘.trc’ “TRACE FILE”
from v$process a, v$session b, v$parameter c, v$parameter d
where a.addr = b.paddr
and b.audsid = userenv(‘sessionid’)
and c.name = ‘user_dump_dest’
and d.name = ‘db_name’;
TRACE FILE
—————————————————————
C:\oracle9i\admin\ORCL92\udump\ORCL92_ora_03164.trc
Both queries above generate the trace file names (with Oracle9i on Windows XP) that would exist if the session were to be traced. However, there is no indication in any V$ view that a session is currently being traced. The only way to really know if tracing is being performed is to inspect the file names and dates in user_dump_dest directory. For this reason, a DBA should not trace a session indefinitely, as it will continue to consume both performance resources and file system resources. If the user_dump_dest directory fills, the Oracle database will come to a screeching halt.
When the DBA determines that enough data has been gathered, the next step is to disable tracing.
Step 3: Turn Tracing Off
The same options that we use to enable tracing are used to disable it. These include:
ALTER SESSION SET SQL_TRACE = FALSE;
DBMS_SESSION.SET_SQL_TRACE(FALSE);
To disable tracing for another user’s session use:
DBMS_SYSTEM.SET_SQL_TRACE_IN_SESSION(sid,serial#,false);
This process is a perfect candidate for automation. The code below (start_trace.sql) creates a stored procedure that automates all the steps discussed so far. It can also serve as a wrapper for the standard methods of enabling tracing. Start_trace.sql accepts the sid and serial# for the session that needs tracing. It requires that a time interval, in seconds, be set to run the trace so that it doesn’t run perpetually and bog down the session. When the time has elapsed, it will disable tracing for the session and send the relevant trace information: user, time, and trace file name.
< start_trace.sql
create or replace procedure start_trace
(
v_sid in number,
v_serial# in number,
seconds in number)
———————————————
— 2003 – Oracle Utilities
— D. Moore —
— This procedure serves as a wrapper to
— session tracing. It accepts
— a sid and serial#, along with the amount of
— time in seconds that the trace should last.
— The trace will be stopped when that time
— period expires. After tracing is turned
— off, the name of the trace file will be
— displayed.
———————————————
IS
v_user varchar2 (32);
stop_trace_cmd varchar2 (200);
duration number;
v_spid number;
dump_dest varchar2 (200);
db_name varchar2 (32);
v_version varchar2 (32);
v_compatible varchar2 (32);
file_name varchar2 (32);
no_session_found exception;
BEGIN
begin
select a.username, b.spid into v_user,v_spid
from v$session a, v$process b
where a.sid = v_sid and
a.serial# = v_serial# and
a.paddr = b.addr;
exception
when NO_DATA_FOUND then
raise no_session_found;
end;
dbms_system.set_sql_trace_in_session(v_sid,v_serial#,true);
dbms_output.put_line(‘Tracing Started for User: ‘
|| v_user);
dbms_output.put_line(‘Tracing Start Time: ‘
|| TO_CHAR(SYSDATE, ‘MM-DD-YYYY HH24:MI:SS’));
—————————————————
— Sleep for the amount of seconds specified as
— seconds input parameter. When complete, stop
— the tracing and display the resulting trace file
— name
—————————————————
if seconds is null then
duration := 60;
else
duration := seconds;
end if;
dbms_lock.sleep(duration);
— the time alotted has now expired. Disable
— tracing and output the trace file information
dbms_system.set_sql_trace_in_session(v_sid,v_serial#,false);
dbms_output.put_line (‘Tracing Stop Time: ‘
|| TO_CHAR(SYSDATE, ‘MM-DD-YYYY HH24:MI:SS’));
— get all of the data needed to format the trace file name
select value into dump_dest
from v$parameter
where name = ‘user_dump_dest’;
select value into db_name
from v$parameter
where name = ‘db_name’;
— we need the version of the database in order to determine
— the naming scheme for the trace file
dbms_utility.db_version(v_version, v_compatible);
if substr(v_version,1,1) = ‘9’ then
file_name := db_name || ‘_ora_’ || v_spid || ‘.trc’;
elsif substr(v_version,1,3) = ‘8.1’ then
file_name := ‘ora_’ || v_spid || ‘_’ || db_name || ‘.trc’;
elsif substr(v_version,1,3) = ‘8.0’ then
file_name := ‘ora_’ || v_spid || ‘.trc’;
end if;
dbms_output.put_line(‘Trace Directory: ‘ || dump_dest);
dbms_output.put_line(‘Trace Filename: ‘ || file_name);
exception
when no_session_found then
dbms_output.put_line(‘No session found for sid and serial# specified’);
END start_trace;
The output from start_trace.sql is displayed below. The time interval specified was 30 and we can see the elapsed time of the trace in the timestamps below.
SQL> exec start_trace(17, 6157, 30);
Tracing Started for User: SCOTT
Tracing Start Time: 12-26-2002 14:55:12
Tracing Stop Time: 12-26-2002 14:55:42
Trace Directory: C:\oracle9i\admin\ORCL92\udump
Trace Filename: ORCL92_ora_5472.trc
The next step is to run tkprof against the trace file.
Step 4: Locate Trace File and Execute tkprof
Locating the file is easy because the script above gives us the file name. tkprof will format the raw trace file, although the file is somewhat readable without tkprof.
Raw Trace File
PARSING IN CURSOR #1 len=44 dep=0 uid=59 oct=3 lid=59 tim=535446373886 hv=159129
656 ad=’12cbbe70′
select * from employee where emp_id = 87933
END OF STMT
PARSE #1:c=0,e=37469,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=4,tim=535446373874
EXEC #1:c=0,e=71,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=4,tim=535446375834
FETCH #1:c=31250,e=42564,p=10,cr=416,cu=0,mis=0,r=1,dep=0,og=4,tim=535446418910
FETCH #1:c=0,e=3852,p=0,cr=57,cu=0,mis=0,r=0,dep=0,og=4,tim=535446424026
STAT #1 cnt=1 pid=0 pos=1 obj=30497 op=’TABLE ACCESS FULL EMPLOYEE ‘
=====================
PARSING IN CURSOR #1 len=44 dep=0 uid=59 oct=3 lid=59 tim=535448474894 hv=159129
656 ad=’12cbbe70’
select * from employee where emp_id = 87933
END OF STMT
PARSE #1:c=0,e=146,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=4,tim=535448474882
EXEC #1:c=0,e=76,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=4,tim=535448476767
FETCH #1:c=31250,e=30553,p=12,cr=416,cu=0,mis=0,r=1,dep=0,og=4,tim=535448507870
FETCH #1:c=15625,e=3832,p=0,cr=57,cu=0,mis=0,r=0,dep=0,og=4,tim=535448512927
STAT #1 cnt=1 pid=0 pos=1 obj=30497 op=’TABLE ACCESS FULL EMPLOYEE ‘=====================
PARSING IN CURSOR #1 len=44 dep=0 uid=59 oct=3 lid=59 tim=535449209407 hv=159129
656 ad=’12cbbe70’
select * from employee where emp_id = 87933
END OF STMT
PARSE #1:c=0,e=111,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=4,tim=535449209395
EXEC #1:c=0,e=74,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=4,tim=535449211302
FETCH #1:c=31250,e=32623,p=8,cr=416,cu=0,mis=0,r=1,dep=0,og=4,tim=535449244513
FETCH #1:c=15625,e=3918,p=0,cr=57,cu=0,mis=0,r=0,dep=0,og=4,tim=535449249648
STAT #1 cnt=1 pid=0 pos=1 obj=30497 op=’TABLE ACCESS FULL EMPLOYEE ‘=====================
PARSING IN CURSOR #1 len=44 dep=0 uid=59 oct=3 lid=59 tim=535449801444 hv=159129
656 ad=’12cbbe70’
select * from employee where emp_id = 87933
END OF STMT
PARSE #1:c=0,e=102,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=4,tim=535449801433
EXEC #1:c=0,e=74,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=4,tim=535449803310
FETCH #1:c=31250,e=31503,p=7,cr=416,cu=0,mis=0,r=1,dep=0,og=4,tim=535449835358
FETCH #1:c=15625,e=4039,p=0,cr=57,cu=0,mis=0,r=0,dep=0,og=4,tim=535449840721
STAT #1 cnt=1 pid=0 pos=1 obj=30497 op=’TABLE ACCESS FULL EMPLOYEE ‘=====================
PARSING IN CURSOR #1 len=44 dep=0 uid=59 oct=3 lid=59 tim=535450369301 hv=159129
656 ad=’12cbbe70’
select * from employee where emp_id = 87933
END OF STMT
PARSE #1:c=0,e=101,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=4,tim=535450369290
EXEC #1:c=0,e=76,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=4,tim=535450371203
FETCH #1:c=15625,e=28362,p=5,cr=416,cu=0,mis=0,r=1,dep=0,og=4,tim=535450400245
FETCH #1:c=15625,e=4333,p=0,cr=57,cu=0,mis=0,r=0,dep=0,og=4,tim=535450405578
STAT #1 cnt=1 pid=0 pos=1 obj=30497 op=’TABLE ACCESS FULL EMPLOYEE ‘=====================
With minimal effort, a programmer could create a trace file parser and formatter similar to tkprof that provides the trace data in a format even more suitable for analysis.
The tkprof command can now be executed from the operating system prompt.
C:\oracle9i\admin\ORCL92\udump>tkprof ORCL92_ora_3064.trc output.txt insert=tkprof.sql record=Allsql.sql
tkprof: Release 9.2.0.1.0 – Production on Thu Dec 26 13:22:29 2002
Copyright (c) 1982, 2002, Oracle Corporation. All rights reserved.
Based on the command above, tkprof will process the file ORCL92_ora_3064.trc and format the results in the file output.txt. Two other files were also created (tkprof.sql, allsql.sql) that will be discussed later.
Step 5: Analyze tkprof Output
This is the most difficult step in the process. Each tkprof output file contains a header, body, and summary section. The header simply displays the trace file name, definitions, and sort options selected. The body contains the performance metrics for SQL statements. The summary section contains an aggregate of performance statistics for all SQL statements in the file.
tkprof Output
tkprof: Release 9.2.0.1.0 – Production on Tue Dec 24 15:32:43 2002
Copyright (c) 1982, 2002, Oracle Corporation. All rights reserved.
Trace file: ORCL92_ora_3064.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
employee where emp_id = 87933
call count cpu elapsed disk query current rows
——- —— ——– ———- ———- ———- ———- ———-
Parse 10 0.00 0.03 0 0 0 0
Execute 10 0.00 0.00 0 0 0 0
Fetch 20 0.34 0.35 72 4730 0 10
——- —— ——– ———- ———- ———- ———- ———-
total 40 0.34 0.39 72 4730 0 10
Misses in library cache during parse: 1
Optimizer goal: CHOOSE
Parsing user id: 59
Rows Row Source Operation
——- —————————————————
1 TABLE ACCESS FULL EMPLOYEE
********************************************************************************
The output displays a table of performance metrics after each unique SQL statement. Each row in the table corresponds to each of the three steps required in SQL processing.
1. Parse – The translation of the SQL into an execution plan. This step includes syntax checks, permissions, and all object dependencies.
2. Execute – The actual execution of the statement.
3. Fetch – The number of rows returned for a SELECT statement.
The table columns include the following:
- Count – The number of times a statement was parsed, executed, or fetched.
- CPU – The total CPU time in seconds for all parse, execute, or fetch calls.
- Elapsed – Total elapsed time in seconds for all parse, execute, or fetch calls.
- Disk – The number of physical disk reads from the datafiles for all parse, execute, or fetch calls.
- Query – The number of buffers retrieved for all parse, execute, or fetch calls.
- Current – The number of buffers retrieved in current mode (INSERT, UPDATE, or DELETE statements).
Observe from the tkprof output above that the SQL statement performed a TABLE ACCESS FULL, meaning a full-table scan. Full-table scans can degrade performance, especially when accessing a small subset of the data in a table. In this case, the query is selecting one row, yet all 100,000 rows in the table are scanned. This is a perfect situation to add an index on the EMP_ID column of the EMPLOYEE table:
SQL> CREATE INDEX emp_idx1 ON employee (emp_id);
Index created.
Let’s examine the performance of this query again, this time with the index enabled.
select *
from
employee where emp_id = 87933
call count cpu elapsed disk query current rows
——- —— ——– ———- ———- ———- ———- ———-
Parse 1 0.03 0.05 1 1 0 0
Execute 1 0.00 0.00 0 0 0 0
Fetch 2 0.00 0.03 3 4 0 1
——- —— ——– ———- ———- ———- ———- ———-
total 4 0.03 0.09 4 5 0 1
Misses in library cache during parse: 1
Optimizer goal: CHOOSE
Parsing user id: 59
Rows Row Source Operation
——- —————————————————
1 TABLE ACCESS BY INDEX ROWID EMPLOYEE
1 INDEX RANGE SCAN EMP_IDX1 (object id 30498)
********************************************************************************
The CPU speed improved by a multiple of 11 (.03 vs. .34) compared to the benchmark before the index was added.
Step 6: Load tkprof Results into Tables
Loading tkprof data into the database is optional, but it can be worthwhile for those DBAs that want historical data or the ability to access data via SQL queries to generate reports. The command used earlier specified insert=tkprof.sql which generated the following SQL in tkprof.sql:
CREATE TABLE tkprof_table
(
date_of_insert DATE
,cursor_num NUMBER
,depth NUMBER
,user_id NUMBER
,parse_cnt NUMBER
,parse_cpu NUMBER
,parse_elap NUMBER
,parse_disk NUMBER
,parse_query NUMBER
,parse_current NUMBER
,parse_miss NUMBER
,exe_count NUMBER
,exe_cpu NUMBER
,exe_elap NUMBER
,exe_disk NUMBER
,exe_query NUMBER
,exe_current NUMBER
,exe_miss NUMBER
,exe_rows NUMBER
,fetch_count NUMBER
,fetch_cpu NUMBER
,fetch_elap NUMBER
,fetch_disk NUMBER
,fetch_query NUMBER
,fetch_current NUMBER
,fetch_rows NUMBER
,ticks NUMBER
,sql_statement LONG
);
INSERT INTO tkprof_table values
(
SYSDATE, 1, 0, 59, 0, 0, 0, 0, 0, 0, 0
, 1, 0, 192, 0, 0, 0, 1, 0
, 0, 0, 0, 0, 0, 0, 0, 4294966155
, ‘alter session set sql_trace=true
‘);
INSERT INTO tkprof_table VALUES
(
SYSDATE, 2, 1, 0, 1, 0, 1232, 0, 0, 0, 1
, 1, 0, 745, 0, 0, 0, 0, 0
, 1, 0, 115, 0, 3, 0, 1, 17866289
, ‘select obj#,type#,ctime,mtime,stime,status,dataobj#,flags,oid$, spare1, spare
2 from obj$ where owner#=:1 and name=:2 and namespace=:3 and(remoteowner=:4 or r
emoteowner is null and :4 is null)and(linkname=:5 or linkname is null and :5 is
null)and(subname=:6 or subname is null and :6 is null)
‘);
INSERT INTO tkprof_table VALUES
(
SYSDATE, 3, 1, 0, 1, 0, 1400, 0, 0, 0, 1
, 1, 0, 658, 0, 0, 0, 0, 0
, 1, 0, 131, 0, 3, 0, 1, 5463
, ‘select ts#,file#,block#,nvl(bobj#,0),nvl(tab#,0),intcols,nvl(clucols,0),audit
$,flags,pctfree$,pctused$,initrans,maxtrans,rowcnt,blkcnt,empcnt,avgspc,chncnt,a
vgrln,analyzetime, samplesize,cols,property,nvl(degree,1),nvl(instances,1),avgsp
c_flb,flbcnt,kernelcols,nvl(trigflag, 0),nvl(spare1,0),nvl(spare2,0),spare4,spar
e6 from tab$ where obj#=:1
‘);
INSERT INTO tkprof_table VALUES
(
SYSDATE, 4, 1, 0, 2, 0, 1110, 0, 0, 0, 1
, 2, 15625, 757, 0, 0, 0, 0, 0
, 2, 0, 221, 0, 6, 0, 2, 8966
, ‘select type#,blocks,extents,minexts,maxexts,extsize,extpct,user#,iniexts,NVL(
lists,65535),NVL(groups,65535),cachehint,hwmincr, NVL(spare1,0) from seg$ where
ts#=:1 and file#=:2 and block#=:3
‘);
INSERT INTO tkprof _table VALUES
(
SYSDATE, 4, 1, 0, 1, 0, 1802, 0, 0, 0, 1
, 1, 0, 1089, 0, 0, 0, 0, 0
, 2, 0, 489, 0, 5, 0, 1, 23441
, ‘select i.obj#,i.ts#,i.file#,i.block#,i.intcols,i.type#,i.flags, i.property,i.
pctfree$,i.initrans,i.maxtrans,i.blevel,i.leafcnt,i.distkey, i.lblkkey,i.dblkkey
,i.clufac,i.cols,i.analyzetime,i.samplesize,i.dataobj#, nvl(i.degree,1),nvl(i.in
stances,1),i.rowcnt,mod(i.pctthres$,256),i.indmethod#,i.trunccnt,nvl(c.unicols,0
),nvl(c.deferrable#+c.valid#,0), nvl(i.spare1,i.intcols),i.spare4,spare2,spare6,
decode(i.pctthres$,null,null, mod(trunc(i.pctthres$/256),256)) from ind$ i, (se
lect enabled, min(cols) unicols, min(to_number(bitand(defer,1))) deferrable#, mi
n(to_number(bitand(defer,4))) valid# from cdef$ where obj#=:1 and enabled > 1 gr
oup by enabled) c where i.obj#=c.enabled(+) and i.bo#=:1
‘);
INSERT INTO tkprof _table VALUES
(
SYSDATE, 5, 1, 0, 1, 0, 910, 0, 0, 0, 1
, 1, 0, 573, 0, 0, 0, 0, 0
, 2, 0, 147, 0, 3, 0, 1, 5409
, ‘select pos#,intcol#,col#,spare1,bo#,spare2 from icol$ where obj#=:1
‘);
INSERT INTO tkprof _table VALUES
(
SYSDATE, 6, 1, 0, 1, 15625, 1426, 0, 0, 0, 1
, 1, 0, 775, 0, 0, 0, 0, 0
, 6, 0, 1744, 0, 3, 0, 5, 10773
, ‘select name,intcol#,segcol#,type#,length,nvl(precision#,0),decode(type#,2,nvl
(scale,-127/*MAXSB1MINAL*/),178,scale,179,scale,180,scale,181,scale,182,scale,18
3,scale,231,scale,0),null$,fixedstorage,nvl(deflength,0),default$,rowid,col#,pro
perty, nvl(charsetid,0),nvl(charsetform,0),spare1,spare2,nvl(spare3,0) from col$
where obj#=:1 order by intcol#
‘);
INSERT INTO tkprof _table VALUES
( SYSDATE, 8, 1, 0, 1, 0, 831, 0, 0, 0, 1
, 1, 0, 597, 0, 0, 0, 0, 0, 1, 0, 59, 0, 1, 0, 0, 5736
, ‘select con#,obj#,rcon#,enabled,nvl(defer,0) from cdef$ where robj#=:1’);
INSERT INTO tkprof _table VALUES
( SYSDATE, 9, 1, 0, 1, 0, 973, 0, 0, 0, 1
, 1, 0, 650, 0, 0, 0, 0, 0, 1, 0, 43, 0, 2, 0, 0, 5050
, ‘select con#,type#,condlength,intcols,robj#,rcon#,match#,refact,nvl(enabled,0)
,rowid,cols,nvl(defer,0),mtime,nvl(spare1,0) from cdef$ where obj#=:1’);
INSERT INTO tkprof _table VALUES
( SYSDATE, 1, 0, 59, 1, 31250, 58068, 1, 1, 0, 1
, 1, 0, 85, 0, 0, 0, 0, 0, 2, 0, 37301, 3, 4, 0, 1, 39511
, ‘ select * from employee where emp_id = 87933);
INSERT INTO tkprof _table VALUES
( SYSDATE, 2, 1, 0, 2, 0, 1122, 0, 0, 0, 1, 2, 0, 672, 0, 0, 0, 0, 0
, 2, 0, 178, 0, 6, 0, 2, 12416444
, ‘select o.owner#,o.name,o.namespace,o.remoteowner,o.linkname,o.subname,o.datao
bj#,o.flags from obj$ o where o.obj#=:1’);
INSERT INTO tkprof _table VALUES( SYSDATE, 1, 0, 59, 1, 0, 353, 0, 0, 0, 1
, 1, 0, 148, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 1160, ‘alter session set sql_trace=false
‘);
This file contains the DDL to create the table as well as the data to load. If the table already exists, the error will be ignored when it tries to create the table again.
tkprof Command Line Options
tkprof provides many useful command line options that provide additional functionality for the DBA.
- print – Lists only the first n SQL statements in the output file. If nothing is specified, all statements will be listed. Use this option when the list needs to be limited to the “Top n” statements. This is useful when combined with a sorting option to enable the top n statements by CPU, or disk reads, or parses, etc.
- aggregate – When “Yes”, tkprof will combine the statistics from multiple user executions of the same SQL statement. When “No”, the statistics will be listed each time the statement is executed.
- insert – Creates a file that will load the statistics into a table in the database for further processing. Choose this option if you want to perform any advanced analysis of the tkprof output.
- sys – Enables or disables the inclusion of SQL statements executed by the SYS user, including recursive SQL statements. The default is to enable.
- table – Used in the Explain Plan command (if specified) for Oracle to load data temporarily into an Oracle table. The user must specify the schema and table name for the plan table. If the table exists all rows will be deleted otherwise tkprof will create the table and use it.
- record – creates a SQL script with the specified filename that contains all non-recursive SQL statements from the trace file. For DBAs wanting to log the SQL statements in a separate file, this is the option to use. In the example earlier, the contents of the Allsql.sql file include:
alter session set sql_trace=true ;
select * from employee where emp_id = 87933 ;
alter session set sql_trace=false ;
- explain – Executes an Explain Plan for each statement in the trace file and displays the output. Explain Plan is less useful when used in conjunction with tkprof than it is when used alone. Explain Plan provides the predicted optimizer execution path without actually executing the statement. tkprof shows you the actual execution path and statistics after the statement is executed. In addition, running Explain Plan against SQL statements that were captured and saved is always problematic given dependencies and changes in the database environment.
- sort – Sorts the SQL statements in the trace file by the criteria deemed most important by the DBA. This option allows the DBA to view the SQL statements that consume the most resources at the top of the file, rather than searching the entire file contents for the poor performers. The following are the data elements available for sorting:
- prscnt – The number of times the SQL was parsed.
- prscpu – The CPU time spent parsing.
- prsela – The elapsed time spent parsing the SQL.
- prsdsk – The number of physical reads required for the parse.
- prsmis – The number of consistent block reads required for the parse.
- prscu – The number of current block reads required for the parse.
- execnt – The number of times the SQL statement was executed.
- execpu – The CPU time spent executing the SQL.
- exeela – The elapsed time spent executing the SQL.
- exedsk – The number of physical reads during execution.
- exeqry – The number of consistent block reads during execution.
- execu – The number of current block reads during execution.
- exerow – The number of rows processed during execution.
- exemis – The number of library cache misses during execution.
- fchcnt – The number of fetches performed.
- fchcpu – The CPU time spent fetching rows.
- fchela – The elapsed time spent fetching rows.
- fchdsk – The number of physical disk reads during the fetch.
- fchqry – The number of consistent block reads during the fetch.
- fchcu – The number of current block reads during the fetch.
- fchrow – The number of rows fetched for the query.
Many sort options exist, however some are more useful than others. Execnt, execpu, exedsk and prscnt are the most useful sort parameters when formatting trace output with tkprof, because they are more indicative of most SQL performance issues. The execution counts are most indicative of performance issues and therefore should bubble to the top. In particular, this is true of the SQL statement that used the most CPU – execpu. The prscnt parameter is important because it shows the SQL statements that are parsed most, usually a result of not using bind variables.
SQL Execution Statistics in 9i
The SQL tuning process prior to 9.2 involved executing SQL commands, then OS commands, and then SQL commands again. This is a very time-consuming and burdensome process. In 9.2, Oracle decided to retain the SQL metrics for each statement in the SGA (library cache) while the statement remains cached. The DBA could then diagnose SQL issues at a SQL prompt and leave tkprof alone. This is a vast improvement over prior versions.
Oracle9.2 contains the following views that enable the DBA to identify SQL issues directly from a SQL prompt. These views should be used to periodically check SQL statistics and full-table scans, alerting the DBA to problem areas requiring corrective action.
- v$sql_plan – This view shows the same information as shown by Explain Plan except it is the actual execution plan and not the predicted one – just like tkprof and even better than Explain Plan.
- v$sql_plan_statistics – This view contains the execution statistics for each operation (step) in the v$sql_plan. Queries should access this view and look for poor SQL operations including TABLE ACCESS FULL – full-table scans.
- v$sql_plan_statistics_all – This view combines data from v$sql_plan, v$sql_plan_statistics and v$sql_workarea.
Both v$sql_plan_statistics and v$sql_plan_statistics_all are not populated by default. The option statistics_level=all must be set.
Best Practices for Using tkprof
Enable tracing only on those sessions that are having problems. Be selective to minimize the performance burden on the sessions and to retain more free space in the user dump destination directory.
Rename trace files after tracing is disabled. The new file name should be something more meaningful that will be recognizable at a later date. The name employee_index.trc is much more meaningful than ORCL92_ora_3172.trc.
Delete trace files that are no longer needed to reduce clutter and free disk space.
Explain Plan is not as useful when used in conjunction with tkprof since the trace file contains the actual execution path of the SQL statement. Use Explain Plan when anticipated execution statistics are desired without actually executing the statement.
When tracing a session, remember that nothing in v$session indicates that a session is being traced. Therefore, trace with caution and remember to disable tracing after an adequate amount of trace data has been generated.
tkprof does not control the contents of a trace file, it simply formats them. Oracle provides multiple ways to actually generate the trace file. tkprof is valuable for detailed trace file analysis. For those DBAs that pefer a simpler tracing mechanism with instant feedback, the autotrace utility should be used.
To take tkprof to the next level, consider using Trace Analyzer.
Oracle DBA's Blog 