Oracle 10046 trace File analysis

Generate the 10046 trace file:

Sql> CREATE TABLE t10046 as SELECT * from Dba_objects; Table created.   Sql> Select File_id,block_id,blocks from dba_extents where segment_name= ' T10046 ';          file_id block_id BLOCKS------------------------------1 94664 8 1 94672          8 1 94680 8 1 94688 8 1 94696 8 1 94704 8 1 94712 8 1 94896 8 1 94904 8 1 9      4912 8 1 94920 8 1 94928 8 1 94936 8 1         94944 8 1 94952 8 1 94960 8 1 95872 128 1 96000 128 1 96128 128 1 96256 128 1 96384 12   8 1 96512 128 1 96640 128 1 96768 128 1   96896 12825 rows selected. Sql> alter session SET events ' 10046 Trace name context forever,level 12 ';  Session altered. #没有创建索引, will walk full table scan sql> select COUNT (*) from t10046; COUNT (*)----------86956sql> alter session set events ' 10046 Trace name context off ';

Contents of the 10046 trace file:

=====================parsing in CURSOR #140231913930616 len=27 dep=0 uid=0 oct=3 lid=0 tim=1458364346292404 hv= 3335870169 ad= ' 7bf41070 ' sqlid= ' awzvq6b3dapqt ' select COUNT (*) from T10046end of Stmtparse #140231913930616: c=10998,e= 11061,p=217,cr=59,cu=0,mis=1,r=0,dep=0,og=1,plh=2130400753,tim=1458364346292403exec #140231913930616: C=0,e=36,p =0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=2130400753,tim=1458364346292551wait #140231913930616: nam= ' SQL*Net message To client ' Ela= 7 driver id=1650815232 #bytes =1 p3=0 obj#=-1 tim=1458364346292607wait #140231913930616: nam= ' Enq:ko-fas T object checkpoint ' ela= 3499 name|mode=1263468550 2=65555 0=1 obj#=-1 tim=1458364346296691wait #140231913930616: nam= ' d  Irect path read ' ela= 335 file number=1 first dba=94665 block cnt=55 obj#=88635 tim=1458364346297284wait #140231913930616: nam= ' direct path read ' ela= 1770 file number=1 first dba=94896 block cnt=72 obj#=88635 tim=1458364346299150wait #14023191 3930616:nam= ' direct path read ' ela= 912 file number=1 Firstdba=95872 block cnt=128 obj#=88635 tim=1458364346300730wait #140231913930616: nam= ' direct path read ' ela= 386 file number=  1 First dba=96000 block cnt=128 obj#=88635 tim=1458364346301893wait #140231913930616: nam= ' direct path read ' ela= 299 file Number=1 first dba=96128 block cnt=128 obj#=88635 tim=1458364346302928wait #140231913930616: nam= ' direct path read ' ela= 371 file number=1 First dba=96256 block cnt=128 obj#=88635 tim=1458364346304307wait #140231913930616: nam= ' direct path rea d ' ela= 236 file number=1 First dba=96384 block cnt=128 obj#=88635 tim=1458364346305513wait #140231913930616: nam= ' direct Path read ' ela= 202 file number=1 first dba=96512 block cnt=128 obj#=88635 tim=1458364346306513wait #140231913930616: nam= ' Direct path read ' ela= 381 file number=1 first dba=96640 block cnt=128 obj#=88635 tim=1458364346307527wait #1402319139306 16:nam= ' direct path read ' ela= 285 file number=1 first dba=96768 block cnt=128 obj#=88635 tim=1458364346309125wait #14023 1913930616:nam= ' DirectPath read ' ela= 324 file number=1 first dba=96896 block cnt=89 obj#=88635 tim=1458364346310304fetch #140231913930616: c=149 98,e=19124,p=1240,cr=1243,cu=0,mis=0,r=1,dep=0,og=1,plh=2130400753,tim=1458364346311758stat #140231913930616 id= 1 cnt=1 pid=0 pos=1 obj=0 op= ' SORT AGGREGATE (cr=1243 pr=1240 pw=0 time=19122 us) ' STAT #140231913930616 id=2 cnt=86956 pid =1 pos=1 obj=88635 op= ' TABLE ACCESS full T10046 (cr=1243 pr=1240 pw=0 time=24549 US cost=338 size=0 card=70030) ' WAIT #1402 31913930616:nam= ' sql*net message from client ' ela= 225 driver id=1650815232 #bytes =1 p3=0 obj#=88635 tim=1458364346312363 FETCH #140231913930616: C=0,e=1,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=0,plh=2130400753,tim=1458364346312405wait # 140231913930616:nam= ' sql*net message to client ' Ela= 2 driver id=1650815232 #bytes =1 p3=0 obj#=88635 tim=1458364346312426 2016-03-19 13:12:37.876wait #140231913930616: nam= ' sql*net message from client ' ela= 11563756 driver id=1650815232 #by Tes=1 p3=0 obj#=88635 Tim=1458364357876195close #140231913930616:c=0,e=10,dep=0,type=0,tim=1458364357876316===================== 

