下面是trace文件中的一个片段,表示一个SQL执行的过程,一个trace文件由很多这样的片段组成:
PARSING IN CURSOR #4 len=135 dep=1 uid=0 oct=3 lid=0 tim=777069789359 hv=1115215392 ad='33e7e384' select /*+ index(idl_char$ i_idl_char1) +*/ piece#,length,piece from idl_char$ where obj#=:1 and part=:2 and version=:3 order by piece# END OF STMT PARSE #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=775454461373 FETCH #4:c=0,e=18,p=0,cr=4,cu=0,mis=0,r=1,dep=1,og=4,tim=777069789450 FETCH #4:c=0,e=5,p=0,cr=1,cu=0,mis=0,r=0,dep=1,og=4,tim=777069789477 STAT #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 RANGE SCAN I_IDL_CHAR1 (cr=3 pr=0 pw=0 time=12 us)'
以"--"开头是人为添加的,在其它查询中可能存在,下面关键字段的含义:
1)PARSING IN CURSOR和END OF STMT包含了SQL语句文本;
2)PARSE、EXEC和FETCH分别表示解析(parse)、执行(execution)和获取(fetch)调用;
3)BINDS表示绑定变量的定义与值;
4)WAIT表示在处理过程汇总发生的等待事件;
5)STAT表示产生的执行计划以及相关的统计。
下面是更细致的一些解释(来自:Interpreting Raw SQL_TRACE and DBMS_SUPPORTSTART_TRACE output),由于Oracle每个版本都有差异,所以这些内容仅供参考。
-------------------------------------------------------------------------
PARSING IN CURSOR # len=X dep=X uid=X oct=X lid=X tim=X hv=X ad=‘X‘
SQL语句
END OF STMT
--------------------------------------------------------------------------
len:SQL语句长度
dep:游标递归调用的深度
uid:分析SQL的用户ID
oct:ORACLE命令类型
lid:特权用户id
tim:时间抽。ORACLE 9i以前,单位仅仅为1/100秒;ORACLE 9i之后单位为1/1000000秒。时间戳可以用来决定两点之间的时间间隔。该数值取自v$timer中的数值,可以用2个操作的‘tim‘差决定绝对时间
hv:SQL HASH ID(对应V$SQLAREA视图和V$SQLTEXT视图的HASH_VALUE字段)
ad:SQLTEXT地址(对应V$SQLAREA视图和V$SQLTEXT视图的ADDRESS字段)
--------------------------------------------------------------------------
PARSE ERROR #%d:len=%ld dep=%d uid=%ld oct=%d lid=%ld tim=%lu err=%d
SQL语句
--------------------------------------------------------------------------
len:SQL语句长度
dep:游标递归调用的深度
uid:分析SQL的用户ID
oct:ORACLE命令类型
tim:时间抽。同上
err:Oracle错误代码(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
--------------------------------------------------------------------------
操作:
1)PARSE:解析SQL
2)EXEC:执行已经分析的SQL
3)FETCH:从游标中获取记录
4)UNMAP:如果游标使用了临时表,当游标关闭的时候,该操作用来释放临时表资源(释放锁、删除状态对象、释放临时段等)。在tkprof产生的报告中,UNMAP的统计信息加入到EXECUTE操作的统计信息中。
5)SORT UNMAP:如上类似,但是为OS文件排序或者TEMP表段(segment)
c:CPU time(1/100秒在Oracle7、8和9)
e:Elapsed time(1/100秒在Oracle7、8,微秒在Oracle 9和之后版本)
p:物理读(Number of physical reads)
cr:CR(consistent read,一致性读)读的数量
cu:在当前模式(current mode)下读的数量
mis:cursor在缓存中错过的数量
r:涉及的记录数量
dep:递归调用深度(0 = user SQL,>0 = recursive)
og:优化器模式:1=All_Rows,2=First_Rows,3=Rule,4=Choose
tim:时间戳,用于确定两个操作之间的时间
--------------------------------------------------------------------------
ERROR #%d:err=%d tim=%lu
--------------------------------------------------------------------------
一个execution或者tetch错误后的错误展示
err:在堆栈顶的Oracle错误码(例如:ORA-XXXX)
tim:时间戳
--------------------------------------------------------------------------
STAT #<CURSOR> id=N cnt=0 [pid=0 pos=0 obj=0 op=‘SORT AGGREGATE ‘]
--------------------------------------------------------------------------
STAT:为<CURSOR>的执行计划统计报告
<CURSOR>:统计应用到的Cursor
id:执行计划中个操作在执行计划树中的编号
cnt:涉及的行数
pid:这行的父id
pos:在执行计划中的位置
obj:行的对象id(如果这是一个基本对象)
op:行涉及的操作
--------------------------------------------------------------------------
XCTEND rlbk=%d rd_only=%d
--------------------------------------------------------------------------
XCTEND:事务结束标志
rlbk:1表示rollback,0表示commit
rd_only:事务只读则是1,写则是0
注:下面的只有当WAITS或者BINDS出现时才存在
--------------------------------------------------------------------------
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:游标绑定变量
bind N:绑定变量位置
dty:数据类型
mxl:绑定变量最大长度
mal:数组长度
scl:规模(Scale)
pre:进度(precision)
oacflg:表明绑定选项的特定标志
oacfl2:oacflg的延续
size:为这块分配的内存
offset:为这个绑定缓存进入这块的偏移量
bfp:绑定地址
bln:绑定缓存长度
avl:实际值长度(也是数组长度)
flg:表明绑定状态的特定标志
value:绑定变量的实际值
--------------------------------------------------------------------------
WAIT #<CURSOR>: nam="" ela=0 p1=0 p2=0 p3=0
--------------------------------------------------------------------------
WAIT:等待事件信息
nam:等待事件名称
ela:操作花费的时间
p1:为等待事件提供的参数p1
p2:为等待事件提供的参数p2
p3:为等待事件提供的参数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 file scattered read"
解读:我们等待0.05秒。为一个读:文件4,开始块1435,共25块
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"
解读:我们等待0.04秒,为单块读(p3=1),从文件4,开始块1224