Re: Slow performance/response
- From: Daniel Fink <Daniel.Fink@xxxxxxx>
- To: oracle-l@xxxxxxxxxxxxx
- Date: Wed, 30 Jun 2004 08:59:10 -0600
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 //www.freelists.org/archives/oracle-l/
FAQ is at //www.freelists.org/help/fom-serve/cache/1.html
-----------------------------------------------------------------
Other related posts:
