Section 6.2. Activating Extended SQL Trace | Optimizing Oracle Performance

6.2 Activating Extended SQL Trace

The first secret to the syntax of Oracle's extended SQL trace mechanism lies in the file $ORACLE_HOME/rdbms/mesg/oraus.msg . It's the error message file for the Oracle kernel. If you search for the first occurrence of the string "10000" that appears at the beginning of a line in the file (e.g., by issuing the command /^10000 in vi ), you'll find yourself in the midst of the following file content:

 / Pseudo-error debugging events: /    Error codes 10000 .. 10999 are reserved for debug event codes that are /    not really errors. / // NLS_DO_NOT_TRANSLATE [10000,10999] - Tag to indicate messages should // not be translated.  10000  , 00000, "controlfile debug event, name 'control_file'" // *Cause: // *Action:

Oracle kernel developers have created debugging events with codes in the range 10000 through 10999 to assist them in testing and debugging the kernel.

Oracle Corporation does not distribute oraus.msg on Microsoft Windows ports. To view the file, you'll need to find it on a non-Windows distribution.

The one-line descriptions of these debug event codes are quite educational. In them you can discover the existence of debug events that enable Oracle kernel developers to simulate events like memory errors or various types of file corruption, change the behavior of components like the query optimizer, or trace internal kernel operations like latch acquisitions. Debugging events that can assist you in your role as performance analyst include:

 10032, 00000, "sort statistics (SOR*)" 10033, 00000, "sort run information (SRD*/SRS*)" 10053, 00000, "CBO Enable optimizer trace" 10079, 00000, "trace data sent/received via SQL*Net" 10104, 00000, "dump hash join statistics to trace file" 10241, 00000, "remote SQL execution tracing/validation"

Amid the list of over 400 debugging events is the one to activate extended SQL trace:

 10046, 00000, "enable SQL statement timing"

This inconspicuous little capability, buried about 16,000 lines deep within an undocumented file, is one of the heroes of this book. It is the source of your ability to obtain a full account of how an Oracle application program consumes your users' response times.

Prior to Oracle release 10, all pseudo-error debugging events are officially unsupported, unless you're acting specifically under the direction of Oracle Support. Later in this chapter, I describe the DBMS_SUPPORT.START_TRACE_IN_SESSION package, which is a fully supported way to use event 10046.

6.2.1 Tracing Your Own Source Code

Tracing a session is a very simple process when you have read-write access to the source code of the session to be traced. Activating and deactivating extended SQL trace requires only that the Oracle kernel execute the SQL statements shown in Example 6-1. The first line ensures that TIMED_STATISTICS is active for the session, regardless of the instance-wide value of TIMED_STATSITICS . Without activating Oracle timed statistics, all of your e , c , ela , and tim values will be zero and therefore of no value in your response time analysis.

Example 6-1. This code activates and deactivates extended SQL trace for a session

 alter session set timed_statistics=true alter session set max_dump_file_size=unlimited alter session set tracefile_identifier='POX20031031a' alter session set events '10046 trace name context forever, level 8' /* code to be traced goes here */ alter session set events '10046 trace name context off'

The second line ensures that the Oracle kernel will not truncate your trace file against your wishes. The MAX_DUMP_FILE_SIZE parameter permits the Oracle database administrator to restrict the size of trace files generated by Oracle sessions. The feature is designed to prevent performance analysts from accidentally filling the filesystem(s) to which USER_DUMP_DEST and BACKGROUND_DUMP_DEST refer. However, forgetting to relax this file size restriction can be an expensive and frustrating mistake for a performance improvement project. ^[1] The last thing you want to see after three weeks of careful preparation to trace a long-running monthly batch job is a shorter-than-expected trace file with following line at its tail:

^[1] The default setting is UNLIMITED on Oracle release 9.

 *** DUMP FILE SIZE IS LIMITED TO 1048576 BYTES ***

With the ability to relax the maximum dump file size limit comes the responsibility of not filling the filesystem to which your trace file will be written. If the Oracle kernel is writing to a filesystem that throws a "filesystem full" error, the result will be a truncated trace file. You'll end up with something that looks like this at the tail of the file:

 WAIT #42: nam='db file sequential read' ela= 17101 p1=10 p2=2213 p3=1 WAIT #42: nam='db file se

Note that some Oracle ports (notably Oracle8 i for Microsoft Windows) do not support the UNLIMITED keyword value. For these ports, simply set MAX_DUMP_FILE_SIZE to a large integer. On the 32-bit implementations of Oracle in our laboratory, the maximum value you can specify is 2 ³¹ - 1 = 2,147,483,647. Note also that the parameters TIMED_STATISTICS and MAX_DUMP_FILE_SIZE have been session-modifiable since Oracle release 7.3. If you are using a release of Oracle prior to 7.3, the only way to set either of these parameters for a given session is to set them instance-wide.

