Section 5.2. Extended SQL Trace Data Reference

---

5.2 Extended SQL Trace Data Reference

One of the reasons for Oracle Corporation's enormous success in the high-performance database market is the easy accessibility of detailed response time data. Beginning with extended SQL trace files and extending throughout several fixed views, the Oracle kernel provides you all the detail you need in order to know why an application has consumed exactly the response time that it did. The only thing that might be missing is whether you understand how to exploit all that detail. Filling this gap is the mission of my work in this book.

5.2.1 Trace File Element Definitions

Several good sources exist to describe the format of each trace file line [Oracle MetaLink note 39817.1; Kyte (2001) 464-475; Morle (2000) 133-142]. However, none goes far enough to enable full accounting of session response time. Full response time accounting is the goal that you will achieve with the book you are reading now. The following sections describe the meaning of each of the performance- related statistics reported in Oracle's extended SQL trace data.

5.2.1.1 Cursor numbers

Each line emitted to a trace file corresponds to one "action" executed by the Oracle kernel program. Each line uses the string #ID to identify a cursor upon which the kernel performed the action. For example, the following line shows a fetch executed upon cursor #1 :

 FETCH #1:c=0,e=177,p=0,cr=1,cu=2,mis=0,r=1,dep=0,og=4,tim=1038931660054596 

The cursor numbers are relevant only within the scope of the trace file. Furthermore, the Oracle kernel makes a cursor number available for reuse within a trace file when a cursor is closed. Hence, trace file lines containing references to a given cursor number do not all necessarily refer to the same cursor. Fortunately, a given trace file contains a time-ordered record of every cursor creation; each PARSING IN CURSOR token indicates a cursor birth (or rebirth). For example, the following are two PARSING IN CURSOR lines from the trace file in Example 5-2:

 = = = = = = = = = = = = = = = = = = = = = PARSING IN CURSOR #1 len=69 dep=0 uid=5 oct=42 lid=5 tim=1038931660052098  hv=1509700594 ad='50d6d560' alter session set events '10046 trace name context forever, level 12' END OF STMT ... = = = = = = = = = = = = = = = = = = = = = PARSING IN CURSOR #1 len=51 dep=0 uid=5 oct=3 lid=5 tim=1038931660054075  hv=1716247018 ad='50c551f8' select 'Hello, world; today is 'sysdate from dual END OF STMT 

The first PARSING IN CURSOR section indicates that cursor #1 was associated with the ALTER SESSION statement. Later in the same trace file, the Oracle kernel reused ID #1 for the cursor associated with the SELECT statement.

5.2.1.2 Session identification and timestamps

A line beginning with the token *** indicates the system time obtained immediately before the *** line itself was emitted to the trace file. For example:

 *** 2002-12-02 22:25:53.716 *** SESSION ID:(8.6550) 2002-12-02 22:25:53.714 

This information helps the performance analyst by establishing a mapping from Oracle's tim value clock to the system wall clock. The Oracle kernel helpfully emits a *** line into the trace data any time there has been a significant amount of time (tens of seconds) elapsed since the emission of the previously emitted trace line. This feature is helpful because it allows you to resynchronize your understanding of the correct wall clock time over large spans of WAIT lines, which contain approximate elapsed durations ( ela ), but no internal clock ( tim ) values. If you want to emit this line yourself to your trace data, you can do so by calling DBMS_SYSTEM.KSDDDT .

A line containing the token SESSION ID:( m . n ) identifies the trace file lines that follow the SESSION ID line as being associated with the Oracle session with V$SESSION.SID= m and V$SESSION.SERIAL#= n . The session identification lines help you ensure that you are analyzing the correct trace file. In Oracle multithreaded server (MTS) configurations, the lines are especially valuable , because each Oracle kernel process can service requests on behalf of many Oracle sessions. Lines containing a session ID signal which session's work is represented in the raw trace lines that follow.

Did you notice that the timestamp and session identification lines shown here are printed out of time sequence? (The first line marks time 22:25:53.716, and the second one marks a time 0.002 seconds earlier.) This phenomenon is similar to the one described later in Section 5.2.1.4.

5.2.1.3 Application identification

