Oracle Trace Event 10046 Notes

 

Oracle Trace Event 10046 Notes

Introduction

This document covers Oracle 10046 event tracing functionality.  This is also termed SQL Trace, and, as the name implies it traces SQL that a user session executes, giving diagnostics information, which is useful for general troubleshooting and performance tuning.  The 10046 trace can be used to tell you exactly what Oracle is doing and how log each of the steps takes.  Topic discussed here are the different trace levels, init.ora parameters required and the different tools available for turning tracing on and off.

 

10046 tracing works with all Oracle Versions 8i,9i,10g.  10g also has new functionality (dbms_monitor), which should be used in preference especially when tracing applications using shared server/connection pooling.

 

Exceptions

This document does not discuss how to read/interpret a raw trace file, how to use relevant oracle tools like tkprof for making trace files more “readable”, or the 10g dbms_monitor functionality.

 

Trace levels

Trace levels can be used to define the type of information in the trace file.  There are a number of different trace levels, which generate different logging information.

Levels of trace

1 – standard SQL trace no, no wait events, or bind variables.

4 – Bind variables only

8 – Wait events only

12 – Bind Variables and Wait Events

 

Init.ora/spfile parameters

There are a few init.ora parameters that need to be set for the sessions you want to trace.  They are as follows:

timed_statistics=true

 

This is only really required for the waits or sql timing information.  Should be enabled by default on most system.  Recommended.

 

max_dump_file_size=unlimited

This allows the trace file to grow as required bty the trace.  If this is not set to unlimited, then you may find your trace file does not cover all activity, and you will see a message similar to “*** DUMP FILE IS LIMITED TO xxxxx BYTES ***” at the end of your trace file..  Recommended.

 

tracefile_identifier = ‘test_trace’

As string which is used to form part of the trace filename when the trace file is created.  This is useful when you are tracing a number of sessions and you want to make it easier to find the tracefile.

 

NOTE: to set these parameters the user needs “alter session” privilege.

 

Enabling Tracing

There are various methods of enabling tracing, from alter session to oradebug, but its worth noting that you can use different methods to switch it on/off.  For example you could user dbms_support to turn it on and oradebug to switch off.  Different tools suite different options.

 

To enable SQL trace for your current session

This is the easiest trace to setup, as it involves  issuing only one alter session commend either:

 

alter session set sql_trace=true; 

If you want higher than a level 1 trace then you must set the 10046 event to trace the session, for example:

 

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

 

Enabling trace for another session that is already connected.

Option 1 – Use SQLPlus oradebug

First you need to get the SID from v$session, connect as sysdba in SQLPlus and you can use oradebug.

oradebug setorapid 16

oradebug event 10046 trace name context forever, level 12;

and to turn it off use:

oradebug setorapid 16

oradebug event 10046 trace name context off;

Option 2 – Use dbms_support package

This may not be installed, but the source is usually in $ORACLE_HOME/rdbms/admin/dbmssupp.sql, which must be run as SYS or a SYSDBA.

 

execute dbms_support.start_trace_in_session(:sid,:serial,waits=>true,binds=>false);

 

Where SID and SERIAL are taken from v$session.

 

And to turn off

 

execute dbms_support.stop_trace_in_session(:sid, :serial);

 

Option 3 Use the trace.sql script

The source code for this script is provided later in this document.  It asks which username you want to trace and traces all sessions connected as that user.  It lists the users currently connected, and the init.ora parameters related to tracing, and prompts for username, and trace level.  Please remember to only supply valid trace levels, and to logon as SYSDBA.

To turn the tacing off, simply run the script again, and specify a level of zero.

 

An example of using the trace.sql script

 

SQL*Plus: Release 9.2.0.5.0 - Production on Mon Feb 7 15:29:51 2005

 

Copyright (c) 1982, 2002, Oracle Corporation.  All rights reserved.

 

Enter password: ********

 

Connected to:

Oracle9i Enterprise Edition Release 9.2.0.3.0 - 64bit Production

With the Partitioning, OLAP and Oracle Data Mining options

JServer Release 9.2.0.3.0 - Production

 

SQL> @trace

 

