SQL Trace and TKPROF

SQL Trace and TKPROF

This article lists the commands required to trace SQL statements executed by a user, an application or the entire database.

Tracing a SQL session

[edit]Start session trace

To start a SQL trace for the current session, execute:

ALTER SESSION SET sql_trace = true;

You can also add an identifier to the trace file name for later identification:

ALTER SESSION SET sql_trace = true;
ALTER SESSION SET tracefile_identifier = mysqltrace;

[edit]Stop session trace

To stop SQL tracing for the current session, execute:

ALTER SESSION SET sql_trace = false;

[edit]Tracing other user's sessions

DBA's can use DBMS_SYSTEM.SET_SQL_TRACE_IN_SESSION to trace problematic database sessions. Steps:

• Get the SID and SERIAL# for the process you want to trace.

SQL> select sid, serial# from sys.v_$session where ...
       SID    SERIAL#
---------- ----------
         8      13607

• Enable tracing for your selected process:

SQL> ALTER SYSTEM SET timed_statistics = true;
SQL> execute dbms_system.set_sql_trace_in_session(8, 13607, true);

• Ask user to run just the necessary to demonstrate his problem.

• Disable tracing for your selected process:

SQL> execute dbms_system.set_sql_trace_in_session(8,13607, false);

• Look for trace file in USER_DUMP_DEST:

$ cd /app/oracle/admin/oradba/udump
$ ls -ltr
total 8
-rw-r-----    1 oracle   dba         2764 Mar 30 12:37 ora_9294.trc

[edit]Tracing an entire database

To enable SQL tracing for the entire database, execute:

ALTER SYSTEM SET sql_trace = true SCOPE=MEMORY;

To stop, execute:

ALTER SYSTEM SET sql_trace = false SCOPE=MEMORY;

[edit]Identifying trace files

Trace output is written to the database's UDUMP directory.

The default name for a trace files is INSTANCE_PID_ora_TRACEID.trc where:

• INSTANCE is the name of the Oracle instance,
• PID is the operating system process ID (V$PROCESS.OSPID); and
• TRACEID is a character string of your choosing.

[edit]Size of trace files

The trace file size is limited by the parameter MAX_DUMP_FILE_SIZE. The unit of this parameter, if you don't specify the K or M option, is in OS block size.

Be sure this parameter is set to a value high enough for your purpose (e.g. some MB). Of course this depends on the amount and complexitiy of statements which have to be run while tracing. If this value is set too low, possibly the dump file size limit will be reached before the execution of the crucial statements and the trace file will be closed before the interesting parts can be recorded in it.

On the other hand, when this parameter is set to UNLIMITED (default value), if the program to be traced is working forth and forth and the trace mode is not finished, the trace file can grow without limit which means until the associated file system or disk is full. A DBA can stop the trace of a session using the DBMS_MONITOR (10g and up), DBMS_SYSTEM or DBMS_SUPPORT package.

[edit]Formatting output

Trace output is quite unreadable. However, Oracle provides a utility, called TKProf, that can be used to format trace output.

TKProf

TKProf is an Oracle database utility used to format SQL Trace output into human readable format. The TKProf executable is located in the ORACLE HOME/bin directory.

[edit]Start TKProf

Syntax is:

tkprof input.trc output.prf [options]

Example:

$ tkprof orcl102_ora_3064.trc output.prf EXPLAIN=scott/tiger SYS=NO

[edit]Sample output

For the above example, the output would be in file output.prf:

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: ORCL102_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 = 3737
 
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