If the application has set its module name or action with the DBMS_APPLICATION_INFO package, then the Oracle kernel will emit an APPNAME line when level-1 SQL tracing is activated. For example:

 APPNAME mod='SQL*Plus' mh=3669949024 act='' ah=4029777240 

The individual values in this line are as follows :

mod

The name of the module set with the SET_MODULE procedure.

mh

A "hash value" that identifies the module.

act

The name of the action set with either SET_MODULE or SET_ACTION .

ah

A "hash value" that identifies the action.

5.2.1.4 Cursor identification

A PARSING IN CURSOR section contains information about a cursor. For example:

 = = = = = = = = = = = = = = = = = = = = = PARSING IN CURSOR #135 len=358 dep=0 uid=173 oct=3 lid=173 tim=3675359494 hv=72759792  ad='bb13f788' select vendor_number, vendor_id, vendor_name, vendor_type_lookup_code, type_1099,  employee_id, num_1099, vat_registration_num, awt_group_id, allow_awt_flag, hold_all_ payments_flag, num_active_pay_sites, total_prepays, available_prepays from po_ vendors_ap_v where (VENDOR_NUMBER LIKE :1) AND ( active_flag = 'Y' and enabled_flag =  'Y' ) order by vendor_number END OF STMT 

The PARSING IN CURSOR line itself contains information about cursor #ID . Text between the PARSING IN CURSOR line and the corresponding END OF STMT line is the cursor's SQL text. The Oracle kernel usually emits this section at the conclusion of a parse call, just before the kernel emits a cursor's PARSE line. However, if tracing was not active when the parse call completed, the kernel will usually emit near the beginning of the trace data (just before the completion of the first traced database call, but potentially after one or more WAIT lines), as if the Oracle kernel were executing the following pseudocode:

 # Upon completion of Oracle kernel activity required by a db call... if SQL tracing level >= 1 {     if db call is PARSE or pic[cursor_id] is unset {         emit "PARSING IN CURSOR" section         pic[cursor_id] = 1     }     emit statistics for the db call } 

Thus, Oracle reveals information in the trace file about a cursor even if tracing was not active at the conclusion of the cursor's parse call.

Each PARSING IN CURSOR line contains the following information about a cursor:

len

The length of the SQL text.

dep

The recursive depth of the cursor. A dep= n + 1 cursor is a child of some dep= n cursor ( n = 0, 1, 2, ...). Several actions motivate recursive SQL, including database calls that require information from the Oracle database dictionary, statements that fire triggers, and PL/SQL blocks that contain SQL statements. See Section 5.3.3 later in this chapter for further discussion of the "recursive" SQL relationship.

uid

The schema user ID of the user who parsed the statement.

oct

The Oracle command type ID [Oracle OCI (1999)].

lid

The privilege user ID. For example, if FRED calls a package owned by JOE , then a SQL statement executed within the package will have a uid that refers to FRED , and an lid that refers to JOE .

tim

If a tim value is 0, then TIMED_STATISTICS for the session was false when the database call time would have been calculated. You can thus confirm whether TIMED_STATISTICS was true by observing tim values. In our field work, my colleagues and I have found that specific non-zero tim values associated with PARSING IN CURSOR sections are largely irrelevant.

In Oracle9 i , tim is a value expressed in microseconds (1 m s = 0.000 001 seconds). On some systems (such as our Linux research servers), tim field values are unadulterated gettimeofday values. On other systems (like our Microsoft Windows research machines), the origin of tim field values can be much more mysterious . In releases prior to Oracle9 i , tim is a V$TIMER.HSECS value expressed in centiseconds (1 cs = 0.01 seconds).

hv

The statement ID of the SQL statement. The hv may look unique, but it is not. Occasionally (albeit rarely), distinct SQL texts share the same hv value.

ad

The library cache address of the cursor, as is shown in V$SQL .

5.2.1.5 Database calls

A database call is a subroutine in the Oracle kernel. If level-1 SQL tracing is active when a database call completes, then the Oracle kernel emits a database call line upon completion of that database call. PARSE , EXEC , and FETCH calls are the most common types of database call. For example:

 PARSE #54:c=20000,e=11526,p=0,cr=2,cu=0,mis=1,r=0,dep=1,og=0,tim=1017039304725071 EXEC #1:c=10000,e=12137,p=0,cr=22,cu=0,mis=0,r=1,dep=0,og=4,tim=1017039275981174 FETCH #3:c=10000,e=306,p=0,cr=3,cu=0,mis=0,r=1,dep=2,og=4,tim=1017039275973158 

