SQL Trace Facility & TKPROF - Part - I

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................!!