Re: Slow performance/response

Here is  a quick and dirty overview of some of the relevant fields (metalink 
has a good note about reading raw trace files and 
"Optimizing Oracle Performance" is a comprehensive overview of trace files and 
performance optimization).

EXEC - a database call to execute the statement and how much cpu and elapsed 
time were consumed, the number and types of LIOs, rows 
returned (and more).
WAIT - a timed event (not a WAIT event). Anyway, this gives the name of the 
timed event, the duration (ela) and   additional 
information (p1,p2,p3).
FETCH - actual returning of rows to the calling program (like sql*plus)
STAT - the *actual* execution plan, with the steps, parent steps, type of 
operation, # of rows returned, ios and timing information

c=  - A call/event gets CPU time when it is on the CPU when the clock is 
incremented. When it is 0, this means that the process was 
not on the CPU when the cpu clock was incremented. This does not mean that the 
call consumed 0 cpu time.
e=/ela=/time= - This is the elapsed time in microseconds (9i).
cr=/cu= - Logical IOs.
r=/cnt= - number of rows returned
id= - the unique id for each step in the execution plan
pid= - the parent id for the step

I am not seeing the query you posted earlier in the trace file. So I'll use one 
of the non-recursive queries as an example of how to 
read the output.

The first statement performed 1 logical i/o (cr=1) and returned 0 rows (r=0). 
From parse to fetch completion, it consumed 959 
microseconds and was not on the CPU when the clock incremented.

The execution plan was to perform a unique scan on the PBSYSCATPBT_IDX index 
(consumed 11 microseconds) and use the ROWID to access 
the PBCATTBL table (consumed 3 microseconds (14 total - 11 for the index 
scan)). As the cnt values are 0, this statement did not 
return any rows (verifying the information in the FETCH call).

The second statement performed 4 logical i/os and returned 20 rows. From parse 
to fetch completion, it consumed 1939 microseconds 
and was not on the CPU when the clock incremented.

The execution plan was to perform a full table scan of PBCATFMT (consuming 76 
microseconds) using 4 logical i/os and returned 20 rows.

> =====================
> PARSING IN CURSOR #1 len=276 dep=0 uid=151 oct=3 lid=151 tim=1063030977863756 
> hv=2671731006 ad='34c53228'
> SELECT 
> PBD_FHGT,PBD_FWGT,PBD_FITL,PBD_FUNL,PBD_FCHR,PBD_FPTC,PBD_FFCE,PBH_FHGT,PBH_FWGT,PBH_FITL,PBH_FUNL,PBH_FCHR,PBH_FPTC,PBH_FFCE,PBL_FHGT,PBL_FWGT,PBL_FITL,PBL_FUNL,PBL_FCHR,PBL_FPTC,PBL_FFCE,PBT_CMNT
>  
>   FROM SYSTEM.PBCATTBL   WHERE PBT_OWNR = 'PUBLIC' AND PBT_TNAM = 'DUAL'
> END OF STMT
> PARSE #1:c=0,e=892,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=4,tim=1063030977863753
> BINDS #1:
> EXEC #1:c=0,e=46,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=4,tim=1063030977863889
> WAIT #1: nam='SQL*Net message to client' ela= 2 p1=1413697536 p2=1 p3=0
> FETCH #1:c=0,e=19,p=0,cr=1,cu=0,mis=0,r=0,dep=0,og=4,tim=1063030977864026
> WAIT #1: nam='SQL*Net message from client' ela= 1959 p1=1413697536 p2=1 p3=0
> =====================
> STAT #1 id=1 cnt=0 pid=0 pos=1 obj=36257 op='TABLE ACCESS BY INDEX ROWID 
> PBCATTBL (cr=1 r=0 w=0 time=14 us)'
> STAT #1 id=2 cnt=0 pid=1 pos=1 obj=36258 op='INDEX UNIQUE SCAN 
> PBSYSCATPBT_IDX (cr=1 r=0 w=0 time=11 us)'
> =====================
> =====================
> PARSING IN CURSOR #1 len=63 dep=0 uid=151 oct=3 lid=151 tim=1063030977885676 
> hv=1175394665 ad='31c351f0'
> SELECT PBF_NAME,PBF_FRMT,PBF_TYPE,PBF_CNTR FROM SYSTEM.PBCATFMT
> END OF STMT
> PARSE #1:c=0,e=505,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=4,tim=1063030977885672
> BINDS #1:
> EXEC #1:c=0,e=28,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=4,tim=1063030977885769
> WAIT #1: nam='SQL*Net message to client' ela= 2 p1=1413697536 p2=1 p3=0
> FETCH #1:c=0,e=55,p=0,cr=3,cu=0,mis=0,r=1,dep=0,og=4,tim=1063030977885878
> WAIT #1: nam='SQL*Net message from client' ela= 1272 p1=1413697536 p2=1 p3=0
> WAIT #1: nam='SQL*Net message to client' ela= 0 p1=1413697536 p2=1 p3=0
> FETCH #1:c=0,e=77,p=0,cr=1,cu=0,mis=0,r=19,dep=0,og=4,tim=1063030977887302
> WAIT #1: nam='SQL*Net message from client' ela= 2325 p1=1413697536 p2=1 p3=0
> =====================
> STAT #1 id=1 cnt=20 pid=0 pos=1 obj=36261 op='TABLE ACCESS FULL PBCATFMT 
> (cr=4 r=0 w=0 time=76 us)'
> =====================

----------------------------------------------------------------
Please see the official ORACLE-L FAQ: http://www.orafaq.com
----------------------------------------------------------------
To unsubscribe send email to:  oracle-l-request@xxxxxxxxxxxxx
put 'unsubscribe' in the subject line.
--
Archives are at http://www.freelists.org/archives/oracle-l/
FAQ is at http://www.freelists.org/help/fom-serve/cache/1.html
-----------------------------------------------------------------

Other related posts: