« 关于oracle的版权信息-一些你可能不知道的，一些可以看出Oracle野心的... | Blog首页 | 周末看片-关于莉莉周的一切 »
了解raw trace文件的各项内容
链接：https://www.eygle.com/archives/2005/10/aeearaw_traceia.html
今天浏览metalink，看到这篇Interpreting Raw SQL_TRACE，比较老的一篇文章了，但是确实很有用，所以决定大略翻译一下吧。
我们知道有几种方法可以得到一个SQL语句执行时后台的trace文件，一个是用SQL_TRACE，一个是用DBMS_SUPPORT包或者DBMS_SYSTEM包，还有一种就是直接使用10046 event。
使用10046 event的方法大致如下：
alter session set events '10046 trace name context forever, level 12';
your sql statement...
alter session set events '10046 trace name context off';
其中的level有1，4，8，12几个选项，其中1相当于设置SQL_TRACE=TRUE之后的结果，4包括1的结果和绑定变量的实际值，8包括1的结果和等待事件的情况，12则同时包含1的结果，绑定变量的实际值和等待事件情况，所以可以说level 12是最为详细的trace了。
同时我们也知道，对于trace结果，oracle提供了tkprof实用程序用来格式化trace文件，提供一份更容易读懂的trace结果。
那么为什么还要直接读取trace文件呢？最重要的是tkprof的结果是不包含绑定变量值的，同时也不包括真正的SQL执行顺序，而trace文件中我们则可以看到按照时间排列的parse,binds,executes,fetch等等，这在某西场合下是很有用处的。还有就是，如果你能够直接读取这些让人看得眼晕的trace，是不是会有一种很爽，很大师的感觉:-)
当然如果我们要根据一些标准（比如CPU时长，磁盘读取量等）进行trace中的SQL排序，那么tkprof是我们唯一的选择，可以参看coolyl（丫现在迷恋WOW，已经不理朝政了:-D）的Tkprof工具介绍和分析。
下面是metalink中的这篇文章的大体翻译，大部分名词用英文反而更好，就不强加翻译了，相信大家都看得懂。当然也是比较懒的原因:-)
文本总结了trace结果原始输出文件中的内容。
----------------------------------------------------------------------------
APPNAME mod='%s' mh=%lu act='%s' ah=%lu
----------------------------------------------------------------------------
APPNAME：Application name setting。在Oracle 7.2和以上版本中出现。这个名称可以由DBMS_APPLICATION_INFO包来设定。
mod：Module name
mh：Module hash value
act：Action
ah：Action hash value
比如：APPNAME mod='SQL*Plus' mh=3669949024 act='' ah=4029777240
----------------------------------------------------------------------------
PARSING IN CURSOR #
statement....
END OF STMT
----------------------------------------------------------------------------
CURSOR：Cursor number
len ：Length of SQL statement，SQL语句的长度
dep ：Recursive depth of the cursor，当前SQL语句的递规深度，如果为0则表示是用户提交的SQL，为1则是由于用户SQL而导致Oracle后台自己执行的SQL，为2则是由1级SQL继续诱发的下一级SQL。
uid ：Schema user id of parsing user
oct ：Oracle command type.
lid ：Privilege user id.
tim ：Timestamp。在Oracle9i之前单位是1/100秒，9i则是1/1,000,000秒。利用这个值可以计算一个SQL执行了到底多长时间。这个值就是当前行被写入trace文件时数据库V$TIMER视图的值。
hv ：Hash id.
ad ：SQLTEXT address，SQLTEXT的地址，跟V$SQLAREA和V$SQLTEXT视图中的ADDRESS字段值相等。
statement ：The actual SQL statement being parsed.
----------------------------------------------------------------------------
PARSE ERROR #%d:len=%ld dep=%d uid=%ld oct=%d lid=%ld tim=%lu err=%d
statement....
----------------------------------------------------------------------------
PARSE ERROR ：在Oracle 7.2以上版本中解析的错误会写入trace文件中。
len ：Length of SQL statement.
dep ：Recursive depth of the statement
uid ：User id.
oct ：Oracle command type (if known).
lid ：Privilege user id.
tim ：Timestamp.
err ：Oracle error code (e.g. ORA-XXXXX) reported
statement ：The SQL statement that errored.
----------------------------------------------------------------------------
PARSE #
EXEC #
FETCH #
UNMAP #
----------------------------------------------------------------------------
PARSE ：Parse a statement. 解析一个SQL
EXEC ：Execute a pre-parsed statement. 执行已经解析完毕的SQL
FETCH ：Fetch rows from a cursor. 从游标中得到数据，通常指select返回记录
UNMAP ：如果游标使用了临时表（temporary table）, 当游标关闭的时候将会看到UNMAP
c ：CPU time (100th's of a second in Oracle7 ,8 and 9).
e ：Elapsed time (100th's of a second Oracle7, 8. Microseconds in Oracle 9 onwards).
p ：Number of physical reads.
cr ：Number of buffers retrieved for CR reads.
cu ：Number of buffers retrieved in current mode.
mis ：Cursor missed in the cache.
r ：Number of rows processed.
dep ：Recursive call depth (0 = user SQL, >0 = recursive).
og ：Optimizer goal: 1=All_Rows, 2=First_Rows, 3=Rule, 4=Choose
tim ：Timestamp (large number in 100ths of a second).
比如：FETCH #2:c=0,e=106,p=0,cr=3,cu=0,mis=0,r=1,dep=1,og=4,tim=6005498548671
----------------------------------------------------------------------------
ERROR #%d:err=%d tim=%lu
----------------------------------------------------------------------------
执行或者fetch之后出现的SQL Error
err ：Oracle error code (e.g. ORA-XXXXX) at the top of the stack.
tim ：Timestamp.
----------------------------------------------------------------------------
STAT #
----------------------------------------------------------------------------
CURSOR的执行计划.
CURSOR ：Cursor which the statistics apply to.
id ：Line of the explain plan which the row count applies to (从1开始).
cnt ：Number of rows for this row source.
pid ：Parent id of this row source.
pos ：Position in explain plan.
obj ：Object id of row source (if this is a base object).
op ： The row source access operation.
比如：
STAT #2 id=2 cnt=0 pid=1 pos=1 obj=510 op='TABLE ACCESS BY INDEX ROWID OBJECT_USAGE (cr=2 r=0 w=0 time=83 us)'
STAT #2 id=3 cnt=1 pid=2 pos=1 obj=511 op='INDEX RANGE SCAN I_STATS_OBJ# (cr=1 r=0 w=0 time=43 us)'
----------------------------------------------------------------------------
XCTEND rlbk=%d rd_only=%d
----------------------------------------------------------------------------
XCTEND是事务结束的标志.
rlbk ：1 if a rollback was performed, 0 if no rollback (commit).
rd_only ：1 if transaction was read only, 0 if changes occurred.
----------------------------------------------------------------------------
BINDS #%d:
bind 0: dty=2 mxl=22(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 ：Variables bound to a cursor.
bind N ：The bind position being bound.
dty ：Data type.
mxl ：Maximum length of the bind variable (private max len in paren).
mal ：Array length.
scl ：Scale.
pre ：Precision.
oacflg ：Special flag indicating bind options
oacflg2 ：Continuation of oacflg
size ：Amount of memory to be allocated for this chunk
offset ：Offset into this chunk for this bind buffer
bfp ：Bind address.
bln ：Bind buffer length.
avl ：Actual value length (array length too).
flg ：Special flag indicating bind status
value ：The actual value of the bind variable.
比如：
BINDS #4:
bind 0: dty=2 mxl=22(22) mal=00 scl=00 pre=00 oacflg=08 oacfl2=1 size=24 offset=0
bfp=ffffffff7ce64ee0 bln=22 avl=01 flg=05
value=0
bind 1: dty=1 mxl=32(11) mal=00 scl=00 pre=00 oacflg=18 oacfl2=1 size=32 offset=0
bfp=ffffffff7ce6b128 bln=32 avl=11 flg=05
value="TABCOMPART$"
bind 2: dty=2 mxl=22(22) mal=00 scl=00 pre=00 oacflg=08 oacfl2=1 size=24 offset=0
bfp=ffffffff7ce6bae8 bln=24 avl=02 flg=05
value=1
----------------------------------------------------------------------------
WAIT #
----------------------------------------------------------------------------
WAIT ：An event that we waited for.
nam ：What was being waited for.
ela ：Elapsed time for the operation.
p1 ：P1 for the given wait event.
p2 ：P2 for the given wait event.
p3 ：P3 for the given wait event.
比如 (Full Table Scan):
WAIT #1: nam="db file scattered read" ela= 5 p1=4 p2=1435 p3=25
在游标1上经历了"db file scattered read"等待事件，一共等了0.05秒，在读取File 4，从1435 block开始，读了25个block
比如 (Index Scan):
WAIT #1: nam="db file sequential read" ela= 4 p1=4 p2=1224 p3=1
在游标1上经历了"db file sequential read"等待事件，一共等了0.04秒，在读取file 4，block 1224，读取了这一个block
对于每一个等待事件的含义和p1,p2,p3表示的意思，可以参考Oracle Database Reference文档的Oracle Wait Events章节。
历史上的今天...
>> 2017-10-23文章:
>> 2015-10-23文章:
>> 2010-10-23文章:
>> 2009-10-23文章:
By eygle on 2005-10-23 03:25 | Comments (5) | Internal | 487 |
运用之妙，存乎一心。
这个东西关键在运用，在领悟：）
above comment really sounds like eygle's style :-)
精辟
你好!
在文章中提到的ela的值是1%秒﹐我對這個有點疑問?
請看﹕
使用10046跟蹤一全表掃描的sql語句后﹐查看trc文件﹐發現好多db file scattered read等待事件﹐ela的值太大。
ela好象是以1%秒為單位的事件經過的時間﹐如果是這樣﹐那下面的每個等待都要經過几百秒的時間﹐那整個sql語句執行完需几十分鐘。可事實上﹐整個sql執行只需10秒﹐不知這是怎么回事?
SQL> select count(*) from TRAND_TEST;
COUNT(*)
----------
657764
目前歷時: 00:00:11.31
跟蹤事件中得到了大量的如下等待事件。
WAIT #1: nam='db file scattered read' ela= 49903 p1=20 p2=139 p3=64
WAIT #1: nam='db file scattered read' ela= 24998 p1=20 p2=203 p3=62
WAIT #1: nam='db file scattered read' ela= 17467 p1=20 p2=267 p3=64
WAIT #1: nam='db file scattered read' ela= 22010 p1=20 p2=331 p3=62
WAIT #1: nam='db file scattered read' ela= 47725 p1=20 p2=395 p3=64
WAIT #1: nam='db file scattered read' ela= 44951 p1=20 p2=459 p3=62
WAIT #1: nam='db file scattered read' ela= 33947 p1=20 p2=523 p3=64
WAIT #1: nam='db file scattered read' ela= 51974 p1=20 p2=587 p3=62
WAIT #1: nam='db file scattered read' ela= 12138 p1=20 p2=651 p3=64
WAIT #1: nam='db file scattered read' ela= 26120 p1=20 p2=715 p3=62
WAIT #1: nam='db file scattered read' ela= 30228 p1=20 p2=779 p3=64
WAIT #1: nam='db file scattered read' ela= 32382 p1=20 p2=843 p3=62
WAIT #1: nam='db file scattered read' ela= 60860 p1=20 p2=907 p3=64
WAIT #1: nam='db file scattered read' ela= 48750 p1=20 p2=971 p3=62
to bin_huhj
Elapsed time (100th's of a second Oracle7, 8. Microseconds in Oracle 9 onwards).
microsecond
[5maIkrEJsekEnd]
n.
一百万分之一秒, 微秒