Other database call types (for example, ERROR , UNMAP , and SORT UNMAP ) are explained in Oracle MetaLink note 39817.1. Each database call line contains the following statistics:

c

The total CPU time consumed by the Oracle process during the call. Oracle9 i expresses c in microseconds (1 m s = 0.000 001 seconds). Prior kernel versions express c in centiseconds (1 cs = 0.01 seconds).

e

The amount of wall time that elapsed during the call. Oracle9 i expresses e in microseconds (1 m s = 0.000 001 seconds). Prior kernel versions express e in centiseconds (1 cs = 0.01 seconds).

p

The number of Oracle database blocks obtained by the call via operating system disk read calls. The name p is supposed to be mnemonic for the word "physical," but note that not every so-called Oracle "physical" read visits a physical disk device. Many such reads are serviced from various caches between the Oracle kernel and the physical disk.

cr

The number of Oracle database blocks obtained by the call in consistent mode from the Oracle database buffer cache. A read executed in consistent mode can motivate additional consistent mode reads from undo blocks, which are stored in rollback segments.

cu

The number of Oracle database blocks obtained by the call in current mode from the Oracle database buffer cache. A read executed in current mode is simply a read of the current content of a block.

mis

The number of library cache misses encountered during the call. Each library cache miss motivates a hard parse operation.

r

The number of rows returned by the call.

dep

The recursive depth of the cursor. A dep= n + 1 cursor is a child of some dep= n cursor ( n = 0, 1, 2, ...). See Section 5.2.1.4 earlier in this chapter for more details.

og

The optimizer goal in effect during the call. Oracle uses the values shown in Table 5-1.

tim

See Section 5.2.1.4 listed previously for details.

Table 5-1. Oracle query optimizer goal by og value (source: Oracle MetaLink note 39817.1)

og value	Oracle query optimizer goal
1	ALL_ROWS
2	FIRST_ROWS
3	RULE
4	CHOOSE

Note that the Oracle kernel does not emit a database call line into the trace file until the action has completed . Thus, an extraordinarily long database operation might cause the Oracle kernel to work for several hours without emitting anything to the trace file. Poorly optimized SQL can produce EXEC calls (for updates or deletes) or FETCH calls (for selects) that consume CPU capacity for several days at a time.

5.2.1.6 Wait events

An Oracle wait event is a sequence of Oracle kernel instructions that is wrapped with special timing instrumentation. If level-8 or level-12 SQL tracing is active when a wait event completes, then the Oracle kernel emits a WAIT line upon completion of that event. For example:

 WAIT #1: nam='SQL*Net message to client' ela= 40 p1=1650815232 p2=1 p3=0 WAIT #1: nam='SQL*Net message from client' ela= 1709 p1=1650815232 p2=1 p3=0 WAIT #34: nam='db file sequential read' ela= 14118 p1=52 p2=2755 p3=1 WAIT #44: nam='latch free' ela= 1327989 p1=-1721538020 p2=87 p3=13 

Each WAIT line contains the following statistics about work executed during the event:

nam

The name assigned by an Oracle kernel developer to reveal which part of the Oracle kernel code is responsible for this portion of your response time.

ela

The elapsed duration of the named event's execution. Oracle9 i expresses ela in microseconds (1 m s = 0.000 001 seconds). Prior kernel versions express ela in centiseconds (1 cs = 0.01 seconds).

p1, p2, p3

The meanings of these parameters vary by nam . A complete catalog of parameter descriptions for each event type is available by running the following SQL:

 select name, parameter1, parameter2, parameter3 from v$event_name order by name 

Note that WAIT lines appear in the trace data before the database call that motivated them. This occurs because the Oracle kernel emits lines into the trace file as events complete. Thus, if a fetch call requires three OS read calls, the three waits for the read calls will appear in the trace file before Oracle emits the information about the completed fetch call.

