I believe that the best way to begin the study of Oracle operational data is with a tour of Oracle’s extended SQL trace output. SQL trace output is unsurpassed as an educational and diagnostic aid, because it presents a linear sequential recorded history of what the Oracle kernel does in response to an application’s demands upon the database.

The SQL trace feature has been a part of the Oracle kernel since Version 6, which should be older than any version of Oracle that you are currently running. In 1992, with the release of the kernel Version 7.0.12, Oracle Corporation significantly enhanced the value of SQL trace data by adding information about the durations of non-CPU-consuming instructions that the Oracle kernel executes.

Let’s begin our study with the “Hello, world” of Oracle response time data. Example 5-1 shows one of the simplest SQL*Plus sessions you can run. The session activates the extended SQL trace mechanism for itself. It then queries the string “Hello, world; today is sysdate" from the database and exits.

alter session set max_dump_file_size=unlimited;
alter session set timed_statistics=true;
alter session set events '10046 trace name context forever, level 12';
select 'Hello, world; today is '||sysdate from dual;
exit;

The trace file shown in Example 5-2 reveals the sequence of actions the Oracle kernel performed on behalf of this session. If you’ve learned to view SQL trace data only through the lens of Oracle’s tkprof, then you’re in for a treat. By upgrading your understanding of extended SQL trace data in the raw, you’ll earn the ability to diagnose more classes of performance problem than can be detected with tkprof alone. After becoming fluent with raw trace data, many analysts are surprised by how many deficiencies they find in tkprof.

/u01/oradata/admin/V901/udump/ora_9178.trc
Oracle9i Enterprise Edition Release 9.0.1.0.0 - Production
With the Partitioning option
JServer Release 9.0.1.0.0 - Production
ORACLE_HOME = /u01/oradata/app/9.0.1
System name:    Linux
Node name:  research
Release:    2.4.4-4GB
Version:    #1 Fri May 18 14:11:12 GMT 2001
Machine:    i686
Instance name: V901
Redo thread mounted by this instance: 1
Oracle process number: 9
Unix process pid: 9178, image: oracle@research (TNS V1-V3)
    
*** SESSION ID:(7.6692) 2002-12-03 10:07:40.051
APPNAME mod='SQL*Plus' mh=3669949024 act='' ah=4029777240
= = = = = = = = = = = = = = = = = = = = =
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
EXEC #1:c=0,e=1,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=4,tim=1038931660051673
WAIT #1: nam='SQL*Net message to client' ela= 5 p1=1650815232 p2=1 p3=0
WAIT #1: nam='SQL*Net message from client' ela= 1262 p1=1650815232 p2=1 p3=0
= = = = = = = = = = = = = = = = = = = = =
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
PARSE #1:c=0,e=214,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=4,tim=1038931660054053
BINDS #1:
EXEC #1:c=0,e=124,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=4,tim=1038931660054311
WAIT #1: nam='SQL*Net message to client' ela= 5 p1=1650815232 p2=1 p3=0
FETCH #1:c=0,e=177,p=0,cr=1,cu=2,mis=0,r=1,dep=0,og=4,tim=1038931660054596
WAIT #1: nam='SQL*Net message from client' ela= 499 p1=1650815232 p2=1 p3=0
FETCH #1:c=0,e=2,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=0,tim=1038931660055374
WAIT #1: nam='SQL*Net message to client' ela= 4 p1=1650815232 p2=1 p3=0
WAIT #1: nam='SQL*Net message from client' ela= 1261 p1=1650815232 p2=1 p3=0
STAT #1 id=1 cnt=1 pid=0 pos=0 obj=221 op='TABLE ACCESS FULL DUAL '
XCTEND rlbk=0, rd_only=1

It’s not difficult to step through a trace file this small by hand. At the end of this chapter, I’ll describe each action in overview, to give you a feel for what kind of data you’ll find in the trace file. In the meantime, let’s just hit the highlights.

At the beginning of a trace file is a preamble, which reveals information about the trace file: its name, the release of the Oracle kernel that generated it, and so on. Next is a line that identifies the session being traced (session 7, serial number 6692 in our case), and the time the line was emitted. Notice that the kernel identifies every SQL statement used by the session in a PARSING IN CURSOR section. This PARSING IN CURSOR section shows attributes of the SQL text being used, including the SQL text itself.

The action lines in a trace file are lines beginning with the tokens PARSE, EXEC, and FETCH (and a few others) and the WAIT lines. Each PARSE, EXEC, and FETCH line represents the execution of a single database call. The c and e statistics report on how much total CPU time and total elapsed time, respectively, were consumed by the call. Other statistics on a database call line reveal the number of Oracle blocks obtained via operating system read calls (p) or by two modes of database buffer cache retrieval (cr for consistent-mode reads and cu for current-mode reads), the number of misses on the library cache endured by the call (mis), and the number of rows returned by the call (r). The tim value at the end of each database call line lets you know approximately what time it was when the database call completed.

The WAIT lines are an exciting “new” addition to Oracle trace files, since they have been available only since about 1992. These WAIT lines are part of what distinguish extended SQL trace data from plain old regular SQL trace data. Each WAIT line reports on the duration of a specific sequence of instructions executed within the Oracle kernel process. The ela statistic reports the response time of such a sequence of instructions. The nam attribute identifies the call, and the p1, p2, and p3 values provide useful information about the call in a format that is unique to each different nam value.

