Section 5.7. Detailed Trace File Walk-Through

   

5.7 Detailed Trace File Walk-Through

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 m 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 m 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 m 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 m 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 m 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 m 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 m 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- m s read from the SQL*Net socket. The fetch returned no rows and consumed only 2 m 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 m 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 m 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.


   
Top


Optimizing Oracle Performance
Optimizing Oracle Performance
ISBN: 059600527X
EAN: 2147483647
Year: 2002
Pages: 102

flylib.com © 2008-2017.
If you may any questions please contact us: flylib@qtcs.net