Oracle Performance Analysis 2:trace file interpretation

Here is a fragment of the trace file that represents a SQL execution process, and a trace file consists of a number of such fragments:

parsing in CURSOR #4 len=135 dep=1 uid=0 oct=3 lid=0 tim=777069789359 hv=1115215392 ad= ' 33 e7e384 ' Select/*+ Index (idl_char$ i_idl_char1) +*/piece#,length,piece from idl_char$ where Obj#=:1 and Part=:2 and Versio N=:3 ORDER by Piece#end of Stmtparse #4: c=0,e=12,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,tim=777069789357--binds #2: EXEC #4 : c=0,e=14,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,tim=777069789415--wait #2: nam= ' sql*net message from client ' ela= 143 Driver id=1413697536 #bytes =1 p3=0 obj#=-1 tim=775454461373fetch #4: c=0,e=18,p=0,cr=4,cu=0,mis=0,r=1,dep=1,og=4,tim= 777069789450FETCH #4: C=0,e=5,p=0,cr=1,cu=0,mis=0,r=0,dep=1,og=4,tim=777069789477stat #4 id=1 cnt=1 pid=0 Pos=1 obj=74 Op= ' TABLE ACCESS by INDEX ROWID idl_char$ (cr=4 pr=0 pw=0 time=20 us) ' STAT #4 id=2 cnt=1 pid=1 pos=1 obj=115 op= ' Index RAN GE SCAN i_idl_char1 (cr=3 pr=0 pw=0 time=12 us) ' 

The "--" begins with an artificial addition, which may exist in other queries, meaning the following key fields:
1) parsing in cursor and end of stmt contain SQL statement text;
2) Parse, exec, and fetch respectively represent parsing (parse), execute (execution), and fetch (fetch) calls;
3) binds represents the definition and value of the bound variable;
4) Wait indicates the waiting event that occurs during the process summary;
5) stat represents the resulting execution plan and related statistics.
Here are some more detailed explanations (from: Interpreting Raw sql_trace and dbms_supportstart_trace output), because each version of Oracle is different, so these are for informational purposes only.

-------------------------------------------------------------------------
Parsing in CURSOR # len=x dep=x uid=x oct=x lid=x tim=x hv=x ad= ' X '
SQL statements
END of STMT
--------------------------------------------------------------------------
Len:sql statement length
DEP: Depth of cursor recursive invocation
UID: User ID for parsing SQL
oct:oracle Command Type
Lid: Privileged User ID
Tim: Time pumping. Before Oracle 9i, the unit was only 1/100 seconds, and Oracle 9i was followed by 1/1000000 seconds. Timestamps can be used to determine the time interval between two points. The value is taken from the value in the V$timer and can be used to determine the absolute time with a 2 operation ' Tim ' difference
Hv:sql HASH ID (hash_value field corresponding to V$sqlarea view and V$sqltext view)
Ad:sqltext addresses (address fields corresponding to V$sqlarea and V$sqltext views)

--------------------------------------------------------------------------
PARSE ERROR #%d:len=%ld dep=%d Uid=%ld oct=%d lid=%ld tim=%lu err=%d
SQL statement
---------------------------------------------------------------- ----------
Len:sql Statement length
Dep: Depth of cursor recursive invocation
UID: User ID for parsing SQL
oct:oracle command type
Tim: Time pumping. Ibid.
err:oracle error code (E.G.ORA-XXXXX)

--------------------------------------------------------------------------
PARSE #:c=0,e=0,p=0,cr=0,cu=0, mis=0,r=0,dep=0,og=4,tim=0 
exec  #:c=0,e=0,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=4,tim=0
FETCH #:c=0 , e=0,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=4,tim=0
UNMAP #:c=0,e=0,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=4,tim=0
-- ------------------------------------------------------------------------
Action:
 1) Parse: Parse SQL
 2) EXEC: Perform the parsed SQL
 3) FETCH: Fetch a record from the cursor
 4) UNMAP: If the cursor uses a temporary table, the action is used to free the temporary table resource when the cursor is closed (release lock, delete state object , release temporary segments, etc.). In the report generated by TKPROF, Unmap statistics are added to the statistics of the execute operation.
 5) Sort UNMAP: like above, but sort OS files or Temp table segment (segment)

