TKPROF is a performance diagnostic tool that can help us monitor
and tune applications running on the Oracle Database Server. The main purpose
of this tool is to formatting the captured trace file to a more readable format
so that a DBA can have an ease look on statistics captured by SQL Trace Facility.
In order to achieve our goal to generate the statistics report of a SQL
statement we will be capturing/tracing the session activity and use the TKPROF
formatting tool.
The SQL Trace facility provides performance information on individual SQL statement. It generates the following statistics for each SQL statements.
- Parse, execute, and fetch counts.
- CPU and elapsed times.
- Physical reads and logical reads
- Number of rows processed
- Misses on the library cache
- Username under which each parse occurred
- Each commit and rollback
We can enable the SQL tracing for a session or at instance level. When
we enable the SQL trace facility then performance statistics for all SQL
statements are generated in a trace file for the session it is enabled for. The
most important thing to note here while enabling the SQL tracing facility is to
make sure you’re not letting it run at instance level in a production box.
Preferably we enable this facility at session level as it will take disk
storage to store the trace file and degrades the database performance.
Note: when we enable the SQL Trace facility for a session then it
creates a single trace file containing statistics for all SQL statements for
that session. When we enable the SQL Trace facility at instance level then
oracle creates a separate trace file for each process.
Pre-requisite:
Before enabling the SQL Tracing make sure you have TIMED_STATISTICS and USER_DUMP_DEST parameters
set appropriately.
Note: if you have not enabled the TIMED_STATISTICS parameter
then SQL Trace facility will not capture the timed statistics such as CPU and
elapsed times.
Enabling the Tracing:
SQL> alter session set sql_trace=true;
Session altered.
After, enabling the SQL tracing run the SQL statements you want to
capture the statistics of and finally disable the SQL tracing.
SQL> alter session set sql_trace=false;
Session altered.
You can see a trace file named ora10db_ora_5512.trc has been generated
in the snapshot depicted below
Note: Setting SQL_TACE to TRUE can have a
severe performance impact on database server so make sure you disable it having
completed with tracing.
Formatting Trae file with TKPROF Utility:
The resulting trace file is stored at USER_DUMP_DEST location
and it can be formatted using TKPROF utility as follow.
$tkprof <trace file location> <output file locaction>
Note: parameters passed in above command
are as follows:
<trace file
location> - specify here complete location of generated trace file including
its file_name.trc
<output file
location> - specify here a location where the formatted TKPROF file would be
placed
For Example:
[oracle@ora10srv bin]$ ./tkprof
/u01/app/oracle/product/10.2.0/db_1/admin/ora10db/udump/ora10db_ora_5512.trc
/u01/app/oracle/product/10.2.0/db_1/admin/ora10db/udump/scott_sess_trace.log
TKPROF: Release 10.2.0.3.0 - Production on Thu Nov 6 13:26:59 2014
Copyright (c) 1982, 2005, Oracle. All rights reserved.
Now you
can see TKPROF has formatted the input trace file into a readable scott_sess_trace.log file
as depicted in the below snapshot.
[oracle@ora10srv udump]$ cat scott_sess_trace.log | more
TKPROF: Release 10.2.0.3.0 - Production on Thu Nov 6 13:26:59 2014
Copyright (c) 1982, 2005, Oracle. All rights reserved.
Trace file:
/u01/app/oracle/product/10.2.0/db_1/admin/ora10db/udump/ora10db_ora_5512.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 /* OPT_DYN_SAMP */ /*+ ALL_ROWS IGNORE_WHERE_CLAUSE
NO_PARALLEL(SAMPLESUB) opt_param('parallel_execution_enabled',
'false')
NO_PARALLEL_INDEX(SAMPLESUB) NO_SQL_TUNE */ NVL(SUM(C1),0),
NVL(SUM(C2),0)
FROM
(SELECT /*+ NO_PARALLEL("EMP") FULL("EMP")
NO_PARALLEL_INDEX("EMP") */ 1 AS
C1, 1 AS C2 FROM "SCOTT"."EMP"
"EMP") SAMPLESUB
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 1
0.00
0.00
0
7 0
1
------- ------ -------- ---------- ---------- ----------
---------- ----------
total
3 0.00
0.00
0 7
0 1
Misses in library cache during parse: 1
Optimizer mode: ALL_ROWS
Parsing user id: SYS (recursive depth: 1)
Rows Row Source Operation
------- ---------------------------------------------------
1 SORT AGGREGATE (cr=7 pr=0 pw=0
time=218 us)
14 TABLE ACCESS FULL EMP (cr=7 pr=0
pw=0 time=225 us)
********************************************************************************
********************************************************************************
OVERALL TOTALS FOR ALL NON-RECURSIVE STATEMENTS
call count
cpu elapsed disk
query
current rows
------- ------ -------- ---------- ---------- ----------
---------- ----------
Parse
7 0.01
0.08
0 8
0 0
Execute 7
0.00
0.07
0 0
0
0
Fetch
6 0.00
0.00
0 24
0 42
------- ------ -------- ---------- ---------- ----------
---------- ----------
total 20
0.02
0.16
0
32 0
42
Misses in library cache during parse: 1
OVERALL TOTALS FOR ALL RECURSIVE STATEMENTS
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
1 0.00
0.00
0
7
0 1
------- ------ -------- ---------- ---------- ----------
---------- ----------
total
3 0.00
0.00
0 7
0 1
Misses in library cache during parse: 1
7 user SQL statements in session.
1 internal SQL statements in session.
8 SQL statements in session.
********************************************************************************
Trace file: /u01/app/oracle/product/10.2.0/db_1/admin/ora10db/udump/ora10db_ora_5512.trc
Trace file compatibility: 10.01.00
Sort options: default
1 session in tracefile.
7 user SQL statements
in trace file.
1 internal SQL statements in
trace file.
8 SQL statements in trace
file.
6 unique SQL statements in
trace file.
125 lines in trace file.
787 elapsed seconds in trace file.
Note : I'll be writing another article with detailed explanation on this along with trcess Utility to format multiple trace files into a single output file................!!
