How to set trace on SQLPLUS

How to set trace on SQLPLUS

To enable client sqlnet tracing on a client machine for problem in SQL PLUS connections -

Change the connection to current scheman as below

alter session set current_schema=ABC

2. To check the currently enabled traces - select * from dba_enabled_traces;

1. Enable client sqlnet tracing in the client's sqlnet.ora file - this file is by default in the $ORACLE_HOME/network/admin directory

Please add the following lines to the file,

ADR_BASE = /u01/app/oracle

SQLNET.EXPIRE_TIME=5

TRACE_LEVEL_SERVER=16

TRACE_LEVEL_CLIENT=16

TRACE_TIMESTAMP_CLIENT=TRUE

TRACE_UNIQUE_CLIENT=TRUE

TRACE_DIRECTORY_CLIENT=C:\TRACE

TRACE_DIRECTORY_SERVER=/backup/sql_trace/

DIAG_ADR_ENABLED=OFF

The TRACE_DIRECTORY_CLIENT can be set to any pre-existing directory other than a top level directory (e.g. C:\ isn't valid but C:\TEMP could be).

2. Start sqlplus session

3. Tracefile will get generated in C:\TRACE for further analysis.

====

Once the OS process id for the process has been determined then the trace can be initialised as follows:

Lets assume that the process to be traced has an os pid of 9834.

Login to SQL*Plus as a dba and execute the following:

connect / as sysdba

oradebug setospid 9834 ---- this is os level SPID i.e. spid from v$process

oradebug unlimit

oradebug event 10046 trace name context forever,level 12

Note that it is also possible to attach to a session via oradebug using the 'setorapid'.

In this case the PID (i.e. PID from v$process) (Oracle Process identifier ) would be used (rather than the 'SPID') and the oradebug text would change to:

connect / as sysdba

oradebug setorapid 9834 -- This is actual ORACLE pid -

oradebug unlimit

oradebug event 10046 trace name context forever,level 12

• To disable oradebug tracing once tracing is finished:

oradebug event 10046 trace name context off;

For the existing sessions on the db -

select p.PID,p.SPID,s.SID from v$process p,v$session s where s.paddr = p.addr and s.sid = &SESSION_ID

SPID is the operating system Process identifier (os pid)

PID is the Oracle Process identifier (ora pid) 

If you do not know the Session ID then you can use a select similar to the following to help you identify the target session:

column line format a79

set heading off

select 'ospid: ' || p.spid || ' # ''' ||s.sid||','||s.serial#||''' '||

s.osuser || ' ' ||s.machine ||' '||s.username ||' '||s.program line

from v$session s , v$process p where p.addr = s.paddr and s.username <> ' ';

Note: For multi threaded processes in 12c, use newly added column stid from v$process to find specific thread, as Oracle

combines many processes into a single ospid. To find the specific thread, use following sytax:

oradebug setospid <spid> <stid>oradebug unlimit

The tracefile name will be something like <instance><spid>_<stid>.trc.

Instance wide tracing

Note: Please be cautious when setting system wide, as this will impact performance due to every session being traced.

This setting will trace every session that is created after the parameter is set. Existing sessions will not be traced.

Setting system-wide 10046 tracing can be useful for scenarios where a problem session is known to occur but cannot be identified in advance.

In this situation, tracing can be enabled for a short period of time, the problem can then be reproduced and tracing disabled and the resultant traces searched for evidence of the problem.

System-wide tracing can be enabled as follows:

alter system set events '10046 trace name context forever,level 12';

The setting can be disabled in all sessions by using the following command:

alter system set events '10046 trace name context off';

Initialisation parameter setting

• This setting will trace every session in the instance when it is restarted.

event="10046 trace name context forever,level 12"

The setting can be disabled by removing the parameter and restarting the instance or by using an alter system command as follows:

alter system set events '10046 trace name context off';

OR 

At database level -

To enable - dbms_monitor.database_trace_enable(waits => TRUE, binds => TRUE, instance_name => NULL) == If the parameter instance_name is set to NULL,- SQL trace is enabled for all instances

To disable - dbms_monitor.database_trace_disable(instance_name => NULL)

==================

The DBMS_System Package

The DBMS_System package contains a number of routines that can be useful on occasion. Oracle clearly state that these routines are not supported so proceed at your own risk.

ksdwrt

Used to write messages to the alertlog and/or trace files.

• 
  EXEC DBMS_System.ksdwrt(n, message);
  
  EXEC DBMS_System.ksdwrt(2, 'My Test Alertlog Message');
  

Where the value of "n" indicates the destination.

• 1 - Write to trace file.
• 2 - Write to alertlog.
• 3 - Write to both.

Set_Sql_Trace_In_Session

Used to set trace on or off in another users session.

• 
  EXEC DBMS_System.Set_Sql_Trace_In_Session(sid, serial#, true );
  
  EXEC DBMS_System.Set_Sql_Trace_In_Session(31, 97, true );
  

The values for SID and SERIAL# can be found using the V$SESSION view.

Set_Ev

Used to set trace on for a specific event.

• 
  EXEC DBMS_System.Set_Ev(sid, serial#, event, level, name);
  
  EXEC DBMS_System.Set_Ev(31, 97, 10046, 4, '');
  

Where level indicates the following levels of trace.

• 1 - Standard SQL_TRACE functionality.
• 4 - As level 1 plus tracing of bind variables.
• 8 - As level 1 plus wait events.
• 12 - As level 1 plus bind variables and wait events.

Read_Ev

Used to check if a specific event is currently being traced.

• EXEC DBMS_System.Read_Ev(event, output);

If output = 1 the event is being traced.

SQL trace, 10046, trcsess and tkprof in Oracle 10g

The quickest way to capture the SQL is being processed by a session is to switch on SQL trace or set the 10046 event for a representative period of time. The resulting trace files can be read in their raw state or translated using the tkprof utility. Explaining the contents of the trace file is beyond the scope of this article, but the following sections explain how trace files can be created and processed.

Generating SQL Trace Files

There are numerous ways to enable, disable and vary the contents of this trace. The following methods have been available for several versions of the database.

• 
  -- All versions.
  
  SQL> ALTER SESSION SET sql_trace=TRUE;
  
  SQL> ALTER SESSION SET sql_trace=FALSE;
  
  SQL> EXEC DBMS_SESSION.set_sql_trace(sql_trace => TRUE);
  
  SQL> EXEC DBMS_SESSION.set_sql_trace(sql_trace => FALSE);
  
  SQL> ALTER SESSION SET EVENTS '10046 trace name context forever, level 8';
  SQL> ALTER SESSION SET EVENTS '10046 trace name context off';
  
  SQL> EXEC DBMS_SYSTEM.set_sql_trace_in_session(sid=>123, serial#=>1234, sql_trace=>TRUE);
  SQL> EXEC DBMS_SYSTEM.set_sql_trace_in_session(sid=>123, serial#=>1234, sql_trace=>FALSE);
  
  -- Available from SQL*Plus since 8i (commandline utility prior to this.
  SQL> EXEC DBMS_SYSTEM.set_ev(si=>123, se=>1234, ev=>10046, le=>8, nm=>' ');
  SQL> EXEC DBMS_SYSTEM.set_ev(si=>123, se=>1234, ev=>10046, le=>0, nm=>' ');
  
  SQL> ORADEBUG SETOSPID 1234; -- Debug session with the specified OS process.
  SQL> CONN sys/password AS SYSDBA; -- User must have SYSDBA.
  SQL> ORADEBUG SETMYPID; -- Debug current session.
  SQL> ORADEBUG SETORAPID 123456; -- Debug session with the specified Oracle process ID.
  
  -- All versions, requires DBMS_SUPPORT package to be loaded.
  SQL> ORADEBUG EVENT 10046 TRACE NAME CONTEXT FOREVER, LEVEL 12;
  SQL> ORADEBUG TRACEFILE_NAME; -- Display the current trace file.
  SQL> ORADEBUG EVENT 10046 TRACE NAME CONTEXT OFF;
   
  SQL> EXEC DBMS_SUPPORT.start_trace(waits=>TRUE, binds=>FALSE);
  
  SQL> EXEC DBMS_SUPPORT.stop_trace_in_session(sid=>123, serial=>1234);
  SQL> EXEC DBMS_SUPPORT.stop_trace;
  
  SQL> EXEC DBMS_SUPPORT.start_trace_in_session(sid=>123, serial=>1234, waits=>TRUE, binds=>FALSE);
  

The DBMS_SUPPORT package is not present by default, but can be loaded as the SYS user by executing the "@$ORACLE_HOME/rdbms/admin/dbmssupp.sql" script.

For methods that require tracing levels the following are valid values.

• 0 - No trace. Like switching sql_trace off.
• 2 - The equivalent of regular sql_trace.
• 4 - The same as 2, but with the addition of bind variable values.
• 8 - The same as 2, but with the addition of wait events.
• 12 - The same as 2, but with both bind variable values and wait events.

The same combinations are possible for those methods with boolean parameters for waits and binds.

With the advent of Oracle 10g the SQL tracing options have been centralized and extended using the DBMS_MONITOR package. The examples below show just a few possible variations for enabling and disabling SQL trace in Oracle 10g.

• 
  -- Oracle 10g
  
  SQL> EXEC DBMS_MONITOR.session_trace_enable;
  
  SQL> EXEC DBMS_MONITOR.session_trace_enable(waits=>TRUE, binds=>FALSE);
  SQL> EXEC DBMS_MONITOR.session_trace_disable;
  
  SQL> EXEC DBMS_MONITOR.session_trace_enable(session_id=>1234, serial_num=>1234);
  SQL> EXEC DBMS_MONITOR.session_trace_enable(session_id =>1234, serial_num=>1234, waits=>TRUE, binds=>FALSE);
  
  SQL> EXEC DBMS_MONITOR.client_id_trace_enable(client_id=>'tim_hall');
  SQL> EXEC DBMS_MONITOR.session_trace_disable(session_id=>1234, serial_num=>1234);
  SQL> EXEC DBMS_MONITOR.client_id_trace_enable(client_id=>'tim_hall', waits=>TRUE, binds=>FALSE);
  
  SQL> EXEC DBMS_MONITOR.serv_mod_act_trace_enable(service_name=>'db10g', module_name=>'test_api', action_name=>'running');
  SQL> EXEC DBMS_MONITOR.client_id_trace_disable(client_id=>'tim_hall');
  SQL> EXEC DBMS_MONITOR.serv_mod_act_trace_enable(service_name=>'db10g', module_name=>'test_api', action_name=>'running', -> waits=>TRUE, binds=>FALSE);
  
  SQL> EXEC DBMS_MONITOR.serv_mod_act_trace_disable(service_name=>'db10g', module_name=>'test_api', action_name=>'running');
  

The package provides the conventional session level tracing along with two new variations. First, tracing can be enabled on multiple sessions based on the value of the client_identifier column of theV$SESSION view, set using the DBMS_SESSION package. Second, trace can be activated for multiple sessions based on various combinations of the service_name, module, action columns in the V$SESSIONview, set using the DBMS_APPLICATION_INFO package, along with the instance_name in RAC environments. With all the possible permutations and default values this provides a high degree of flexibility.

Identifying Trace Files

Oracle allows you to set the TRACEFILE_IDENTIFIER parameter at session level, allowing you to include some recognizable text into the trace file name.

• ALTER SESSION SET TRACEFILE_IDENTIFIER = "MY_TEST_SESSION";

Even without this, we can easily identify the trace file for the current session using the USER_DUMP_DEST value with the instance name and the session's process id. The identify_trace_file.sql script combines these values to produce the expected trace file name.

• 
  SET LINESIZE 100
  
  COLUMN trace_file FORMAT A60
  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
  
  AND s.audsid = SYS_CONTEXT('USERENV', 'SESSIONID');
  WHERE pa.name = 'user_dump_dest'
  
  AND s.paddr = p.addr
  

If you are using a windows environment you will need to alter the "/" to a "\" in the concatenated string. The expected output from this script is displayed below.

Note. Identification of trace files is simpler in Oracle 11g due to the introduction of diagnostic views. The Oracle 11g version of the identify_trace_file.sql is shown below.

• 
  SET LINESIZE 100
  
  COLUMN value FORMAT A60
  SELECT value
  
  WHERE name = 'Default Trace File';
  
  FROM v$diag_info
  

trcsess

Activating trace on multiple sessions means that trace information is spread throughout many trace files. For this reason Oracle 10g introduced the trcsess utility, which allows trace information from multiple trace files to be identified and consolidated into a single trace file. The trcsess usage is listed below.

• 
  trcsess [output=<output file name >] [session=<session ID>] [clientid=<clientid>]
  
   [service=<service name>] [action=<action name>] [module=<module name>] <trace file names>
  output=<output file name> output destination default being standard output.
  
  Session id is a combination of session Index & session serial number e.g. 8.13.
  session=<session Id> session to be traced.
  clientid=<clientid> clientid to be traced.
  
  module=<module name> module to be traced.
  service=<service name> service to be traced.
  action=<action name> action to be traced.
  
  <trace_file_names> Space separated list of trace files with wild card '*' supported.
  

With all these options the consolidated trace file can be as broad or as specific as needed.

tkprof

The SQL trace files produced by the methods discussed previously can be read in their raw form, or they can be translated by the tkprof utility into a more human readable form. The output below lists the usage notes from the tkprof utility in Oracle 10g.

• 
  $ tkprof
  
  Usage: tkprof tracefile outputfile [explain= ] [table= ]
  [print= ] [insert= ] [sys= ] [sort= ]
  
   table=schema.tablename Use 'schema.tablename' with 'explain=' option.
  explain=user/password Connect to ORACLE and issue EXPLAIN PLAN.
  
   insert=filename List SQL statements and data inside INSERT statements.
  print=integer List only the first 'integer' SQL statements.
   aggregate=yes|no
  
   record=filename Record non-recursive statements found in the trace file.
  sys=no TKPROF does not list SQL statements run as user SYS.
   waits=yes|no Record summary for any wait events found in the trace file.
  
   prsela elapsed time parsing
  sort=option Set of zero or more of the following sort options:
   prscnt number of times parse was called
   prscpu cpu time parsing
   prsdsk number of disk reads during parse
  
   execnt number of execute was called
  prsqry number of buffers for consistent read during parse
   prscu number of buffers for current read during parse
   prsmis number of misses in library cache during parse
   execpu cpu time spent executing
  
   exerow number of rows processed during execute
  exeela elapsed time executing
   exedsk number of disk reads during execute
   exeqry number of buffers for consistent read during execute
   execu number of buffers for current read during execute
  
   fchqry number of buffers for consistent read during fetch
  exemis number of library cache misses during execute
   fchcnt number of times fetch was called
   fchcpu cpu time spent fetching
   fchela elapsed time fetching
   fchdsk number of disk reads during fetch
  
  $
  fchcu number of buffers for current read during fetch
   fchrow number of rows fetched
  
   userid userid of user that parsed the cursor
  

The waits parameter was only added in Oracle 9i, so prior to this version wait information had to be read from the raw trace file. The values of bind variables must be read from the raw files as they are not displayed in the tkprof output.

The following section shows an example of gathering SQL trace for a session to give you an idea of the whole process.

Trace Example

The following script creates a test table and a procedure that populates it. This procedure will be the subject of our example trace.

• 
  CREATE TABLE sql_trace_test (
  id NUMBER,
  
  EXEC DBMS_STATS.gather_table_stats('test', 'sql_trace_test');
  description VARCHAR2(50)
  );
  
  CREATE OR REPLACE PROCEDURE populate_sql_trace_test (p_loops IN NUMBER) AS
  l_number NUMBER;
  BEGIN
   FOR i IN 1 .. p_loops LOOP
   INSERT INTO sql_trace_test (id, description)
  
   FROM sql_trace_test;
  VALUES (i, 'Description for ' || i);
   END LOOP;
   
   SELECT COUNT(*)
   INTO l_number
   
   COMMIT;
   
  
  SHOW ERRORS
  DBMS_OUTPUT.put_line(l_number || ' rows inserted.');
  END;
  
  /
  

Gathering the statistics on the empty table may seem odd, but this prevents any dynamic sampling being added to the trace file contents, which would only serve to complicate the file.

Next, we identify the trace file for the current session.

• 
  SQL> @identify_trace_file.sql
  SID SERIAL# TRACE_FILE
  
  ---------- ---------- ------------------------------------------------------------
  130 26739 /u01/app/oracle/admin/DEV/udump/dev1_ora_367660.trc
  1 row selected.
  
  SQL>
  

Now we know the name of the trace file we can enable tracing, execute the procedure and disable tracing.

• 
  SQL> ALTER SESSION SET EVENTS '10046 trace name context forever, level 8';
  Session altered.
  SQL> SET SERVEROUTPUT ON
  
  PL/SQL procedure successfully completed.
  SQL> EXEC populate_sql_trace_test(p_loops => 5);
  5 rows inserted.
  
  SQL>
  SQL> ALTER SESSION SET EVENTS '10046 trace name context off';
  
  Session altered.
  

The contents of the file are listed below. The output looks a little confusing, but you can identify the individual statements and their associated waits and statistics.

• 
  /u01/app/oracle/admin/DEV/udump/dev1_ora_367660.trc
  
  Oracle Database 10g Enterprise Edition Release 10.1.0.3.0 - Production
  
  With the Partitioning, Oracle Label Security, OLAP and Data Mining options
  ORACLE_HOME = /u01/app/oracle/product/10.1.0/db_1
  System name: OSF1
  
  Machine: alpha
  Node name: dbserver.oracle-base.com
  Release: V5.1
  Version: 2650
  Instance name: DEV1
  
  Unix process pid: 367660, image: oracleDEV1@dbserver.oracle-base.com
  Redo thread mounted by this instance: 1
  Oracle process number: 16
  *** 2005-04-05 09:46:51.499
  
  *** SERVICE NAME:(SYS$USERS) 2005-04-05 09:46:51.499
  *** ACTION NAME:() 2005-04-05 09:46:51.499
  *** MODULE NAME:(SQL*Plus) 2005-04-05 09:46:51.499
  
  PARSING IN CURSOR #29 len=68 dep=0 uid=180 oct=42 lid=180 tim=11746409761792 hv=3847243385 ad='2bb57798'
  *** SESSION ID:(130.26739) 2005-04-05 09:46:51.499
  =====================
  ALTER SESSION SET EVENTS '10046 trace name context forever, level 8'
  
  WAIT #29: nam='SQL*Net message to client' ela= 0 p1=1413697536 p2=1 p3=0
  END OF STMT
  EXEC #29:c=0,e=1024,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,tim=11746409761792
  
  PARSING IN CURSOR #4 len=36 dep=0 uid=180 oct=47 lid=180 tim=11746417122304 hv=3425213768 ad='2c631cd8'
  WAIT #29: nam='SQL*Net message from client' ela= 7358464 p1=1413697536 p2=1 p3=0
  =====================
  BEGIN DBMS_OUTPUT.ENABLE(2000); END;
  END OF STMT
  
  WAIT #4: nam='SQL*Net message to client' ela= 0 p1=1413697536 p2=1 p3=0
  PARSE #4:c=0,e=1024,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,tim=11746417122304
  EXEC #4:c=0,e=0,p=0,cr=0,cu=0,mis=0,r=1,dep=0,og=1,tim=11746417122304
  WAIT #4: nam='SQL*Net message from client' ela= 6924288 p1=1413697536 p2=1 p3=0
  
  PARSE #18:c=0,e=3072,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=1,tim=11746424051712
  =====================
  PARSING IN CURSOR #18 len=51 dep=0 uid=180 oct=47 lid=180 tim=11746424051712 hv=2083693016 ad='27ecb338'
  BEGIN populate_sql_trace_test(p_loops => 5); END;
  END OF STMT
  =====================
  
  PARSE #19:c=0,e=1024,p=0,cr=0,cu=0,mis=1,r=0,dep=1,og=1,tim=11746424052736
  PARSING IN CURSOR #19 len=86 dep=1 uid=180 oct=2 lid=180 tim=11746424052736 hv=3247833140 ad='28fa57f8'
  INSERT INTO SQL_TRACE_TEST (ID, DESCRIPTION) VALUES (:B1 , 'Description for ' || :B1 )
  END OF STMT
  =====================
  
  EXEC #23:c=0,e=5120,p=0,cr=0,cu=0,mis=1,r=0,dep=2,og=4,tim=11746424059904
  PARSING IN CURSOR #23 len=69 dep=2 uid=0 oct=3 lid=0 tim=11746424053760 hv=1471956217 ad='2e7591f0'
  select con#,obj#,rcon#,enabled,nvl(defer,0) from cdef$ where robj#=:1
  END OF STMT
  PARSE #23:c=0,e=1024,p=0,cr=0,cu=0,mis=1,r=0,dep=2,og=4,tim=11746424053760
  
  ,mtime,nvl(spare1,0) from cdef$ where obj#=:1
  FETCH #23:c=0,e=0,p=0,cr=2,cu=0,mis=0,r=0,dep=2,og=4,tim=11746424059904
  =====================
  PARSING IN CURSOR #25 len=146 dep=2 uid=0 oct=3 lid=0 tim=11746424065024 hv=2107929772 ad='2e7b4b08'
  select con#,type#,condlength,intcols,robj#,rcon#,match#,refact,nvl(enabled,0),rowid,cols,nvl(defer,0)
  END OF STMT
  
  distcnt, lowval, hival, density, col#, spare1, spare2, avgcln from hist_head$ where obj#=:1 and intcol#=:2
  PARSE #25:c=0,e=5120,p=0,cr=0,cu=0,mis=1,r=0,dep=2,og=4,tim=11746424065024
  =====================
  PARSING IN CURSOR #27 len=210 dep=3 uid=0 oct=3 lid=0 tim=11746424102912 hv=864012087 ad='2e351f08'
  select /*+ rule */ bucket_cnt, row_cnt, cache_cnt, null_cnt, timestamp#, sample_size, minimum, maximum,
  END OF STMT
  
  EXEC #27:c=0,e=0,p=0,cr=0,cu=0,mis=0,r=0,dep=3,og=3,tim=11746424110080
  PARSE #27:c=50000,e=36864,p=0,cr=0,cu=0,mis=1,r=0,dep=3,og=3,tim=11746424102912
  EXEC #27:c=16667,e=4096,p=0,cr=0,cu=0,mis=1,r=0,dep=3,og=3,tim=11746424108032
  FETCH #27:c=0,e=1024,p=0,cr=3,cu=0,mis=0,r=1,dep=3,og=3,tim=11746424109056
  EXEC #27:c=0,e=0,p=0,cr=0,cu=0,mis=0,r=0,dep=3,og=3,tim=11746424109056
  FETCH #27:c=0,e=0,p=0,cr=3,cu=0,mis=0,r=1,dep=3,og=3,tim=11746424109056
  
  PARSE #28:c=0,e=9216,p=0,cr=0,cu=0,mis=1,r=0,dep=3,og=3,tim=11746424119296
  FETCH #27:c=0,e=0,p=0,cr=3,cu=0,mis=0,r=1,dep=3,og=3,tim=11746424110080
  =====================
  PARSING IN CURSOR #28 len=121 dep=3 uid=0 oct=3 lid=0 tim=11746424119296 hv=3150898423 ad='2e347db8'
  select /*+ rule */ bucket, endpoint, col#, epvalue from histgrm$ where obj#=:1 and intcol#=:2 and row#=:3
  order by bucket
  END OF STMT
  EXEC #28:c=0,e=1024,p=0,cr=0,cu=0,mis=1,r=0,dep=3,og=3,tim=11746424121344
  
  FETCH #25:c=0,e=0,p=0,cr=2,cu=0,mis=0,r=0,dep=2,og=4,tim=11746424126464
  FETCH #28:c=0,e=1024,p=0,cr=3,cu=0,mis=0,r=3,dep=3,og=3,tim=11746424122368
  EXEC #27:c=0,e=0,p=0,cr=0,cu=0,mis=0,r=0,dep=3,og=3,tim=11746424122368
  FETCH #27:c=0,e=0,p=0,cr=3,cu=0,mis=0,r=1,dep=3,og=3,tim=11746424122368
  EXEC #27:c=0,e=0,p=0,cr=0,cu=0,mis=0,r=0,dep=3,og=3,tim=11746424123392
  FETCH #27:c=0,e=0,p=0,cr=3,cu=0,mis=0,r=1,dep=3,og=3,tim=11746424123392
  EXEC #25:c=83334,e=61440,p=0,cr=18,cu=0,mis=1,r=0,dep=2,og=4,tim=11746424126464
  =====================
  
  FETCH #12:c=0,e=0,p=0,cr=2,cu=0,mis=0,r=0,dep=2,og=4,tim=11746424131584
  PARSING IN CURSOR #12 len=169 dep=2 uid=0 oct=3 lid=0 tim=11746424128512 hv=1173719687 ad='2e7c2c50'
  select col#, grantee#, privilege#,max(mod(nvl(option$,0),2)) from objauth$ where obj#=:1 and col# is not null
  group by privilege#, col#, grantee# order by col#, grantee#
  END OF STMT
  PARSE #12:c=0,e=1024,p=0,cr=0,cu=0,mis=1,r=0,dep=2,og=4,tim=11746424128512
  EXEC #12:c=0,e=3072,p=0,cr=0,cu=0,mis=1,r=0,dep=2,og=4,tim=11746424131584
  =====================
  PARSING IN CURSOR #26 len=151 dep=2 uid=0 oct=3 lid=0 tim=11746424131584 hv=4139184264 ad='2e7cc608'
  
  select u.name,o.name, t.update$, t.insert$, t.delete$, t.enabled from obj$ o,user$ u,trigger$ t where 
  select grantee#,privilege#,nvl(col#,0),max(mod(nvl(option$,0),2))from objauth$ where obj#=:1 group by grantee#,
  privilege#,nvl(col#,0) order by grantee#
  END OF STMT
  PARSE #26:c=0,e=0,p=0,cr=0,cu=0,mis=0,r=0,dep=2,og=4,tim=11746424131584
  EXEC #26:c=0,e=0,p=0,cr=0,cu=0,mis=0,r=0,dep=2,og=4,tim=11746424131584
  FETCH #26:c=0,e=1024,p=0,cr=2,cu=0,mis=0,r=0,dep=2,og=4,tim=11746424132608
  =====================
  PARSING IN CURSOR #7 len=175 dep=2 uid=0 oct=3 lid=0 tim=11746424132608 hv=1729330152 ad='2f3597a8'
  t.baseobject=:1 and t.obj#=o.obj# and o.owner#=u.user# order by o.obj#
  END OF STMT
  PARSE #7:c=0,e=0,p=0,cr=0,cu=0,mis=0,r=0,dep=2,og=4,tim=11746424132608
  
  STAT #7 id=6 cnt=0 pid=3 pos=2 obj=18 op='TABLE ACCESS BY INDEX ROWID OBJ$ (cr=0 pr=0 pw=0 time=0 us)'
  EXEC #7:c=0,e=0,p=0,cr=0,cu=0,mis=0,r=0,dep=2,og=4,tim=11746424132608
  FETCH #7:c=0,e=0,p=0,cr=2,cu=0,mis=0,r=0,dep=2,og=4,tim=11746424132608
  STAT #7 id=1 cnt=0 pid=0 pos=1 obj=0 op='SORT ORDER BY (cr=2 pr=0 pw=0 time=0 us)'
  STAT #7 id=2 cnt=0 pid=1 pos=1 obj=0 op='NESTED LOOPS (cr=2 pr=0 pw=0 time=0 us)'
  STAT #7 id=3 cnt=0 pid=2 pos=1 obj=0 op='NESTED LOOPS (cr=2 pr=0 pw=0 time=0 us)'
  STAT #7 id=4 cnt=0 pid=3 pos=1 obj=84 op='TABLE ACCESS BY INDEX ROWID TRIGGER$ (cr=2 pr=0 pw=0 time=0 us)'
  STAT #7 id=5 cnt=0 pid=4 pos=1 obj=128 op='INDEX RANGE SCAN I_TRIGGER1 (cr=2 pr=0 pw=0 time=0 us)'
  STAT #7 id=7 cnt=0 pid=6 pos=1 obj=36 op='INDEX UNIQUE SCAN I_OBJ1 (cr=0 pr=0 pw=0 time=0 us)'
  
  END OF STMT
  STAT #7 id=8 cnt=0 pid=2 pos=2 obj=22 op='TABLE ACCESS CLUSTER USER$ (cr=0 pr=0 pw=0 time=0 us)'
  STAT #7 id=9 cnt=0 pid=8 pos=1 obj=11 op='INDEX UNIQUE SCAN I_USER# (cr=0 pr=0 pw=0 time=0 us)'
  EXEC #19:c=83334,e=86016,p=0,cr=29,cu=21,mis=1,r=1,dep=1,og=1,tim=11746424138752
  EXEC #19:c=0,e=0,p=0,cr=0,cu=1,mis=0,r=1,dep=1,og=1,tim=11746424138752
  EXEC #19:c=0,e=0,p=0,cr=0,cu=1,mis=0,r=1,dep=1,og=1,tim=11746424138752
  EXEC #19:c=0,e=0,p=0,cr=0,cu=1,mis=0,r=1,dep=1,og=1,tim=11746424139776
  EXEC #19:c=0,e=0,p=0,cr=0,cu=1,mis=0,r=1,dep=1,og=1,tim=11746424139776
  =====================
  PARSING IN CURSOR #29 len=35 dep=1 uid=180 oct=3 lid=180 tim=11746424140800 hv=3788777626 ad='2c84eb58'
  SELECT COUNT(*) FROM SQL_TRACE_TEST
  
  PARSING IN CURSOR #7 len=52 dep=0 uid=180 oct=47 lid=180 tim=11746424143872 hv=1029988163 ad='2c2ec1b8'
  PARSE #29:c=0,e=1024,p=0,cr=0,cu=0,mis=1,r=0,dep=1,og=1,tim=11746424140800
  EXEC #29:c=0,e=1024,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=1,tim=11746424141824
  FETCH #29:c=0,e=0,p=0,cr=7,cu=0,mis=0,r=1,dep=1,og=1,tim=11746424141824
  =====================
  PARSING IN CURSOR #4 len=6 dep=1 uid=180 oct=44 lid=180 tim=11746424141824 hv=255718823 ad='2e5363f0'
  COMMIT
  END OF STMT
  PARSE #4:c=0,e=0,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=1,tim=11746424141824
  XCTEND rlbk=0, rd_only=0
  EXEC #4:c=0,e=0,p=0,cr=0,cu=1,mis=0,r=0,dep=1,og=1,tim=11746424141824
  EXEC #18:c=83334,e=91136,p=0,cr=36,cu=26,mis=0,r=1,dep=0,og=1,tim=11746424142848
  WAIT #18: nam='SQL*Net message to client' ela= 0 p1=1413697536 p2=1 p3=0
  WAIT #18: nam='SQL*Net message from client' ela= 1024 p1=1413697536 p2=1 p3=0
  =====================
  
  EXEC #12:c=0,e=0,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,tim=11746432706560
  BEGIN DBMS_OUTPUT.GET_LINES(:LINES, :NUMLINES); END;
  END OF STMT
  PARSE #7:c=0,e=0,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,tim=11746424143872
  WAIT #7: nam='SQL*Net message to client' ela= 0 p1=1413697536 p2=1 p3=0
  EXEC #7:c=0,e=0,p=0,cr=0,cu=0,mis=0,r=1,dep=0,og=1,tim=11746424144896
  WAIT #7: nam='SQL*Net message from client' ela= 8560640 p1=1413697536 p2=1 p3=0
  =====================
  PARSING IN CURSOR #12 len=55 dep=0 uid=180 oct=42 lid=180 tim=11746432706560 hv=2655499671 ad='2a24eab8'
  ALTER SESSION SET EVENTS '10046 trace name context off'
  END OF STMT
  
  PARSE #12:c=0,e=0,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,tim=11746432705536
  

The following command uses the tkprof utility to translate the trace file, placing the translated output in the translated.txt file.The explain and table parameters have been set to allow execution plans to be displayed and the sys parameter prevents recursive SQL being displayed.

• 
  $ cd /u01/app/oracle/admin/DEV/udump/
  
  $ tkprof dev1_ora_367660.trc translated.txt explain=test/test table=sys.plan_table sys=no waits=yes
  TKPROF: Release 10.1.0.3.0 - Production on Tue Apr 5 09:22:43 2005
  
  $
  
  Copyright (c) 1982, 2004, Oracle. All rights reserved.
  

The contents of the translated file are displayed below.

• 
  TKPROF: Release 10.1.0.3.0 - Production on Tue Apr 5 09:53:50 2005
  Copyright (c) 1982, 2004, Oracle. All rights reserved.
  
  ********************************************************************************
  Trace file: dev1_ora_367660.trc
  Sort options: default
  
  cpu = cpu time in seconds executing 
  count = number of times OCI procedure was executed
  elapsed = elapsed time in seconds executing
  
  query = number of buffers gotten for consistent read
  disk = number of physical reads of buffers from disk
  current = number of buffers gotten in current mode (usually for update)
  
  ALTER SESSION SET EVENTS '10046 trace name context forever, level 8'
  rows = number of rows processed by the fetch or execute call
  ********************************************************************************
  
  Fetch 0 0.00 0.00 0 0 0 0
  call count cpu elapsed disk query current rows
  ------- ------ -------- ---------- ---------- ---------- ---------- ----------
  Parse 0 0.00 0.00 0 0 0 0
  Execute 1 0.00 0.00 0 0 0 0
  
  Parsing user id: 180 (TEST)
  ------- ------ -------- ---------- ---------- ---------- ---------- ----------
  total 1 0.00 0.00 0 0 0 0
  Misses in library cache during parse: 0
  Optimizer mode: ALL_ROWS
  Elapsed times include waiting on following events:
  
  ********************************************************************************
  Event waited on Times Max. Wait Total Waited
   ---------------------------------------- Waited ---------- ------------
   SQL*Net message to client 1 0.00 0.00
   SQL*Net message from client 1 7.35 7.35
  BEGIN DBMS_OUTPUT.ENABLE(2000); END;
  
  ------- ------ -------- ---------- ---------- ---------- ---------- ----------
  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 1
  Fetch 0 0.00 0.00 0 0 0 0
  total 2 0.00 0.00 0 0 0 1
  Misses in library cache during parse: 0
  
   SQL*Net message from client 1 6.92 6.92
  Optimizer mode: ALL_ROWS
  Parsing user id: 180 (TEST)
  Elapsed times include waiting on following events:
   Event waited on Times Max. Wait Total Waited
   ---------------------------------------- Waited ---------- ------------
   SQL*Net message to client 1 0.00 0.00
  
  Execute 1 0.00 0.00 0 0 0 1
  ********************************************************************************
  BEGIN populate_sql_trace_test(p_loops => 5); END;
  call count cpu elapsed disk query current rows
  ------- ------ -------- ---------- ---------- ---------- ---------- ----------
  Parse 1 0.00 0.00 0 0 0 0
  Fetch 0 0.00 0.00 0 0 0 0
  
   ---------------------------------------- Waited ---------- ------------
  ------- ------ -------- ---------- ---------- ---------- ---------- ----------
  total 2 0.00 0.00 0 0 0 1
  Misses in library cache during parse: 1
  Optimizer mode: ALL_ROWS
  Parsing user id: 180 (TEST)
  Elapsed times include waiting on following events:
   Event waited on Times Max. Wait Total Waited
   SQL*Net message to client 1 0.00 0.00
   SQL*Net message from client 1 0.00 0.00
  
  ------- ------ -------- ---------- ---------- ---------- ---------- ----------
  ********************************************************************************
  INSERT INTO SQL_TRACE_TEST (ID, DESCRIPTION) 
  VALUES
   (:B1 , 'Description for ' || :B1 )
  call count cpu elapsed disk query current rows
  ------- ------ -------- ---------- ---------- ---------- ---------- ----------
  Parse 1 0.00 0.00 0 0 0 0
  Execute 5 0.00 0.00 0 1 25 5
  Fetch 0 0.00 0.00 0 0 0 0
  total 6 0.00 0.00 0 1 25 5
  Misses in library cache during parse: 1
  
  ------- ------ -------- ---------- ---------- ---------- ---------- ----------
  Misses in library cache during execute: 1
  Optimizer mode: ALL_ROWS
  Parsing user id: 180 (TEST) (recursive depth: 1)
  Rows Execution Plan
  ------- ---------------------------------------------------
   0 INSERT STATEMENT MODE: ALL_ROWS
  ********************************************************************************
  SELECT COUNT(*) 
  FROM
   SQL_TRACE_TEST
  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: 180 (TEST) (recursive depth: 1)
  Rows Execution Plan
  ------- ---------------------------------------------------
   0 SELECT STATEMENT MODE: ALL_ROWS
   0 SORT (AGGREGATE)
   0 TABLE ACCESS MODE: ANALYZED (FULL) OF 'SQL_TRACE_TEST' 
   (TABLE)
  COMMIT
  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 1 0
  Fetch 0 0.00 0.00 0 0 0 0
  ------- ------ -------- ---------- ---------- ---------- ---------- ----------
  total 2 0.00 0.00 0 0 1 0
  Misses in library cache during parse: 0
  Optimizer mode: ALL_ROWS
  Parsing user id: 180 (TEST) (recursive depth: 1)
  ********************************************************************************
  BEGIN DBMS_OUTPUT.GET_LINES(:LINES, :NUMLINES); END;
  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 1
  Fetch 0 0.00 0.00 0 0 0 0
  
  ALTER SESSION SET EVENTS '10046 trace name context off'
  ------- ------ -------- ---------- ---------- ---------- ---------- ----------
  total 2 0.00 0.00 0 0 0 1
  Misses in library cache during parse: 0
  Optimizer mode: ALL_ROWS
  Parsing user id: 180 (TEST)
  Elapsed times include waiting on following events:
   Event waited on Times Max. Wait Total Waited
   ---------------------------------------- Waited ---------- ------------
   SQL*Net message to client 1 0.00 0.00
   SQL*Net message from client 1 8.56 8.56
  ********************************************************************************
  call count cpu elapsed disk query current rows
  
  Execute 5 0.00 0.00 0 0 0 3
  ------- ------ -------- ---------- ---------- ---------- ---------- ----------
  Parse 1 0.00 0.00 0 0 0 0
  Execute 1 0.00 0.00 0 0 0 0
  Fetch 0 0.00 0.00 0 0 0 0
  ------- ------ -------- ---------- ---------- ---------- ---------- ----------
  total 2 0.00 0.00 0 0 0 0
  Misses in library cache during parse: 0
  Optimizer mode: ALL_ROWS
  Parsing user id: 180 (TEST)
  ********************************************************************************
  OVERALL TOTALS FOR ALL NON-RECURSIVE STATEMENTS
  call count cpu elapsed disk query current rows
  ------- ------ -------- ---------- ---------- ---------- ---------- ----------
  Parse 4 0.00 0.00 0 0 0 0
  
  Fetch 12 0.00 0.00 0 35 0 9
  Fetch 0 0.00 0.00 0 0 0 0
  ------- ------ -------- ---------- ---------- ---------- ---------- ----------
  total 9 0.00 0.00 0 0 0 3
  Misses in library cache during parse: 1
  Elapsed times include waiting on following events:
   Event waited on Times Max. Wait Total Waited
   ---------------------------------------- Waited ---------- ------------
   SQL*Net message to client 4 0.00 0.00
   SQL*Net message from client 4 8.56 22.84
  OVERALL TOTALS FOR ALL RECURSIVE STATEMENTS
  call count cpu elapsed disk query current rows
  ------- ------ -------- ---------- ---------- ---------- ---------- ----------
  Parse 10 0.05 0.05 0 0 0 0
  Execute 18 0.03 0.03 0 1 26 5
  
   15 unique SQL statements in trace file.
  ------- ------ -------- ---------- ---------- ---------- ---------- ----------
  total 40 0.08 0.08 0 36 26 14
  Misses in library cache during parse: 7
  Misses in library cache during execute: 6
   8 user SQL statements in session.
   7 internal SQL statements in session.
   15 SQL statements in session.
   2 statements EXPLAINed in this session.
  ********************************************************************************
  Trace file: dev1_ora_367660.trc
  Trace file compatibility: 10.01.00
  Sort options: default
   1 session in tracefile.
   8 user SQL statements in trace file.
   7 internal SQL statements in trace file.
   15 SQL statements in trace file.
   2 SQL statements EXPLAINed using schema:
   sys.plan_table
   Schema was specified.
  
   22 elapsed seconds in trace file.
  Existing table was used.
  
   146 lines in trace file.
  

For each statement executed by the session, the file contains a record of the parse, execute and fetch statistics, an execution plan where necessary and a list of session waits.

Trace Analyzer

In addition to TKPROF, Oracle provide another tool for analyzing SQL trace files called Trace Analyzer. This is available for download from Metalink and can be installed on any version of the database server from Oracle8i upwards.

Trace Analyzer reads a raw SQL Trace file generated by standard SQL Trace or by EVENT 10046 (Level 4, 8 or 12), and generates a comprehensive HTML report with performance related details: time summary, call summary (parse, execute, fetch), identification of top SQL, row source plan, explain plan, CBO statistics, wait events, values of bind variables, I/O summary per schema object, latches, hot blocks, etc.

===

alter session set tracefile_identifier='10046trace';

alter session set timed_statistics = true;

alter session set statistics_level=all;

alter session set max_dump_file_size = unlimited;

alter session set events '10046 trace name context forever,level 12';

==

set autotrace traceonly explain;

==