USERNAME                       CONNECTIONS

------------------------------ -----------

CROMEYR                                  1

F5BACKUP                                 8

IANRILEY                                 1

JOHND                                    1

NETCOOL                                  2

PATROL2000                               1

RUSSELLS2                                4

SIMON                                    8

WEBUSER                                 16

 

NAME                           VALUE                ISMODI

------------------------------ -------------------- ------

timed_statistics               TRUE                 FALSE

max_dump_file_size             UNLIMITED            FALSE

Trace all sessions for one user.  Enter username to trace: netcool

Trace Level 0=none/off (default), 1=sql_trace 4=binds 8=waits 12=binds and waits : 12

 

oradebug setorapid 59

 oradebug event 10046 trace name context forever, level 12;

 

 

ORA-01031: insufficient privileges

ORA-01031: insufficient privileges

 

This is because you are trying to run oradebug to enable the trace, but you are not connected as SYSDBA.  Now try to connect as SYSDBA and re-run the trace.

 

SQL> connect johnd@TEST01 as sysdba

Enter password: ********

Connected.

SQL> @trace

 

USERNAME                       CONNECTIONS

------------------------------ -----------

CROMEYR                                  1

F5BACKUP                                 8

IANRILEY                                 1

NETCOOL                                  2

PATROL2000                               1

RUSSELLS2                                4

SIMON                                    8

WEBUSER                                 16

 

NAME                           VALUE                ISMODI

------------------------------ -------------------- ------

timed_statistics               TRUE                 FALSE

max_dump_file_size             UNLIMITED            FALSE

Trace all sessions for one user.  Enter username to trace: netcool

Trace Level 0=none/off (default), 1=sql_trace 4=binds 8=waits 12=binds and waits : 12

 

The output from the script is the oradebug commends which are executed:

 

oradebug setorapid 16

 oradebug event 10046 trace name context forever, level 12;

 

 

oradebug setorapid 71

 oradebug event 10046 trace name context forever, level 12;

 

 

Unix process pid: 23539, image: oracle@test-sun-01.localnet (TNS V1-V3)

Statement processed.

Unix process pid: 8040, image: oracle@test-sun-01.localnet (TNS V1-V3)

Statement processed.

 

 

When the user has finished the activity you want to trace, then you need to remember to turn it off.  Run the script again, select the same username, but enter zero (“0”) for the trace level.

 

SQL> @trace

 

USERNAME                       CONNECTIONS

------------------------------ -----------

CROMEYR                                  1

F5BACKUP                                 8

IANRILEY                                 1

NETCOOL                                  2

PATROL2000                               1

RUSSELLS2                                4

SIMON                                    8

WEBUSER                                 16

 

NAME                           VALUE                ISMODI

------------------------------ -------------------- ------

timed_statistics               TRUE                 FALSE

max_dump_file_size             UNLIMITED            FALSE

Trace all sessions for one user.  Enter username to trace: netcool

Trace Level 0=none/off (default), 1=sql_trace 4=binds 8=waits 12=binds and waits : 0

 

oradebug setorapid 16

 oradebug event 10046 trace name context off;

 

oradebug setorapid 71

 oradebug event 10046 trace name context off;

 

Unix process pid: 23539, image: oracle@test-sun-01.localnet (TNS V1-V3)

Statement processed.

Unix process pid: 8040, image: oracle@test-sun-01.localnet (TNS V1-V3)

Statement processed.

SQL>

 

Note here that the oradebug commands set the trace level to off.

 

How do I trace an OS process  that I don’t know the SID/SERIAL or username for?

If you know the UNIX process ID, for example, you got it from the “top” command, then you can use oradebug to turn on tracing for that process.  This is assuming it is a shadow server side process, rather than any general oracle process.  Please note that turning on tracing for some of the mandatory oracle background processes, like PMON, can sometimes cause the instance to crash!

 

test-sun-01.localnet[oracle]:TEST01:$ ps -ef

     UID   PID  PPID  C    STIME TTY      TIME CMD

...

  oracle 12449 12441  0 13:41:57 ?        0:00 oracleTEST01 (DESCRIPTION=(LOCAL=YES)(ADDRESS=(PROTOCOL=beq)))