C:cpu time (1/100 seconds in Oracle7, 8, and 9)
E:elapsed time (1/100 seconds in Oracle7, 8, microseconds in Oracle 9 and later)
P: Physical reading (number of physical reads)
CR:CR (Consistent read, consistent read) number of reads
CU: The number of reads under current mode
Mis:cursor the number of misses in the cache
R: Number of records involved
DEP: Recursive call depth (0 = user Sql,>0 = recursive)
OG: Optimizer mode: 1=all_rows,2=first_rows,3=rule,4=choose
Tim: Timestamp, used to determine the time between two operations

--------------------------------------------------------------------------
ERROR #%d:err=%d Tim=%lu
--------------------------------------------------------------------------
An error display after a execution or tetch error
ERR: Oracle error code at top of stack (ex: ORA-XXXX)
Tim: Time stamp

--------------------------------------------------------------------------
STAT #<cursor> id=n cnt=0 [pid=0 pos=0 obj=0 op= ' SORT AGGREGATE ']
--------------------------------------------------------------------------
Stat: Statistical report of the execution plan for <CURSOR>
<cursor>: CURSOR to which statistics are applied
ID: The number of actions in the execution plan tree that are executed in a plan
CNT: Number of rows involved
PID: The parent ID of this line
POS: Location in the execution plan
OBJ: The object ID of the row (if this is a base object)
OP: The action involved in the row

--------------------------------------------------------------------------
Xctend rlbk=%d rd_only=%d
--------------------------------------------------------------------------
Xctend: End of transaction flag
Rlbk:1 indicates that rollback,0 represents a commit
Rd_only: Transaction Read-only is 1, write is 0

Note: The following only exists if waits or binds appears

--------------------------------------------------------------------------
Binds #%d:
Bind 0:dty=2 mxl=22 ($) mal=00 scl=00 pre=00 oacflg=03 oacfl2=0 size=24 offset=0
Bfp=02fedb44 bln=22 avl=00 flg=05
value=10
--------------------------------------------------------------------------
Bind: Cursor bound variable

Bind N: Bind variable position
DTY: Data type
MXL: Maximum length of bound variable
Mal: Array length
SCL: Size (scale)
Pre: progress (Precision)
OACFLG: A specific flag indicating the binding option
The continuation of the OACFL2:OACFLG
Size: The memory allocated for this block
Offset: The offsets for this binding cache into this block

BFP: Binding Address
BLN: Binding Cache length
AVL: Actual value Length (also array length)
FLG: A specific flag indicating the state of the binding
Value: The actual value of the bound variable

--------------------------------------------------------------------------
WAIT #<cursor>: nam= "" Ela=0 p1=0 p2=0 p3=0
--------------------------------------------------------------------------
Wait: Waits for event information
NAM: Wait for event name
ELA: Time spent on operations
P1: The parameters provided for the wait event P1
P2: The parameters provided for the wait event P2
P3: The parameters provided for the wait event P3

Example (full Table Scan):        
 wait #1: nam= "DB file Scattered read "Ela= 5 p1=4 p2=1435 p3=25
   waiting under CURSOR No 1
   for" db fi Le scattered read "
reads: we wait 0.05 seconds. For a read: File 4, start block 1435, total 25 blocks
 
Example (Index Scan):
 wait #1: nam= "db file Sequential read" Ela= 4 p1=4 p2 =1224 p3=1
   waiting under CURSOR No 1
   for "DB file sequential read"
Interpretation: we wait 0.04 seconds, for a single block read (p3=1), from File 4, start block 1224