10046 Trace File Content analysis:

1. Database invocation
With 3 subcategories: parsing, execution, and acquisition
These 3 classifications are associated with subroutine Dbms_sql by calling Dbms_sql. Parse,dbms_sql. Execute,dbms_sql. Fetch_rows to run at the same pace as SQL.
Parsing is typically represented by two adjacent entries in a trace file: The first is the parsing in CURSOR and the second is parse. As shown below:

Parsing in CURSOR #140231913930616 len=27 dep=0 uid=0 oct=3 lid=0 tim=1458364346292404 hv=3335870169 ad= ' 7bf41070 ' sqlid= ' AWZVQ6B3DAPQT ' SELECT COUNT (*) from T10046end of Stmtparse #140231913930616: c=10998,e=11061,p=217,cr=59,cu=0,mis=1,r= 0,dep=0,og=1,plh=2130400753,tim=1458364346292403

(1) Parsing in cursor the specific meaning of each item

Parameters	Description
Len	Represents the SQL statement text byte length # "SELECT COUNT (*) from t10046" byte length is 27
Dep	Recursive call Depth #本次调用深度为0
Uid	Resolves user identifiers, corresponding to all_users.user_id and v$sql.parsing_user_id #本次是以sys用户执行的, so uid=0
Oct	Oracle command type, corresponding to V$sql.command_type and V$session.command #select对应类型是3
Lid	Parse pattern identifier, corresponding to all_users.user_id and v$sql.parsing_schema_id, may differ from UID
Tim	Microsecond unit timestamp, usually a little earlier than the value of Tim in the associated parse entry
Hv	hash value, corresponding to V$sql.hash_value
Ad	Address, corresponding to v$sql.address
Sqlid	SQL ID, corresponding to v$sql.sql_id

(2) Specific meanings of the parse items

Parameters	Description
C	CPU Overhead
E	Run time
P	Physical Reading
Cr	Consistent read
Cu	Data block currently being processed
Mis	Cursor missing, 0 for soft parsing, 1 for hard parsing
R	Rows of data being processed
Dep	Recursive call depth
og	Optimize your goals. 1:all_rows,2:first_rows,3:rule,4:choose. Oracle 10g is all_rows after default
Plh	The hash value of the execution plan. Corresponds to V$sql_plan.plan_hash_value,v$sql_plan_statistics_all.plan_hash_value and V$sqlstats.plan_hash_value
Tim	Time stamp in microseconds

2. Execution plan, statistical information and stat entry format

Each row of a set of stat entries represents the row source that forms the result of the statement. A so-called row source, which refers to the data retrieved from an index or table or the intermediate result of a multi-table connection (because two tables must be connected first).
After 10g, the stat entry is only written at Timed_statistics=true and Sql_trace=true. Note that Timed_statistics=fasle is implicitly set if Statistics_level=basic (the default is typical).

