I second Sybrand's recommendation of Cary Millsap's book for learning how to read 10046 trace files. That book is likely the best source for understanding these trace files.
If you search for information on 10046 trace files, you will likely find a couple other writeups that I created for reading 10046 trace files in addition to the one posted by Aman. One of those posts is here:
http://groups.google.com/group/ORACLE_DBA_EXPERTS/browse_thread/thread/520793f76f5d40d3
In short summary:
len= the number of characters in the SQL statement
dep= tells the application/trigger depth at which the SQL statement was executed. dep=0 indicates that it was executed by the client application. dep=1 indicates that the SQL statement was executed by a trigger, the Oracle optimizer, or a space management call. dep=2 indicates that the SQL statement was called from a trigger, dep=3 indicates that the SQL statement was called from a trigger that was called from a trigger.
tim= is a time stamp measured in 1/1,000,000 of a second that may be used for tracking the progress in the 10046 trace file - take the delta value of the most recent tim=, subtract the first tim=, divide the result by 1,000,000 - equals the number of seconds into the trace file.
c= CPU seconds - amount of CPU resources required at that point in the execution. On 8.1.7.4 and earlier, divide by 100 to obtain the number of seconds. After 8.1.7.4, divide by 1,000,000 to obtain the number of seconds.
e= Elapsed seconds - number of seconds as measured by a high precision clock at that point in the execution. This may be significantly different from CPU seconds. On 8.1.7.4 and earlier, divide by 100 to obtain the number of seconds. After 8.1.7.4, divide by 1,000,000 to obtain the number of seconds.
p= Physical blocks read from disk.
cr= Consistent reads
cu= Consistent reads in current mode
mis= Number of shared pool misses at that stage of execution.
r= Number of rows returned by the call
og= Optimizer goal - 1=ALL_ROWS, 2=FIRST_ROWS, 3=RULE, 4=CHOOSE
XCTEND rlbk=0 indicates that the client issued a COMMIT, rd_only=1 indicates that no information changed in the database as a result of the COMMIT
ela= is the elapsed time in 1/100 of a second on 8.1.7.4 and earlier, and in 1/1,000,000 of a second on versions after 8.1.7.4.
p1= meaning depends on the wait event
p2= meaning depends on the wait event
p3= meaning depends on the wait event
STAT lines - the row source execution plan:
id= line identifier
cnt= number of rows returned or processed
pid= parent operation identifier - used to determine indentation of the plan
obj= object id (or possibly data object id - I will have to verify) of the object referenced at that stage of the plan
Search for additional details.
Putting the pieces together, it is possible to do the following analysis:
(Raw Trace)
=====================
PARSING IN CURSOR #76 len=712 dep=0 uid=535 oct=3 lid=535 tim=4085083825 hv=2470216549 ad='488f714c'
select currency_id, sell_rate, buy_rate, act_material_cost, act_labor_cost, act_burden_cost, act_service_cost,
tracking_currency,
s_currency, s_thousand, i_currency, i_neg_curr, i_curr_digits,
rnd_acct_id, real_gn_acct_id, real_ls_acct_id, unreal_gn_acct_id, unreal_ls_acct_id
from LABOR_TICKET_CURR t, currency c
where TRANSACTION_ID = 1257288
and t.currency_id = c.id
order by c.id asc END OF STMT
PARSE #76:c=15625,e=3997,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=1,tim=4085083815
WAIT #76: nam='SQL*Net message to client' ela= 7 driver id=1413697536 #bytes=1 p3=0 obj#=38653 tim=4085086655
WAIT #76: nam='SQL*Net message from client' ela= 806 driver id=1413697536 #bytes=1 p3=0 obj#=38653 tim=4085087815
BINDS #76:
EXEC #76:c=0,e=425,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,tim=4085088645
FETCH #76:c=0,e=97,p=0,cr=1,cu=0,mis=0,r=0,dep=0,og=1,tim=4085089011
WAIT #76: nam='SQL*Net message to client' ela= 7 driver id=1413697536 #bytes=1 p3=0 obj#=38653 tim=4085089369
WAIT #76: nam='SQL*Net message from client' ela= 15705 driver id=1413697536 #bytes=1 p3=0 obj#=38653 tim=4085105370
STAT #76 id=1 cnt=0 pid=0 pos=1 obj=0 op='SORT ORDER BY (cr=1 pr=0 pw=0 time=112 us)'
STAT #76 id=2 cnt=0 pid=1 pos=1 obj=0 op='NESTED LOOPS (cr=1 pr=0 pw=0 time=70 us)'
STAT #76 id=3 cnt=0 pid=2 pos=1 obj=38654 op='TABLE ACCESS BY INDEX ROWID LABOR_TICKET_CURR (cr=1 pr=0 pw=0 time=59 us)'
STAT #76 id=4 cnt=0 pid=3 pos=1 obj=39858 op='INDEX RANGE SCAN SYS_C0035887 (cr=1 pr=0 pw=0 time=46 us)'
STAT #76 id=5 cnt=0 pid=2 pos=2 obj=38537 op='TABLE ACCESS BY INDEX ROWID CURRENCY (cr=0 pr=0 pw=0 time=0 us)'
STAT #76 id=6 cnt=0 pid=5 pos=1 obj=39751 op='INDEX UNIQUE SCAN SYS_C0035752 (cr=0 pr=0 pw=0 time=0 us)'
=====================
(End of Raw Trace)
Analysis:
Cursor 76 Ver 3 Parse at 0.067149 (0.027692)
Statement Depth 0 (Application Code)
select currency_id, sell_rate, buy_rate, act_material_cost, act_labor_cost, act_burden_cost, act_service_cost,
tracking_currency,
s_currency, s_thousand, i_currency, i_neg_curr, i_curr_digits,
rnd_acct_id, real_gn_acct_id, real_ls_acct_id, unreal_gn_acct_id, unreal_ls_acct_id
from LABOR_TICKET_CURR t, currency c
where TRANSACTION_ID = 1257288
and t.currency_id = c.id
order by c.id asc
Cursor 76 Ver 3 Parse at 0.067139 (Parse to Parse -0.000010),CPU Time 0.015625,Elapsed Time 0.003997,Rows Affected 0,Blks from Buff 0,Blks from Disk 0,**Shared Pool Misses** 1,Goal=ALL_ROWS
Cursor 76 Ver 3 0.069979 0.000007 SQL*Net message to client
Cursor 76 Ver 3 0.071139 0.000806 SQL*Net message from client
Bind Variables:BINDS #76: 0.071139
Cursor 76 Ver 3 Execute at 0.071969 (Parse to Exec 0.004820),CPU Time 0.000000,Elapsed Time 0.000425,Rows Affected 0,Blks from Buff 0,Blks from Disk 0,
Cursor 76 Ver 3 Fetch at 0.072335 (Parse to Fetch 0.005186),CPU Time 0.000000,Elapsed Time 0.000097,Rows Retrievd 0,Blks from Buff 1,Blks from Disk 0
Cursor 76 Ver 3 Fetch at 0.072335 (Parse to Fetch 0.005186),CPU Time 0.000000,Elapsed Time 0.000097,Rows Retrievd 0,Blks from Buff 1,Blks from Disk 0
Cursor 76 Ver 3 0.072693 0.000007 SQL*Net message to client
Cursor 76 Ver 3 0.088694 0.015705 SQL*Net message from client
(Rows 0) SORT ORDER BY (cr=1 pr=0 pw=0 time=102 us)
(Rows 0) NESTED LOOPS (cr=1 pr=0 pw=0 time=67 us)
(Rows 0) TABLE ACCESS BY INDEX ROWID LABOR_TICKET_CURR (cr=1 pr=0 pw=0 time=57 us)
(Rows 0) INDEX RANGE SCAN SYS_C0035887 (cr=1 pr=0 pw=0 time=45 us)
(Rows 0) TABLE ACCESS BY INDEX ROWID CURRENCY (cr=0 pr=0 pw=0 time=0 us)
(Rows 0) INDEX UNIQUE SCAN SYS_C0035752 (cr=0 pr=0 pw=0 time=0 us)
For more information (for example, cr=0 pr=0 pw=0 time=0 us on STAT lines), try the following search:
http://books.google.com/books?hl=en&q=STAT%3D%20OBJ%20millsap&um=1&ie=UTF-8&sa=N&tab=wp
Charles Hooper
IT Manager/Oracle DBA
K&M Machine-Fabricating, Inc.
Finished the line describing ela=, added sample of analysis results.
Message was edited by:
Charles Hooper