....

SQL> oradebug setospid

ORA-00073: command SETOSPID takes between 1 and 1 argument(s)

SQL> oradebug setospid 12449

Statement processed.

SQL> oradebug event 10046 trace name context forever, level 12;

Statement processed.

 

 

Wait for the session to run a while....then turn off tracing and look for the trace file.

 
 

SQL>  oradebug event 10046 trace name context off;         

Statement processed.

 

Setting init.ora parameters for remote (other) sessions

dbms_system.set_bool_param_in_session (:sid,:serial,’timed_statistics’,true);

 

dbms_system.set_int_param_in_session (:sid,:serial,’max_dump_file_size’,2147483647);

 

Tracing, can also be turned on using dbms_system.set_ev procedure.  This can in fact be used to set any event.  Be careful when using this as if you get the incorrect event number all kinds of weird things can happen including instance crashes!

Here is an example of setting the 10046 trace event using set_ev procedure.

 

sys.dbms_system.set_ev(:sid,:serial,10046,8,’’)

 

And to turn off

sys.dbms_system.set_ev(:sid,:serial,10046,0,’’)

 

 

How can I tell if my session has tracing turned on?

The dbms_system.read_ev procedure can be used for this.  As can be seen below:

declare

event_level number;

begin

dbms_system.read_ev(10046,event_level);

dbms_output.put_line('Event 10046 set at level '|| to_char(event_level));

end;

/

Where can I find my trace files?

Trace files will usually be in the user_dump_destination (udump), but in shared server configurations you will also find trace file in background_dump_destination (bdump).

 

How can I tell if a session already has tracing enabled? i.e. it was enabled by a trigger.

I am unaware of any method to find if an event is set for a remote session.  For the current session use the dbms_system.read_ev as described above.

 

Known issues/problems

Oracle Multi-Threaded Server (MTS) connections to the database are difficult to trace, as the trace information for the session I n question is likely to be a number of trace files.  You need to match the session ID that begins with the line *** in all the trace files, then put then in date/time order.  This effectively leaves you with a virtual trace file.  Its quite tricky, especially if you have a large number of shared server processes.  Where possible try and configure the client to use a dedicated server connection, so that you have one trace file

Connection pooling applications are difficult to trace as you need to trace the whole pool to make sure that you get all the information required from the trace.

 

NOTE : Oracle 10g trace functionality has been improved considerably in this area.  In 10g the dbms_monitor package can be used to trace sessions, and you can check which sessions have tracing enabled by looking at dba_enabled_traces

 

Enabling Tracing with a logon trigger

If you find it difficult to trace a session because it logs in and does stuff before you have time to trace, try implementing a database logon trigger such as the one below:

 

CREATE OR REPLACE TRIGGER enable_10046_trace_trigger

after logon on database

--    10046 TRACELEVELS

--    0  - Turn off tracing.

--    1  - Basic SQL_TRACE.

--    4  - Level 1 plus Bind Variables.

--    8  - Level 1 plus wait events.

--    12 - Level 1 plus Bind Variables and Wait event information.

begin

if user ='JOHND' then

  execute immediate 'alter session set timed_statistics = true';

  execute immediate 'alter session set max_dump_file_size = unlimited';

  execute immediate 'alter session set tracefile_identifier = ''session_trace_energis''';

  execute immediate 'alter session set events ''10046 trace name context forever, level 4'' '; -- bind variables only

end if;

end;

Or if you need to be a little more specific about the users/sessions you want to trace, then you could use something like the following:

CREATE OR REPLACE TRIGGER SYS.enable_10046_trace_trigger
   AFTER LOGON ON DATABASE
--  10046 TRACELEVELS
-- 0  - Turn off tracing.
-- 1  - Basic SQL_TRACE.
-- 4  - Level 1 plus Bind Variables.
-- 8  - Level 1 plus wait events.
-- 12 - Level 1 plus Bind Variables and Wait event information.
DECLARE
   v_exe       v$session.program%TYPE;   -- EXE (Program used to connect) - See v$session
   v_sid       v$session.SID%TYPE;       -- SID for this session
   v_osuser    v$session.osuser%TYPE;
   v_machine   v$session.machine%TYPE;
   v_ok        VARCHAR (10);
