Oracle Performance Analysis Tool – SQL_Trace and TKPROF

As a DBA/Developer we often hear users complaining that certain part of the web or desktop applications run too slow, it would be very helpful if we are able to trace an Oracle session to pinpoint the root cause. Here is when SQL_Trace and TKPROF utility come to play. Unlike switching on AUTOTRACE in sql plus to test a single query in isolation, TKPROF shows you a different set of data for all sql statments executed by your application as it runs.

What is SQL_Tace and TKPROF? In short SQL_TRACE is the used to write performance information on individual SQL statement down to trace files in the file system of the database server. These trace files are not in a proper readable format, for that reason we need TKPROF utility to transform the trace file into a text-based report for performance analysis.

To be able to run the following simulation test, we need to create a user and grant alter session directly to that user.

drop user demo cascade;
create user demo identified by demo;
grant connect, resource to demo;
grant alter session to demo;
grant all on plan_table to demo;
grant select on v_$session to demo;
grant select on v_$process to demo;
grant select on v_$parameter to demo;

Create a test table and a package to simulate a typical work load.

create table test
(
  col1 varchar2(30)
);
/
CREATE OR REPLACE procedure simulate_workload_with_binds as
  var1 varchar2(30);
begin  
  -- This parameter enables the collection of certain vital statistics 
  -- such as CPU execution time, wait events, and elapsed times. 
  execute immediate 'alter session set timed_statistics = true';
  -- Set the maximum size of trace file as unlimited
  execute immediate 'alter session set max_dump_file_size = unlimited';
  -- Set a suffix of the trace file
  execute immediate 'alter session set tracefile_identifier = ''test1_binds_single_process''';
  -- turn on extended SQL tracing
  execute immediate 'alter session set events ''10046 trace name context forever, level 8''';
  
  -- main body of code  
  for c in 1 .. 500 loop
    insert into test (col1) values (c);
    commit;
  end loop;
  commit;

  for c in 1 .. 50 loop
    update test set col1 = col1;
    commit;
  end loop;

  for c in 1 .. 500 loop
    begin
      select col1 into var1 from test where col1 = c;
    exception
      when others then
        null;
    end;
  end loop;
  
  for c in 1 .. 500 loop
    insert into test (col1) values (c);
    commit;
  end loop;
  commit;
  
  for c in 1 .. 500 loop
    delete from test where col1 = c;
    commit;
  end loop;
  commit;  
  -- turn off extended SQL tracing 
  execute immediate 'alter session set events ''10046 trace name context off''';
end;

The trace files will be written into the directory pointed to by the parameter user_dump_dest. You can query for the value by issuing a following statement:

SELECT s.sid,
       s.serial#,
       pa.value || '/' || LOWER(SYS_CONTEXT('userenv','instance_name')) ||    
       '_ora_' || p.spid || '.trc' AS trace_file
FROM   v$session s,
       v$process p,
       v$parameter pa
WHERE  pa.name = 'user_dump_dest'
AND    s.paddr = p.addr
AND    s.audsid = SYS_CONTEXT('USERENV', 'SESSIONID');

Use TKPROF utility to generate report:

D:\>tkprof D:\oracle\product\10.2.0\admin\orcl\udump\orcl_ora_8288_test1_binds_single_process.trc d:\trcout.txt.

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

OVERALL TOTALS FOR ALL NON-RECURSIVE STATEMENTS

call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        0      0.00       0.00          0          0          0           0
Execute      0      0.00       0.00          0          0          0           0
Fetch        0      0.00       0.00          0          0          0           0
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        0      0.00       0.00          0          0          0           0

Misses in library cache during parse: 0


OVERALL TOTALS FOR ALL RECURSIVE STATEMENTS

call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse       28      0.00       0.72          0          1          0           0
Execute   3625      0.48       0.47          0       3880       8123       27000
Fetch      545      0.10       0.07          0       3578          0         533
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total     4198      0.59       1.27          0       7459       8123       27533

Misses in library cache during parse: 18
Misses in library cache during execute: 16

Elapsed times include waiting on following events:
  Event waited on                             Times   Max. Wait  Total Waited
  ----------------------------------------   Waited  ----------  ------------
  undo segment extension                          1        0.00          0.00
  log file sync                                   1        0.00          0.00

   17  user  SQL statements in session.
   17  internal SQL statements in session.
   34  SQL statements in session.
********************************************************************************
Trace file: D:\oracle\product\10.2.0\admin\orcl\udump\orcl_ora_8288_test1_binds_single_process.trc
Trace file compatibility: 10.01.00
Sort options: default

       1  session in tracefile.
      17  user  SQL statements in trace file.
      17  internal SQL statements in trace file.
      34  SQL statements in trace file.
      20  unique SQL statements in trace file.
    5981  lines in trace file.
       1  elapsed seconds in trace file.

A list of key elements to analyse TKPROF report:

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

2. Search for SQL statements that do not use bind variables (:variable). These statements should be modified to use bind variables.

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