Section 5.1. Trace File Walk-Through | Optimizing Oracle Performance

5.1 Trace File Walk-Through

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.

Example 5-1. Input for a SQL*Plus session that generates extended SQL trace data for a simple query

 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 .

Example 5-2. Raw extended SQL trace data produced by a SQL*Plus session using Example 5-1 as input

 /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.

^[1] There are a few inconsequential exceptions to strict chronological ordering, which you shall see shortly.

Top