-- Flag for everything OK - Can't be boolean coz decode doesn't like booleans
BEGIN
--To check the program need to get the sid for this session.
-- SID
   SELECT SID
     INTO v_sid
     FROM v$mystat
    WHERE ROWNUM < 2;

-- Program executable for this session
   SELECT program
     INTO v_exe
     FROM v$session
    WHERE SID = v_sid;

-- OSUSER Details
   SELECT osuser
     INTO v_osuser
     FROM v$session
    WHERE SID = v_sid;

--Machine Details
   SELECT machine
     INTO v_machine
     FROM v$session
    WHERE SID = v_sid;

   IF USER = 'PHONE_USER' AND v_exe = 'phone.exe' AND v_osuser = 'smithj' and v_machine='WG1/WS00001'
   THEN
      EXECUTE IMMEDIATE 'alter session set timed_statistics = true';
      EXECUTE IMMEDIATE 'alter session set max_dump_file_size = unlimited';
      EXECUTE IMMEDIATE 'alter session set tracefile_identifier = ''session_trace_trigger''';
      EXECUTE IMMEDIATE 'alter session set events ''10046 trace name context forever, level 4'' ';
      DBMS_SESSION.set_identifier ('SQL TRACE ENABLED VIA LOGIN TRIGGER');
   END IF;
END;

Script to determine which events are set in the current session

 

Run this script in SQLPlus as SYSDBA

  

rem what_events.sql

rem List the events that are set this this current session.

rem

declare

event_level number;

counter number;

begin

counter:=0;

for i in 10000..10999 loop

  dbms_system.read_ev(i,event_level);

  if (event_level > 0) then

    dbms_output.put_line('Event '||to_char(i)||' set at level '|| to_char(event_level));

    counter:=counter+1;

  end if;

end loop;

if (counter= 0 ) then

  dbms_output.put_line('No events set for this session');

end if;

end;

/

 

trace.sql – trace all sessions for a given username

 

rem **********************************

rem   Name : trace.sql

rem   Description:

rem     Turn on/off 10046 SQL trace event

rem   for all sessions connected as a particular database user.

rem   Uses the "ORADEBUG" method to set the event, so this script MUST be run via SQL*Plus.

rem   Remember you need timed_statistics=true to get timing info in the trace file.

rem     and max_dump_file_size settijng to a high enough value to stop

rem   the trace file getting truncated.

rem   Run the script again with a level of 0 to turn off tracing.

rem   10046 TRACELEVELS

rem   0  - Turn off tracing.

rem   1  - Basic SQL_TRACE.

rem   4  - Level 1 plus Bind Variables.

rem   8  - Level 1 plus wait events.

rem   12 - Level 1 plus Bind Variables and Wait event information.

rem

rem History:

rem Date    Who   Desc

rem 28/09/2004    JAD   Created

rem

rem **********************************

 

set feedback off

column name format a30

column value format a20

column ismodified format a6

 

select username, count(1) connections from v$session

where username <>'SYS' and username is not null group by username;

 

select name,value,ismodified from v$parameter

where name ='timed_statistics' or name='max_dump_file_size';

 

accept traceuser char default SCOTT PROMPT 'Trace all sessions for one user.  Enter username to trace: '

accept tracelevel NUMBER DEFAULT 0 PROMPT 'Trace Level 0=none/off (default), 1=sql_trace 4=binds 8=waits 12=binds and waits : '

 

set heading off

set serverout off

set verify off

 

 

spool tracetmp.sql

 

SELECT  'oradebug setorapid '||pid ||chr(10)||chr(13)||

            'oradebug event 10046 trace name context '||

              decode (&&tracelevel,0,'off','forever, level '||&&tracelevel)||';'||chr(10)||chr(13)

FROM v$process a, v$session b

WHERE a.addr=b.paddr

AND b.username=upper('&&traceuser');

 

spool off;

 

@tracetmp.sql

 

set heading on

set serverout on

set verify on

set feedback on

rem host notepad tracetmp.sql