The WAIT lines in SQL trace data are one interface to the new Oracle feature introduced in 1992 that has been so important in revolutionizing the ease with which we can diagnose and repair performance problems today.

5.2.1.7 Bind variables

If level-4 or level-12 SQL tracing is active when the Oracle kernel binds values to placeholders in an application's SQL text, the kernel emits a BINDS section. For example:

 = = = = = = = = = = = = = = = = = = = = = PARSING IN CURSOR #1 len=105 dep=0 uid=56 oct=47 lid=56 tim=1017039275982462  hv=2108922784 ad='98becef8' declare dummy boolean;begin fnd_profile.get_specific(:name, :userid, :respid,  : applid, :val, dummy);end; END OF STMT  ...   Several lines have been omitted for clarity   ... BINDS #1:  bind 0: dty=1 mxl=2000(1998) mal=00 scl=00 pre=00 oacflg=01 oacfl2=0 size=2000  offset=0    bfp=025a74a0 bln=2000 avl=19 flg=05    value="MFG_ORGANIZATION_ID"  bind 1: dty=2 mxl=22(22) mal=00 scl=00 pre=00 oacflg=01 oacfl2=0 size=72 offset=0    bfp=025a744c bln=22 avl=04 flg=05    value=118194  bind 2: dty=2 mxl=22(22) mal=00 scl=00 pre=00 oacflg=01 oacfl2=0 size=0 offset=24    bfp=025a7464 bln=22 avl=05 flg=01    value=1003677  bind 3: dty=2 mxl=22(22) mal=00 scl=00 pre=00 oacflg=01 oacfl2=0 size=0 offset=48    bfp=025a747c bln=22 avl=03 flg=01    value=140  bind 4: dty=1 mxl=2000(1998) mal=00 scl=00 pre=00 oacflg=01 oacfl2=0 size=2000 offset=0    bfp=025ba490 bln=2000 avl=00 flg=05 

A BINDS section contains one or more bind subsections, one for each variable being bound. The number following the word bind indicates the ordinal position, beginning at 0, of the bind variable within the SQL text. Each bind section contains several statistics about the bind. The most important ones for use in performance analysis are:

dty

The external data type of the value supplied by the application [Oracle OCI (1999)]. Oracle publishes two sets of data types: internal and external . The internal data type definitions reveal how the Oracle kernel stores its data on the host operating system. The external data type definitions reveal how the Oracle kernel interfaces with application SQL.

The external data type of a bind value is important. Occasionally we find SQL statements for which the Oracle query optimizer flatly refuses to use an obviously helpful index. Sometimes such a case is caused by a mismatch between the column type and the value type, which can force an implicit type coercion function to be executed upon the column, which prevents the optimizer from choosing that index.

avl

The length, in bytes, of the bind value.

value

The value that is bound into the statement execution. The Oracle kernel sometimes truncates values that it emits into the trace file. You can determine exactly when this has happened by simple inspection; truncation has occurred any time the avl value is larger than the length of the value field.

5.2.1.8 Row source operations

If level-1 SQL tracing is active when a cursor is closed, then the Oracle kernel emits one STAT line for each row source operation in the cursor's execution plan. For example:

 STAT #1 id=1 cnt=55 pid=0 pos=1 obj=0 op='SORT UNIQUE (cr=39741 r=133 w=0  time=1643800 us)' STAT #1 id=2 cnt=23395 pid=1 pos=1 obj=0 op='VIEW  (cr=39741 r=133 w=0 time=1614067  us)' STAT #1 id=3 cnt=23395 pid=2 pos=1 obj=0 op='SORT UNIQUE (cr=39741 r=133 w=0  time=1600554 us)' STAT #1 id=4 cnt=23395 pid=3 pos=1 obj=0 op='UNION-ALL  (cr=39741 r=133 w=0  time=1385984 us)' 

If a trace file does not contain the STAT lines you were hoping to find, it is because tracing was deactivated before the cursor closed. The STAT lines will of course be absent any time you trace a well-designed persistent service that neither terminates nor closes its cursors more than once every several weeks.

Each STAT line contains the following statistics about the cursor's execution plan:

id

The unique ID of the row source operation within the STAT line set.

cnt

Number of rows returned by this row source operation.

pid

ID of this operation's parent operation.