Stat #140231913930616 id=1 cnt=1 pid=0 pos=1 obj=0 op= ' SORT AGGREGATE (cr=1243 pr=1240 pw=0 time=19122 us) ' Stat #140231913 930616 id=2 cnt=86956 pid=1 pos=1 obj=88635 op= ' TABLE ACCESS full T10046 (cr=1243 pr=1240 pw=0 time=24549 US cost=338 size =0 card=70030) '

(1) Stat description

Parameters	Description
Id	An identifier that indicates the order of the row data source in the execution plan, usually a id=1 of the first stat row of the execution plan
Cnt	Number of rows to be processed
Pid	The parent identifier, usually a pid=0 of the first stat line that executes the plan. Tkprof and Esqltrcprof use IDs and PID to generate an appropriate indentation of the execution plan by stepping one level of indentation over the parent step of a plan
Pos	The location of one step in the parent step
Obj	object identifiers, corresponding to all_objects.object_id and v$sql_plan.object#
Op	The row data source operations performed, such as table access, index scanning, sorting, federation, and so on, correspond to v$sql_plan.operation. In 10g, the parentheses in the OP after the row data source information contain the actual statement execution indicator
Cr	Consistent read
pr	Physical Reading
pw	Physical Write
Time	Estimated run time in microseconds
Cost	CBO calculates the execution plan cost
Size	Estimated number of bytes in units
Card	Estimated cardinality, which is the number of rows processed

3. Waiting for event and wait entry format

WAIT #140231913930616: nam= ' sql*net message to client ' Ela= 7 driver id=1650815232 #bytes =1 p3=0 obj#=-1 tim=1458364346292 607WAIT #140231913930616: nam= ' Enq:ko-fast object checkpoint ' ela= 3499 name|mode=1263468550 2=65555 0=1 obj#=-1 tim=14  58364346296691WAIT #140231913930616: nam= ' direct path read ' ela= 335 file number=1 first dba=94665 block cnt=55 obj#=88635 Tim=1458364346297284wait #140231913930616: nam= ' direct path read ' ela= 1770 file number=1 first dba=94896 block cnt=72 ob j#=88635 tim=1458364346299150wait #140231913930616: nam= ' direct path read ' ela= 912 file number=1 first dba=95872 block cn t=128 obj#=88635 tim=1458364346300730wait #140231913930616: nam= ' direct path read ' ela= 386 file number=1 First dba=96000 Block cnt=128 obj#=88635 tim=1458364346301893wait #140231913930616: nam= ' direct path read ' ela= 299 file number=1 First db a=96128 block cnt=128 obj#=88635 tim=1458364346302928wait #140231913930616: nam= ' direct path read ' ela= 371 file number=1 First DBA=96256 block cnt=128 obj#=88635 tim=1458364346304307wait #140231913930616: nam= ' direct path read ' ela= 236 file number=1 First dba=96384 Block cnt=128 obj#=88635 tim=1458364346305513wait #140231913930616: nam= ' direct path read ' ela= 202 file number=1 First db a=96512 block cnt=128 obj#=88635 tim=1458364346306513wait #140231913930616: nam= ' direct path read ' ela= 381 file number=1 First dba=96640 block cnt=128 obj#=88635 tim=1458364346307527wait #140231913930616: nam= ' direct path read ' ela= 285 file n Umber=1 first dba=96768 block cnt=128 obj#=88635 tim=1458364346309125wait #140231913930616: nam= ' direct path read ' Ela= 32 4 file number=1 First dba=96896 block cnt=89 obj#=88635 tim=1458364346310304

Parameters	Description
Ela	Run time in microseconds
P1	The first argument to wait for an event. Corresponds to V$SESSION_WAIT.P1
P2	The second parameter of the wait event. Corresponds to V$SESSION_WAIT.P2
P3	The third parameter of the wait event. Corresponds to V$SESSION_WAIT.P3
Tim	Time stamp
file#	Absolute file Number
block#	Data Block number
Blocks	Number of data blocks
obj#	The object number is object_id
Nam	The name of the wait event

Reference: http://blog.itpub.net/29320885/viewspace-1223962/

Oracle 10046 trace File analysis