The STAT lines don’t convey direct response time information until Release 9.2. However, even prior to 9.2, they’re of immense use in performance analysis, because they contain information about the execution plan that the Oracle query optimizer chose for executing the cursor’s SQL. Finally, the XCTEND line is emitted whenever the application being traced issues a commit or a rollback instruction.

That’s it. Everything you need to account accurately for a session’s response time is in the trace file. One of the best things about the data is that you can see exactly what a session did during the course of its execution. You don’t have to try to extrapolate details from an average, like assessing V$ data forces you to do. All the details are laid out in front of you in chronological order,^[1] and they’re stored in an easy-to-parse ASCII format.

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.

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

= = = = = = = = = = = = = = = = = = = = =
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

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

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

= = = = = = = = = = = = = = = = = = = = =
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

# 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
}

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

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

= = = = = = = = = = = = = = = = = = = = =
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

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)'

XCTEND rlbk=0, rd_only=0

The Oracle kernel emits two categories of time into a trace file:

A session’s total response time is the sum of all time spent within database calls, plus the sum of all time consumed between database calls. To keep from over- or under-accounting for response time in your trace file, you must know the proper category for each line of your trace file.

Time Within a Database Call

The trace file excerpt in Example 5-3 shows actions that consume time within three different database calls. The first database call to complete was a parse call that consumed 306 μs. The kernel helpfully supplied the PARSING IN CURSOR section before emitting the PARSE line so that you and I can tell what got parsed. Next, the kernel emitted an EXEC line, which means that an execute call completed upon the cursor, consuming an additional 146 μs of elapsed time. The next actions to complete are two operating system read calls denoted on the two WAIT lines. The “parent” operation responsible for issuing these read calls is the fetch call whose statistics are reported on the FETCH line.

Example 5-3. This trace file excerpt demonstrates the consumption of time within three database calls

= = = = = = = = = = = = = = = = = = = = =
PARSING IN CURSOR #4 len=132 dep=1 uid=0 oct=3 lid=0 tim=1033064137929238 hv=3111103299 
ad='517ba4d8'
select /*+ index(idl_ub1$ i_idl_ub11) +*/ piece#,length,piece from idl_ub1$ where obj#=:1 
and part=:2 and version=:3 order by piece#
END OF STMT
PARSE #4:c=0,e=306,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,tim=1033064137929139
EXEC #4:c=0,e=146,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,tim=1033064137931262
[1]  
                     WAIT #4 nam='db file sequential read' ela= 13060 p1=1 p2=53903 p3=1
                     [2]  
                     WAIT #4 nam='db file sequential read' ela= 6978 p1=1 p2=4726 p3=1
                     [3]  FETCH #4: c=0,e=21340,p=2,cr=3,cu=0,mis=0,r=0,dep=1,og=4,tim=1033064137953092
STAT #4 id=1 cnt=0 pid=0 pos=0 obj=72 op='TABLE ACCESS BY INDEX ROWID IDL_UB1$ '
STAT #4 id=2 cnt=0 pid=1 pos=1 obj=120 op='INDEX RANGE SCAN '

The lines for the read calls occur in the trace data before the line for the fetch that motivated them because the Oracle kernel emits the statistics for an action upon that action’s completion. The Oracle kernel instructions that produced these trace lines looked something like this:

fetch IDL_UBL$ query
    execute some of the instructions necessary for the IDL_UBL$ fetch
    perform a single-block I/O call upon file 1, block 53903
    emit [1]"WAIT #4: nam='db file sequential read' ela=13060 ..."
    execute some more fetch instructions
    perform a single-block I/O call upon file 1, block 4726
    emit [2]"WAIT #4: nam='db file sequential read' ela=6978 ..."
    execute the remainder of the fetch instructions
    emit [3]"FETCH #4:c=0,e=21340,..."
close the cursor
etc.

The fetch call consumed a total elapsed duration of 21,340 μs. The components of the response time for the fetch call are shown in Table 5-5.

Table 5-5. Components of the fetch call response time

Response time	Component
13,060 μs	db file sequential read
6,978 μs	db file sequential read
0 μs	Total CPU
1,302 μs	Unaccounted for
21,340 μs	Total elapsed time for the fetch

The e statistic for a database call is the elapsed duration of the entire database call. Thus, the value of e includes the duration of all CPU time consumed by the call (reported as the value of c), plus all of the elapsed time consumed by wait events executed in the context of the database call (reported as ela values). Figure 5-1 shows the relationship; formally, we write:

This is the fundamental relationship of Oracle time statistics within a single database call. The relationship is only approximate because of factors including measurement intrusion effect, quantization error, time spent not executing, and un-instrumented Oracle kernel code segments, which I discuss in Chapter 7.

Figure 5-1. The fundamental relationship of Oracle time statistics within a single database call: the total elapsed duration (e) approximately equals the total CPU time for the call (c) plus the sum of the durations of its wait events (Σela)

Time Between Database Calls

The Oracle kernel also emits elapsed durations for wait events that occur between database calls. Examples of wait events that occur between database calls include:

SQL*Net message from client

SQL*Net message to client

single-task message

pipe get

rdbms ipc message

pmon timer

smon timer

The trace file excerpt in Example 5-4 shows wait events that occur between database calls. The application depicted here makes the scalability-inhibiting mistake of parsing too often. As you can see, the excerpt shows two consecutive parse calls (bold) of the exact same SQL text. The WAIT lines (bold and italic) occur between the parse calls both in the sense of where they are located in the trace file and also because the elapsed times of these actions are not tallied into the elapsed time of the second parse call. You can confirm this by noticing that the elapsed duration recorded for the second PARSE line (e=0) is too small to contain the elapsed duration for the SQL*Net message from client event (ela= 3).

Example 5-4. This trace file excerpt demonstrates the consumption of time between two identical parse calls on an Oracle8i system

= = = = = = = = = = = = = = = = = = = = =
PARSING IN CURSOR #9 len=360 dep=0 uid=26 oct=2 lid=26 tim=1716466757 hv=2475520707 
ad='d4c55480'
INSERT INTO STAGING_AREA (TMSP_LAST_UPDT, OBJECT_RESULT, USER_LAST_UPDT, DOC_OBJ_ID, 
TRADE_NAME_ID, LANGUAGE_CODE) values(TO_DATE('11/05/2001 16:39:06', 'MM/DD/YYYY HH24:MI:
SS'), 'if ( exists ( stdphrase ( "PCP_MAV_1" ) ) , langconv ( "Incompatibility With Other 
Materials" ) + ":  " , log_omission ( "Materials to Avoid:  " ) )', 'sa', 222, 54213, 'NO_
LANG') 
END OF STMT
PARSE #9:c=0,e=0,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=4,tim=1716466757
WAIT #9: nam='SQL*Net message to client' ela= 0 p1=1413697536 p2=1 p3=0
WAIT #9: nam='SQL*Net message from client' ela= 3 p1=1413697536 p2=1 p3=0
= = = = = = = = = = = = = = = = = = = = =
PARSING IN CURSOR #9 len=360 dep=0 uid=26 oct=2 lid=26 tim=1716466760 hv=2475520707 
ad='d4c55480'
INSERT INTO STAGING_AREA (TMSP_LAST_UPDT, OBJECT_RESULT, USER_LAST_UPDT, DOC_OBJ_ID, 
TRADE_NAME_ID, LANGUAGE_CODE) values(TO_DATE('11/05/2001 16:39:06', 'MM/DD/YYYY HH24:MI:
SS'), 'if ( exists ( stdphrase ( "PCP_MAV_1" ) ) , langconv ( "Incompatibility With Other 
Materials" ) + ":  " , log_omission ( "Materials to Avoid:  " ) )', 'sa', 222, 54213, 'NO_
LANG') 
END OF STMT
PARSE #9:c=0,e=0,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=4,tim=1716466760
                  

With this knowledge, you can refine your understanding of the relationship among c, e, and ela statistics for an entire trace file. Given what you’ve seen so far, total response time for a session equals the total amount of time spent within database calls, plus the total amount of time spent between database calls. We can state this formally as:

However, there is one final complication: the double-counting imposed by the presence of recursive SQL.

Recursive SQL Double-Counting

Recursive SQL is the SQL associated with any database call that has a dep value that is greater than zero. A dep= n + 1 database call (for n = 0, 1, 2, ...) can be regarded as a child of some dep= n database call. Application sessions routinely produce complicated enough trace data to produce a whole forest of relationships among SQL statements that act as each other’s parents, children, siblings, and so on. Each SQL trace file contains enough information to enable you to determine the exact parent-child relationships among database calls. To account for a session’s response time without double-counting some statistics, you must understand how to determine the recursive relationships among database calls.

Parent-child relationships

The term recursive denotes the Oracle kernel’s execution of database calls within the context of other database calls. Activities that inspire recursive SQL include execution of DDL statements, execution of PL/SQL blocks with DML statements within them, database call actions with triggers on them, and all sorts of routine application DML statements that motivate data dictionary access. Any database call that can execute another database call can motivate recursive SQL.

Example 5-5 is a trace file excerpt that contains evidence of recursive SQL in action. In this excerpt, you can see information about a new cursor labeled #2, which is associated with the following SQL text:

select text from view$ where rowid=:1

This SQL text appears nowhere within the source of the application that was traced. This SQL was motivated by the parse of a query from the DBA_OBJECTS view.

Example 5-5. A trace file excerpt containing evidence of recursive SQL. The three cursor #2 actions at dep=1 are recursive children of the dep=0 parse action upon cursor #1

= = = = = = = = = = = = = = = = = = = = =
[1]  PARSING IN CURSOR #2 len=37 dep=1 uid=0 oct=3 lid=0 tim=1033174180230513 
hv=1966425544 ad='514bb478'
select text from view$ where rowid=:1
END OF STMT
[2]  PARSE #2:c=0,e=107,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,tim=1033174180230481
[3]  BINDS #2:
 bind 0: dty=11 mxl=16(16) mal=00 scl=00 pre=00 oacflg=18 oacfl2=1 size=16 offset=0
   bfp=0a22c34c bln=16 avl=16 flg=05
   value=00000AB8.0000.0001
[4]  EXEC #2:c=0,e=176,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,tim=1033174180230878
[5]  ETCH #2:c=0,e=89,p=0,cr=2,cu=0,mis=0,r=1,dep=1,og=4,tim=1033174180231021
[6]  TAT #2 id=1 cnt=1 pid=0 pos=0 obj=62 op='TABLE ACCESS BY USER ROWID VIEW$ '
= = = = = = = = = = = = = = = = = = = = =
[7]  PARSING IN CURSOR #1 len=85 dep=0 uid=5 oct=3 lid=5 tim=1033174180244680 
hv=1205236555 ad='50cafbec'
select object_id, object_type, owner, object_name from dba_objects where object_id=:v
END OF STMT
[8]  PARSE #1:c=10000,e=15073,p=0,cr=2,cu=0,mis=1,r=0,dep=0,og=0,tim=1033174180244662

The rule for determining the recursive relationships among database calls is simple:

A database call with dep= n + 1 is the recursive child of the first subsequent dep= n database call listed in the SQL trace data stream.

Example 5-6 shows by example why this is true. The Oracle kernel can emit trace data for a database call only after the action has completed. (The kernel cannot compute, for example, the call’s elapsed time until after the call has completed.) Thus we can reconstruct the sequence of instructions that generated the SQL trace data shown in Example 5-5. Specifically, in this example, all the database calls for the VIEW$ query are recursive children of the parse call for the DBA_OBJECTS query. The indentation levels for procedures in the call stack shown in Example 5-6 highlight the recursive parent-child relationship among database calls.

Example 5-6. This sequence of Oracle kernel instructions emits SQL trace data in the order shown in Example 5-5. In this listing, indentation is proportional to call stack depth

parse DBA_OBJECTS query
    # query VIEW$ to obtain the definition of DBA_OBJECTS
    parse VIEW$ query
        # execute the instructions necessary for the VIEW$ parse
        emit [1]"PARSING IN CURSOR #2 ..."
        emit [2]"PARSE #2: ..."
    bind to the VIEW$ cursor
        # execute the instructions necessary for the VIEW$ bind
        emit [3]"BINDS #2: ..."
    execute the VIEW$ cursor
        # execute the instructions necessary for the VIEW$ exec
        emit [4]"EXEC #2: ..."
    fetch from the VIEW$ cursor
        # execute the instructions necessary for the VIEW$ fetch
        emit [5]"FETCH #2: ..."
    close the VIEW$ cursor
        # execute the instructions necessary for the VIEW$ close
        emit [6]"STAT #2: ..."
    # execute the remaining instructions for the DBA_OBJECTS parse
    emit [7]"PARSING IN CURSOR #1 ..."
    emit [8]"PARSE #1: ..."

Figure 5-2 shows a graphical representation of the parent-child relationships among the database calls.

Figure 5-2. The recursive call stack for Example 5-5 expressed graphically

Recursive statistics

In Oracle releases through at least Oracle9i Release 2, a database call’s c, e, p, cr, and cu statistics contain an aggregation of the resources consumed by the database call itself and its entire recursive progeny.

Tip

A database call’s recursive progeny consists of all recursive descendants of the database call, including children, grandchildren, great-grandchildren, and so on.

Figure 5-3 illustrates such a relationship for a fictional set of database calls. Each node (rectangle) in the graph represents a database call (e.g., a PARSE, EXEC, or FETCH). A directed line from some node A to another node B denotes that database call A is a recursive parent (that is, the caller) of database call B. The cr= n listed inside the node is the statistic that the Oracle kernel will emit for the database call. The value of cr _self is the number of consistent-mode reads executed by the database call itself, exclusive of its children’s call counts.

Figure 5-3. Each of a database call’s c, e, p, cr, and cu statistics is an aggregation of consumption on that statistic for that database call’s entire recursive family tree

The kernel emits only the progeny-inclusive statistics, but from these statistics you can derive the progeny-exclusive statistics shown inside the nodes. For example, if the numbers inside the nodes in Figure 5-3 had been omitted, it would be easy to fill them in. Each node’s value is simply the statistic value for that node minus the sum of the statistic values reported for that node’s direct descendants. The value of a node at dep= k is thus the cr value reported for that database call minus the sum of the cr values of its dep= k + 1 descendants. Or, to generalize, we can say that the quantity s of a resource consumed by a database call at dep= k is:

where s _i is the value of a statistic in the set {c, e, p, cr, cu} reported by the Oracle kernel at recursive depth i.

You can use this technique easily enough on real trace data. Again consider the database calls described in Example 5-5. Figure 5-4 illustrates the progeny-inclusive elapsed time value for each database call (denoted e) and the progeny-exclusive elapsed time contribution for each database call (denoted e _self).

Figure 5-4. The recursive call stack for Example 5-5 expressed graphically

Table 5-6 shows all the progeny-exclusive statistics associated with each database call in Example 5-5. The progeny-exclusive contribution to elapsed time for the PARSE #1 database call, for example, is:

Table 5-6. The c, e, p, cr, and cu statistics for a cursor include that cursor’s activity by itself plus the activity of all of its recursive children. You can derive a cursor’s individual activity by using subtraction

Resources consumed by...	c	e	p	cr	cu
PARSE #1, including its recursive progeny	10,000	15,073	0	2	0
PARSE #2, a child	0	107	0	0	0
EXEC #2, a child	0	176	0	0	0
FETCH #2, a child	0	89	0	2	0
PARSE #1 excluding its recursive progeny	10,000	14,701	0	0	0

Now we have enough information to complete the response time accounting formula. When we eliminate the double-counting influences of recursive SQL, we have, finally:

That is, the total response time for a trace file approximately equals the sum of the file’s e values for database calls at recursive depth zero, plus the sum of the file’s ela values for wait events that occur between database calls. A file’s total response time approximately equals the sum of the file’s c values for database calls at depth zero, plus the sum of all the file’s ela values.

In the 1980s, when most of today’s “tuning methods” were invented, Oracle’s SQL trace facility did not yet have the capability to emit wait event timing information—the WAIT lines—into the trace file. The c, e, and tim data were the only trace data elements that we had. Of course, if most of an application’s response time had been spent consuming CPU, then the c and e data told us most of what we needed to know about the performance of our database calls. However, if some of a database call’s response time was not due to CPU consumption, then our analysis became more difficult.

For example, consider the following fetch call statistics obtained from an application running on Oracle 8.1.7.2:

FETCH #1:c=80741,e=151841,p=9628,cr=34304348,cu=10,mis=0,r=0,dep=0,og=4,tim=87762034

This fetch call consumed 1,518.41 seconds of elapsed time, only 807.41 of which was spent on the CPU. Where did the other 711.00 seconds of response time go? Was it latch contention? Enqueue waits? Long disk queues? Excessive paging? We simply cannot know by looking at this FETCH line. Its statistics contain insufficient information to determine where the unaccounted-for 711 seconds of elapsed time went. Certainly, a large p value is a clue that some of the unaccounted-for e time might have been consumed by OS read calls, but there are roughly 200 different wait events that Oracle could have executed during those 711 seconds. From viewing only the fetch statistics shown here, we cannot know how the 711 seconds were consumed.

In 1992 with the release of kernel Version 7.0.12, Oracle Corporation published an elegant solution to this problem. The new mechanism that Oracle provided was simply to instrument several events executed by the Oracle kernel that consume elapsed time but not CPU capacity. The value of the so-called wait data is absolutely extraordinary. It helps to fill in the time gap between e and c. Anjo Kolk and Shari Yamaguchi were the first to document the use of “wait data” in the document that became the landmark YAPP Method [Kolk and Yamaguchi (1999)].

Let’s revisit our previous example, in which we had 711 seconds of unaccounted-for time. Instructing the Oracle kernel to produce the WAIT statistics adds 9,748 more lines of data to our trace file before the fetch call. Executing the Perl program in Example 5-7 upon 9,749 lines of trace data produces the following resource profile:

$ prof-cid waits.1.trc
 Duration     Pct  Oracle kernel event
---------  ------  ----------------------------------------
  807.41s   53.2%  total CPU
  426.26s   28.1%  direct path write
  197.29s   13.0%  db file sequential read
   76.23s    5.0%  unaccounted-for
    8.28s    0.5%  latch free
    2.87s    0.2%  db file scattered read
    0.05s    0.0%  file open
    0.02s    0.0%  buffer busy waits
    0.00s    0.0%  SQL*Net message to client
---------  ------  ----------------------------------------
 1518.41s  100.0%  Total response time

Now we know. Over 53% of the response time for the fetch was consumed on a CPU in user mode. Over 28% was consumed writing (surprise!) to disk. Another 13% was consumed by reading from disk, and roughly another 6% of the response time was consumed in various other wait events.

#!/usr/bin/perl
    
# $Header: /home/cvs/cvm-book1/sqltrace/prof-cid.pl,v 1.4 2003/03/20 23:32:32 cvm Exp $
# Cary Millsap ([email protected])
# Copyright (c) 1999-2003 by Hotsos Enterprises, Ltd. All rights reserved.
    
# Create a resource profile for a single database call.
# Usage: $0 file.trc
    
# Requires input of Oracle extended SQL trace data (level 8 or level 12)
# that has been pre-filtered to contain only a single database call (that
# is, a single PARSE, EXEC, FETCH, UNMAP, or SORT UNMAP with no recursive
# children) and the WAIT lines associated with that db call. Example input
# file content:
#
#   WAIT #2: nam='db file sequential read' ela= 0 p1=2 p2=3240 p3=1 WAIT
#   WAIT #2: nam='db file sequential read' ela= 0 p1=2 p2=3239 p3=1 FETCH
#   FETCH #2:c=213,e=998,p=2039,cr=100550,cu=5,mis=0,r=0,dep=0,og=4,tim=85264276
    
use strict;
use warnings;
my $cid;            # cursor id
my %ela;            # $ela{event} contains sum of ela statistics for event
my $sum_ela = 0;    # sum of all ela times across events
my $r = 0;          # response time for database call
my $action = "(?:PARSE|EXEC|FETCH|UNMAP|SORT UNMAP)";
while (<>) {
    if (/^WAIT #(d+): nam='([^']*)' ela=s*(d+)/i) {
        $ela{$2} += $3;
        $sum_ela += $3;
    }
    elsif (/^$action #(d+):c=(d+),e=(d+)/i) {
        $ela{"total CPU"} += $2;
        $r = $3;
    }
    if (!defined $cid) {
        $cid = $1;
    } else {
        die "can't mix data across cursor ids $cid and $1" if $1 != $cid;
    }
}
$ela{"unaccounted-for"} = $r - ($ela{"total CPU"} + $sum_ela);
printf "%9s  %6s  %-40s
", "Duration", "Pct", "Oracle kernel event";
printf "%8s-  %5s-  %-40s
", "-"x8, "-"x5, "-"x40;
printf "%8.2fs  %5.1f%%  %-40s
", $ela{$_}/100, $ela{$_}/$r*100, $_ for sort { $ela{$b} 
<=> $ela{$a} } keys %ela;
printf "%8s-  %5s-  %-40s
", "-"x8, "-"x5, "-"x40;
printf "%8.2fs  %5.1f%%  %-40s
", $r/100, 100, "Total response time";

Note the row labeled “unaccounted-for” in our resource profile. Consider how it was computed. The total elapsed time—in fact the response time—for the fetch call is simply the value of e for the fetch. The raw trace data account for this response time in two ways:

The “unaccounted-for” duration is thus the leftover amount Δ (delta) expressed in the following formula:

How Oracle response time accounting has evolved since Oracle Version 6 is an interesting story. In Version 6, Oracle’s SQL trace facility printed database call response times (e) and CPU consumptions (c) to the trace file, but that was the only response time data that the Oracle kernel published. The first Oracle response time model was simple. It was “response time equals CPU consumption plus some unidentified other stuff,” or:

e = c + Δ

This model is effective when Δ is small, but it is not reliable for diagnosing many types of response time problems that occur when Δ is large. In the Version 6 days, most analysts were taught to assume that large values of Δ were attributable to time consumed by operating system read calls. This assumption is often incorrect (as was the case in the resource profile shown previously), but it has helped analysts solve many application performance problems. One reason for the model’s success in spite of its over-simplicity is that so many Oracle application problems are caused by fetch calls that access the database buffer cache excessively. These cases create small Δ values for which the e = c + Δ model works just fine.

Oracle kernel developers were among the first to encounter the most serious inadequacies of the model. The range of potential root causes for large Δ values was so large that some important high-end response time problems simply could not be solved without more operational data. Oracle’s extended SQL trace data, introduced to the general market in 1992 with release 7.0.12, is an elegant solution to the problem. Extended SQL trace data include those WAIT lines that tell us how much time the Oracle kernel spends “waiting” for the execution of key events. The new, significantly improved response time model made possible by the new extended SQL trace feature of Oracle release 7.0.12 is the one that we use today:

As it happens, extended SQL trace data provide significantly more diagnostic power than most analysts have ever believed. Of the few analysts who even realize that the gap Δ exists, some deem the existence of the gap a deficiency of extended SQL trace data that renders the data unreliable. On the contrary, as you shall see, there is good information buried in the value of Δ. There are several contributory causes of non-zero Δ values, as I explain in Chapter 7. Understanding these causes helps you exploit the full diagnostic power of Oracle’s extended SQL trace data.

As you try to extract response time information from raw trace data, you’ll need to be able to interpret the time sequence of events using a process we call “walking the clock.” Walking the clock requires a few pieces of knowledge about how the Oracle kernel manages time data:

EXEC #13:c=0,e=0,p=0,cr=0,cu=0,mis=0,r=0,dep=2,og=3,tim=198360834
FETCH #13:c=0,e=0,p=0,cr=3,cu=0,mis=0,r=1,dep=2,og=3,tim=198360834
EXEC #12:c=2,e=4,p=0,cr=27,cu=0,mis=0,r=0,dep=1,og=4,tim=198360837
FETCH #12:c=2,e=10,p=10,cr=19,cu=4,mis=0,r=1,dep=1,og=4,tim=198360847

PARSE #494:c=4,e=5,p=11,cr=88,cu=0,mis=1,r=0,dep=2,og=0,tim=3864619462
WAIT #494: nam='latch free' ela= 2 p1=-2147434220 p2=95 p3=0
WAIT #494: nam='latch free' ela= 2 p1=-2147434220 p2=95 p3=1
EXEC #494:c=0,e=4,p=0,cr=0,cu=0,mis=0,r=0,dep=2,og=4,tim=3864619466
FETCH #494:c=0,e=0,p=0,cr=2,cu=0,mis=0,r=1,dep=2,og=4,tim=3864619466

EXEC #9:c=0,e=0,p=0,cr=0,cu=0,mis=0,r=0,dep=2,og=3,tim=198360795
FETCH #9:c=0,e=0,p=0,cr=3,cu=0,mis=0,r=1,dep=2,og=3,tim=198360795
EXEC #9:c=0,e=0,p=0,cr=0,cu=0,mis=0,r=0,dep=2,og=3,tim=198360795
FETCH #9:c=0,e=0,p=0,cr=3,cu=0,mis=0,r=1,dep=2,og=3,tim=198360795
EXEC #8:c=4,e=19,p=16,cr=162,cu=0,mis=0,r=0,dep=1,og=4,tim=198360796
FETCH #8:c=0,e=5,p=4,cr=4,cu=0,mis=0,r=1,dep=1,og=4,tim=198360801
FETCH #8:c=0,e=0,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=0,tim=198360801
FETCH #7:c=0,e=0,p=0,cr=2,cu=0,mis=0,r=1,dep=1,og=4,tim=198360801
EXEC #8:c=0,e=0,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,tim=198360801

EXEC #1:c=0,e=1863,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,tim=1017039275956134
FETCH #1:c=0,e=2566,p=0,cr=23,cu=0,mis=0,r=1,dep=1,og=4,tim=1017039275958821
FETCH #1:c=0,e=50,p=0,cr=0,cu=0,mis=0,r=1,dep=1,og=4,tim=1017039275959013
FETCH #1:c=0,e=34,p=0,cr=0,cu=0,mis=0,r=1,dep=1,og=4,tim=1017039275959155
FETCH #1:c=0,e=34,p=0,cr=0,cu=0,mis=0,r=1,dep=1,og=4,tim=1017039275959293
FETCH #1:c=0,e=35,p=0,cr=0,cu=0,mis=0,r=1,dep=1,og=4,tim=1017039275959433

PARSING IN CURSOR #1 len=32 dep=0 uid=5 oct=42 lid=5 tim=1033050389206593 
hv=1197935484 ad='50f93654'
alter session set sql_trace=true
END OF STMT
EXEC #1:c=0,e=33,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=4,tim=1033050389204497
               

When you identify a time-consuming wait event in an Oracle extended SQL trace file, your next task will be to determine which application action you might modify to reduce the time consumption. Doing this with extended SQL trace data is straightforward. You should attribute each WAIT # n duration to the first database call for cursor # n that follows the WAIT line in the trace file. I call this method forward attribution. Forward attribution helps you accurately identify which application SQL is responsible for motivating the wait time. Perhaps remarkably, forward attribution works both for events that are executed within database calls and for events that are executed between database calls.

= = = = = = = = = = = = = = = = = = = = =
PARSING IN CURSOR #4 len=132 dep=1 uid=0 oct=3 lid=0 tim=1033064137929238 
hv=3111103299 ad='517ba4d8'
select /*+ index(idl_ub1$ i_idl_ub11) +*/ piece#,length,piece from idl_ub1$ where 
obj#=:1 and part=:2 and version=:3 order by piece#
END OF STMT
PARSE #4:c=0,e=306,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,tim=1033064137929139
EXEC #4:c=0,e=146,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,tim=1033064137931262
[1]WAIT #4: nam='db file sequential read' ela= 13060 p1=1 p2=53903 p3=1
[2]WAIT #4: nam='db file sequential read' ela= 6978 p1=1 p2=4726 p3=1
[3]FETCH #4:c=0,e=21340,p=2,cr=3,cu=0,mis=0,r=0,dep=1,og=4,tim=1033064137953092

= = = = = = = = = = = = = = = = = = = = =
PARSING IN CURSOR #9 len=360 dep=0 uid=26 oct=2 lid=26 tim=1716466757 hv=2475520707 
ad='d4c55480'
INSERT INTO STAGING_AREA (TMSP_LAST_UPDT, OBJECT_RESULT, USER_LAST_UPDT, DOC_OBJ_ID, 
TRADE_NAME_ID, LANGUAGE_CODE) values(TO_DATE('11/05/2001 16:39:06', 'MM/DD/YYYY HH24:
MI:SS'), 'if ( exists ( stdphrase ( "PCP_MAV_1" ) ) , langconv ( "Incompatibility 
With Other Materials" ) + ":  " , log_omission ( "Materials to Avoid: " ) )', 'sa', 
222, 54213, 'NO_LANG') 
END OF STMT
PARSE #9:c=0,e=0,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=4,tim=1716466757
[1]WAIT #9: nam='SQL*Net message to client' ela= 0 p1=1413697536 p2=1 p3=0
[2]WAIT #9: nam='SQL*Net message from client' ela= 3 p1=1413697536 p2=1 p3=0
= = = = = = = = = = = = = = = = = = = = =
PARSING IN CURSOR #9 len=360 dep=0 uid=26 oct=2 lid=26 tim=1716466760 hv=2475520707 
ad='d4c55480'
INSERT INTO STAGING_AREA (TMSP_LAST_UPDT, OBJECT_RESULT, USER_LAST_UPDT, DOC_OBJ_ID, 
TRADE_NAME_ID, LANGUAGE_CODE) values(TO_DATE('11/05/2001 16:39:06', 'MM/DD/YYYY HH24:
MI:SS'), 'if ( exists ( stdphrase ( "PCP_MAV_1" ) ) , langconv ( "Incompatibility 
With Other Materials" ) + ":  " , log_omission ( "Materials to Avoid: " ) )', 'sa', 
222, 54213, 'NO_LANG') 
END OF STMT
[3]PARSE #9:c=0,e=0,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=4,tim=1716466760

At the beginning of this chapter, I promised you a detailed walk-through of the trace file displayed in Example 5-2. Now it is time for the full tour.

Each SQL trace file begins with a preamble that describes information about the file such as the file name, the Oracle release, and various elements describing the system environment and the session being traced. Here is the preamble from Example 5-2:

/u01/oradata/admin/V901/udump/ora_9178.trc
Oracle9i Enterprise Edition Release 9.0.1.0.0 - Production
With the Partitioning option
JServer Release 9.0.1.0.0 - Production
ORACLE_HOME = /u01/oradata/app/9.0.1
System name:    Linux
Node name:  research
Release:    2.4.4-4GB
Version:    #1 Fri May 18 14:11:12 GMT 2001
Machine:    i686
Instance name: V901
Redo thread mounted by this instance: 1
Oracle process number: 9
Unix process pid: 9178, image: oracle@research (TNS V1-V3)

After the preamble, the Oracle kernel emitted information that identifies the time and the session at which the first trace line was emitted:

*** SESSION ID:(7.6692) 2002-12-03 10:07:40.051

The next line reveals information about the module and action names that were set with DBMS_APPLICATION_INFO by the client program, which in my case was SQL*Plus:

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

The first actual action that the kernel recorded in the trace file was the execution of the ALTER SESSION command. The kernel did not emit information about the parse of the ALTER SESSION command, because tracing wasn’t enabled until after the parse had completed. Conveniently, the Oracle kernel emitted a section describing the cursor being acted upon by the execute call, before it emitted the information about the EXEC call itself. The execute call did very little work. The e=1 string indicates that the call consumed only 1 microsecond (1 μs = 0.000 001 seconds) of elapsed time.

= = = = = = = = = = = = = = = = = = = = =
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
EXEC #1:c=0,e=1,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=4,tim=1038931660051673

When the execution of the ALTER SESSION command completed, the Oracle kernel shipped the result back to the client program by writing to a socket controlled by the SQL*Net driver. The elapsed duration of this write call was 5 μs.

WAIT #1: nam='SQL*Net message to client' ela= 5 p1=1650815232 p2=1 p3=0

Upon completing the write call, the Oracle kernel issued a read upon the same socket (note that the p1 values for both the write and the read are the same), and the kernel awaited the next request from its client program. Approximately 1,262 μs after issuing the read call, the read call returned with another request for the kernel.

WAIT #1: nam='SQL*Net message from client' ela= 1262 p1=1650815232 p2=1 p3=0

The request received by the read of the socket was in fact the instruction to parse my “Hello, world” query. Note that before printing the PARSE statistics, the kernel helpfully emitted a section beginning with a sequence of "=" characters and ending with the string END OF STMT that describes the cursor being parsed. The parse call itself consumed 214 μs of elapsed time.

= = = = = = = = = = = = = = = = = = = = =
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
PARSE #1:c=0,e=214,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=4,tim=1038931660054053

The next database call is EXEC, which denotes the execution of the cursor that the kernel had parsed. Immediately preceding the EXEC line is an empty BINDS section, which indicates that although the SQL*Plus program requested a bind operation, there was nothing in the statement for the kernel to bind. Total elapsed time for the execution: 124 μs.

BINDS #1:
EXEC #1:c=0,e=124,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=4,tim=1038931660054311

At the conclusion of the EXEC call, the kernel shipped a result back to the client program (that is, the SQL*Plus program). The write to the socket consumed 5 μs of elapsed time.

WAIT #1: nam='SQL*Net message to client' ela= 5 p1=1650815232 p2=1 p3=0

Immediately following the write to the socket, the kernel’s next action was a fetch operation. The FETCH statistics show an elapsed duration of 177 μs to return one row (r=1), which required three reads of the database buffer cache, one in consistent mode (cr=1) and two in current mode (cu=2).

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

The next database call recorded in the trace file is another fetch, which took place after a 499-μs read from the SQL*Net socket. The fetch returned no rows and consumed only 2 μs of elapsed time.

WAIT #1: nam='SQL*Net message from client' ela= 499 p1=1650815232 p2=1 p3=0
FETCH #1:c=0,e=2,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=0,tim=1038931660055374

Next, the kernel shipped a result back to the client in a socket write operation that consumed 4 μs of elapsed time.

WAIT #1: nam='SQL*Net message to client' ela= 4 p1=1650815232 p2=1 p3=0

After shipping back the fetch result to the client, the kernel sat idle awaiting its next request. It didn’t wait long. Only 1,261 μs after initiating the SQL*Net socket read, the read call was complete.

WAIT #1: nam='SQL*Net message from client' ela= 1261 p1=1650815232 p2=1 p3=0

The instruction that the read call delivered to the kernel resulted in the closing of the “Hello, world” cursor and finally the end of the read-only transaction. Upon cursor close, the kernel helpfully emitted a STAT line that indicates the execution plan that the query optimizer had chosen for executing my query. In this case, my query had motivated a full-table scan of DUAL.

STAT #1 id=1 cnt=1 pid=0 pos=0 obj=221 op='TABLE ACCESS FULL DUAL '
XCTEND rlbk=0, rd_only=1

As you can see, the Oracle kernel did quite a bit of work to fulfill the requirements of even my trivial SQL*Plus session. For performance problems on real-life systems, you can imagine the significant leap in trace file complexity. But even this simple example shows some of the actions that occur within database calls and some of the actions that occur between database calls. These actions are the building blocks that comprise the much larger and more complex trace files that you’ll encounter in real life.