| Oracle FAQ | Your Portal to the Oracle Knowledge Grid | |
 |
 | |||
| Oracle FAQ | Your Portal to the Oracle Knowledge Grid | |
|
| |||
Home -> Community -> Mailing Lists -> Oracle-L -> 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
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)'
> =====================
-- Archives are at http://www.freelists.org/archives/oracle-l/ FAQ is at http://www.freelists.org/help/fom-serve/cache/1.html -----------------------------------------------------------------Received on Wed Jun 30 2004 - 09:57:43 CDT
 |
 |