pos

The best we can determine, an arbitrary number. It might seem that this value might define the "position" of a row source operation within a set of operations belonging to a single parent, but it appears that sibling row source operations are ordered in increasing ID order.

obj

Object ID of the row source operation, if the operation executes upon a "base object." A row source operation such as NESTED LOOPS , which itself does not access a base object, will report obj=0 . (The NESTED LOOPS operation's children do access base objects, but the NESTED LOOPS row source operation itself does not.)

op

The name of the row source operation. Beginning with Oracle Release 9.2.0.2.0, the kernel emits additional information into the STAT lines [Rivenes (2003)]. The new information reveals several useful statistics for each row source operation, including:

cr

Number of consistent-mode reads.

r

Number of Oracle blocks read with OS read calls.

w

Number of Oracle blocks written with OS read calls.

time

The elapsed duration, expressed in microseconds ( us ).

The statistics for a parent row source operation include a roll-up of the statistics for its children.

Oracle's tkprof utility produces erroneous results in more cases than you might have imagined, especially in STAT line processing. Oracle's tkprof has an exceptional reputation for reliability, but I'm convinced that one reason the tool maintains this reputation is that people simply never bother to double-check its output. To confirm or refute whether tkprof is giving correct output is impossible to do without studying raw trace data. Most people are reluctant to do this. I hope this book helps encourage you to make the effort.

5.2.1.9 Transaction end markers

If level-1 SQL tracing is active when a commit or rollback occurs, then the Oracle kernel emits an XCTEND line upon completion of the call. For example:

 XCTEND rlbk=0, rd_only=0 

Each XCTEND line contains the following statistics about work executed during the commit or rollback:

rlbk

True ( 1 ) if and only if the transaction was rolled back.

rd_only

True ( 1 ) if and only if the transaction changed no data in the database.

Notice that the XCTEND marker has no cursor ID reference. This is because there is a one-to-many relationship between a transaction and the cursors that participate in the transaction.

5.2.1.10 Reference summary

Table 5-2 summarizes the raw trace data statistics that will be most interesting to you during your performance analysis work.

Table 5-2. Descriptions of selected elements from extended SQL trace data

Field	Occurs in . . .			Description
	Cursor ID	Database call	Wait event
c				Total CPU time consumed by the database call. Reported in microseconds on Oracle9 i , centiseconds on prior releases.
cr				Number of Oracle blocks obtained from the database buffer cache in consistent mode.
cu				Number of Oracle blocks obtained from the database buffer cache in current mode.
dep				The recursive depth of the cursor.
e				Elapsed duration consumed by the database call. Reported in microseconds on Oracle9 i , centiseconds on prior releases.
ela				Elapsed duration consumed by the wait event. Reported in microseconds on Oracle9 i , centiseconds on prior releases.
hv				Statement ID.
mis				Number of misses upon the library cache.
nam				Name of the wait event.
p				Number of Oracle blocks obtained via operating system read calls.
p1 , p2 , p3				Information about the wait event; varies by value of nam .
tim				The internal Oracle time at which an event completed.

5.2.2 Oracle Time Units

Oracle9 i kernels report SQL trace timing statistics in microseconds (1 m s = 0.000 001 seconds). Oracle release 6, 7, and 8 kernels report SQL trace timing statistics in centiseconds (1 cs = 0.01 seconds). Table 5-3 summarizes the unit of measure that the Oracle kernel uses for each type of time statistics in extended SQL trace data.

Table 5-3. Trace file time statistic units by Oracle version

Oracle version	c	e	ela	tim
9	m s	m s	m s	m s
8	cs	cs	cs	cs
7	cs	cs	cs	cs
6	cs	cs	N/A	cs

Table 5-4 explains the meaning of the time units that you will use as an Oracle performance analyst.

Table 5-4. Time units commonly used by computer performance analysts

Unit name	Abbreviation	Duration in seconds (s)
Second	1 s	1 s	1E-0 s	1. s
Centisecond	1 cs	1/100 s	1E-2 s	0.01 s
Millisecond	1 ms	1/1,000 s	1E-3 s	0.001 s
Microsecond	1 m s	1/1,000,000 s	1E-6 s	0.000 001 s

---

Top