It is possible that USER_DUMP_DEST may someday also become a session-settable parameter as well. This feature would be useful because it would allow you to redirect specific trace files to specific locations, based on motives of space economy, performance, or just ease of access. Oracle's release 9.2 documentation states that USER_DUMP_DEST is a session-settable parameter [Oracle (2002)]. However, it is not true at least on Oracle release 9.2.0.1.0 for Microsoft Windows.

The third line in Example 6-1 causes the resulting trace file to contain the string "POX20031031a" in its file name (this feature is available in 8.1.7). Inserting some kind of unique ID into the trace file name will make it easy later on to identify which file contains the information I've collected. Any unique ID will do. In this example, I've chosen a name that might make sense for run "a" of the "POX" report executed on 31 October 2003.

The fourth line in Example 6-1 activates the extended SQL trace mechanism itself, causing the Oracle kernel to write statistics into the kernel process' trace file. Note that in Example 6-1, I activated the extended SQL trace mechanism by setting the tracing level to 8. I deactivated SQL trace by specifying the OFF keyword, which set the tracing level to 0. The tracing levels are summarized in Table 6-1.

Table 6-1. Oracle's "pseudo-error debugging event" number 10046 tracing levels

Level	Implied bitmap	Function
	`0000`	Emit no statistics.
1	`0001`	Emit `***` , `APPNAME` , `PARSING IN CURSOR` , `PARSE ERROR` , `EXEC` , `FETCH` , `UNMAP` , `SORT` `UNMAP` , `ERROR` , `STAT` , and `XCTEND` lines.
2	`0011`	Apparently identical to level 1.
4	`0101`	Emit `BINDS` sections in addition to level-1 lines.
8	`1001`	Emit `WAIT` lines in addition to level-1 lines.
12	`1101`	Emit level-1, level-4, and level-8 lines.

Although you can deactivate tracing explicitly, it is often best not to. A session's tracing attribute dies with the session, so when a user disconnects from Oracle, the trace file closes gracefully. Allowing the disconnection to end the tracing is the best way to ensure that all of the session's STAT lines are emitted to the trace file, for the reasons described in Chapter 5. Of course, if you are tracing an application that uses a persistent Oracle connection, like processes configured as "linked internal" within the Oracle Applications Concurrent Manager, then you must deactivate tracing explicitly. Fortunately, it is easy enough to reproduce missing STAT data with Oracle's EXPLAIN PLAN facility or the new V$SQL_PLAN fixed view (available in release 9).

6.2.2 Tracing Someone Else's Source Code

You can trace any Oracle session you want, even background sessions. Do you suspect that writes to database files are taking too long? Trace DBWR and find out. Do you think that writing to the online redo log files is too slow? Trace LGWR and find out. Did you ever wonder what it costs for the Oracle kernel to automatically coalesce tablespaces for you? Trace SMON and find out.

Do not trace PMON with extended SQL trace. Tracing PMON can cause instance failure (Oracle bug 2329767, reputedly fixed in Oracle release 10). The good news is that there are very few legitimate reasons why you might actually want to trace PMON.

6.2.2.1 Triggering a session to activate its own trace

The plot thickens a little bit when you need to trace a program to which you don't have write-access to the source code. It's often not much more difficult; you just have to use a little bit of imagination . For example, you can use the AFTER LOGON trigger function introduced in release 8.1 to activate level-8 tracing for any session with a particular attribute. The code in Example 6-2 creates a trigger that activates tracing for any session whose Oracle username has a suffix of _test .

Example 6-2. This code creates a trigger that activates tracing for any session whose Oracle username has the suffix _test

 create or replace trigger trace_test_user after logon on database begin   if user like '%\_test' escape '\' then     execute immediate 'alter session set timed_statistics=true';     execute immediate 'alter session set max_dump_file_size=unlimited';     execute immediate    end if; end; /

The implementation particulars of a trigger like this will vary widely from one application to the next . The important thing is that you understand your application well enough that you can think innovatively about how you might activate extended SQL tracing for the session of your choice.

6.2.2.2 Activating trace from a third-party session

Oracle provides several packaged procedures that allow you to manipulate attributes of a session to which you are not connected. Your first task is to identify the session that you want to trace. Many database administrators are already familiar with means for finding the SID and SERIAL# (from the V$SESSION fixed view) of a specific process from applications that they manage. Example 6-3 shows one example of a SQL statement that does this.

Example 6-3. This SQL statement lists attributes of a user session for which the session username is supplied in the Oracle placeholder variable : uname

 select   s.sid db_sid,   s.serial# db_serial,   p.spid os_pid,   to_char(s.logon_time, 'yyyy/mm/dd hh24:mi:ss') db_login_time,   nvl(s.username, 'SYS') db_user,   s.osuser os_user,   s.machine os_machine,   nvl(decode(     instr(s.terminal, chr(0)), 0,     s.terminal, substr(s.terminal, 1, instr(s.terminal, chr(0))-1)   ), 'none') os_terminal,   s.program os_program from   v$session s,   v$process p where   s.paddr = p.addr    and s.username like upper(:uname)

An application can greatly simplify the task of session identification by revealing some identifying information about the session to the end user. Imagine an application form that can list the values of V$SESSION.SID and V$SESSION.SERIAL# right on the user's form. Such a feature greatly assists the end-user in describing to the performance analyst how to identify a session that needs targeted performance analysis.

The package called DBMS_APPLICATION_INFO provides three useful procedures ” SET_MODULE , SET_ACTION , and SET_CLIENT_INFO ”for helping to identify targeted Oracle sessions. Each procedure inserts a value into the V$SESSION fixed view for the session executing the procedure. The attributes MODULE , ACTION , and CLIENT_INFO create a convenient hierarchy for identifying user actions. For example, Nikolas Alexander's application form might make the following settings:

 dbms_application_info.set_module('Accounts Payable') dbms_application_info.set_action('Pay Invoices') dbms_application_info.set_client_info('Nikolas Alexander')

When an application "earmarks" itself by calling DBMS_APPLICATION_INFO procedures, it becomes trivial to target the Oracle session executed by an individual client, all Oracle sessions executing a particular action, or even all Oracle sessions participating in the actions of a given module. For example, the following query returns the session identification information for the set of all Oracle sessions running the Pay Invoices action of the Accounts Payable module:

 select session, serial# from v$session where v$session.module = 'Accounts Payable'   and v$session.action = 'Pay Invoices'

One problem with using the MODULE , ACTION , and CLIENT_INFO attributes through Oracle release 9 is that setting any of the attributes requires the overhead of a database call (which includes not just additional workload upon the Oracle kernel, but extra network capacity consumption as well). For small user actions, the overhead becomes a significant proportion of the action's total workload.

Once you have obtained the SID and SERIAL# identification for the session you want to trace, activating trace is straightforward. Example 6-4 shows how to use the DBMS_SYSTEM package to activate TIMED_STATISTICS for a specific session and set its MAX_DUMP_FILE_SIZE to the desired value. Even if you don't have access to DBMS_SYSTEM , you can manipulate these Oracle system parameters system-wide without incurring outage with ALTER SYSTEM commands in any Oracle release since 7.3.

Example 6-4. Manipulating session parameters for a session identified by :sid and :serial

 sys.dbms_system.set_bool_param_in_session(   :sid, :serial,   'timed_statistics', true ) sys.dbms_system.set_int_param_in_session(   :sid, :serial,   'max_dump_file_size', 2147483647 )

There are several ways to activate extended SQL tracing for a given session. Two such ways are shown in Example 6-5 and Example 6-6. Oracle encourages you to use the DBMS_SUPPORT package instead of DBMS_SYSTEM if you have a choice (Oracle MetaLink note 62294.1). However, Oracle does not ship dbmssupp.sql and prvtsupp.plb with some software distributions. If you cannot find DBMS_SUPPORT on your system, don't despair. My colleagues and I have used DBMS_SYSTEM.SET_EV in hundreds of performance improvement projects without negative incident. Friends in Oracle Support have informed me that the DBMS_SUPPORT.START_TRACE_IN_SESSION procedure is implemented as a call to SET_EV anyway.

The safety of using START_TRACE_IN_SESSION is that you're not susceptible to typographical errors in specifying event 10046 . Accidentally typing the wrong event number could obviously lead to catastrophe.

Example 6-5. Activating extended SQL trace at level 8 with START_TRACE_IN_SESSION for a session identified by :sid and :serial

 sys.dbms_support.start_trace_in_session(   :sid, :serial,   waits=>true, binds=>false ) /* code to be traced executes during this time window */ sys.dbms_support.stop_trace_in_session(   :sid, :serial )

Do not use DBMS_SYSTEM.START_SQL_TRACE_IN_SESSION to activate extended SQL trace, because this procedure can activate SQL tracing only at level 1. You cannot activate extended SQL tracing with START_SQL_TRACE_IN_SESSION .

Example 6-6. Activating extended SQL trace at level 8 with SET_EV for a session identified by :sid and :serial

 sys.dbms_system.set_ev(:sid, :serial, 10046, 8, '') /* code to be traced executes during this time window */ sys.dbms_system.set_ev(:sid, :serial, 10046, 0, '')

Top