eygle.com   eygle.com
eygle.com eygle
eygle.com  
 

« 关于oracle的版权信息-一些你可能不知道的,一些可以看出Oracle野心的... | Blog首页 | 周末看片-关于莉莉周的一切 »

了解raw trace文件的各项内容

今天浏览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 # len=X dep=X uid=X oct=X lid=X tim=X hv=X ad='X'
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 #: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
----------------------------------------------------------------------------

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 # id=N cnt=0 [pid=0 pos=0 obj=0 op='SORT AGGREGATE ']
----------------------------------------------------------------------------

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 #: nam="" ela=0 p1=0 p2=0 p3=0
----------------------------------------------------------------------------

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章节。


历史上的今天...
    >> 2015-10-23文章:
    >> 2010-10-23文章:
    >> 2009-10-23文章:

无觅

By eygle on 2005-10-23 03:25 | Comments (5) | Internal | 487 |

5 Comments

运用之妙,存乎一心。

这个东西关键在运用,在领悟:)

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.
一百万分之一秒, 微秒


CopyRight © 2004~2020 云和恩墨,成就未来!, All rights reserved.
数据恢复·紧急救援·性能优化 云和恩墨 24x7 热线电话:400-600-8755 业务咨询:010-59007017-7040 or 7037 业务合作: marketing@enmotech.com