Oracle性能分析2：trace文件解读

下面是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