Oracle性能分析：开启SQL跟踪和获取trace文件
Oracle性能分析1：开启SQL跟踪和获取trace文件 当Oracle查询出现效率问题时，我们往往需要了解问题所在，这样才能针对问题给出解决方案。Oracle提供了SQL执行的trace信息，其中包含了SQL语句的文本信息，一些执行统计，处理过程中的等待，以及解析阶段（如生
Oracle性能分析1：开启SQL跟踪和获取trace文件
当Oracle查询出现效率问题时，我们往往需要了解问题所在，这样才能针对问题给出解决方案。Oracle提供了SQL执行的trace信息，其中包含了SQL语句的文本信息，一些执行统计，处理过程中的等待，以及解析阶段（如生成执行计划）产生的信息。这些信息有助于你分解sql语句的服 务时间和等待时间，并了解所用资源和同步点的详细信息，从而帮助你诊断存在的性能问题。
这篇文章介绍了怎么开启SQL跟踪和获取trace文件，详细信息如下。
开启SQL跟踪
从内部技术细节看，SQL跟踪是基于10046调试事件的，下面是支持的等级：
0
禁止调试事件
1
调试事件是激活的。针对每个被处理的数据库调用，给定如下信息：SQL语句、响应时间、服务时间
处理的行数、处理的行数、逻辑读数量、物理读与写的数量、执行计划以及一些额外信息
4
如果等级1，包括绑定变量的额外信息。主要是数据类型、精度以及每次执行时所用的值
8
同等级1，加上关于等待时间的细节信息。为了处理过程中的每个等待，提供如下信息：等待时间的名字、持续时间，以及一些额外的参数，可标明所等待的资源
12
同时启动等级4和等级8
在Oracle 9i或者之前，下面SQL语句针对所在会话激活SQL跟踪：
?
|
1 |
alter session set sql_trace = true |
还可通过dbms_session包中的set_sql_trace存储过程，或者通过dbms_system包的set_sql_tarce_in_session存储过程方法，但这些都只是在等级1激活SQL跟踪，在实践中用处不大，就不详述了。
更有用的是指定级别的方式，下面是对所在会话开始等级12的SQL跟踪：
?
|
1 |
alter session set events '10046 trace name context forever, level 12' |
对应的对所在会话禁止SQL跟踪的语句如下：
?
|
1 |
alter session set events '10046 trace name context off' |
也可以通过dbms_system包中的set_ev存储过程，这里也不详述了，我下面重点讲讲Oracle 10g之后提供的方法。
Oracle 10g之后提供了dbms_monitor包来开启或关闭SQL跟踪，提供了在会话、客户端、组件以及数据库层级开启SQL跟踪方法，注意只有dba角色的用户才允许使用。
会话级
下面的PL/SQL为ID为122，序列号为6734的会话开启第8级的SQL跟踪：
?
|
1 2 3 4 5 6 |
begin dbms_monitor.session_trace_enable(session_id => 122, serial_num => 6734, waits => true, binds => false); end; |
session_id
session标识，对应v$session视图中的SID列，下面是获取当前会话id的方法：
?
|
1 |
select userenv('sid') from dual |
serial_num
对应v$session视图中的SERIAL#列，由于SID会重用，当SID被重用时，SERIAL#增加，获取方法如下：
?
|
1 |
select serial# from v$session where sid = 122 |
waits
对应v$session视图中的SQL_TRACE_WAITS，表示等待事件跟踪是否被激活，默认为true。
binds
对应v$session视图中的SQL_TRACE_BINDS，表示绑定跟踪是否被激活，默认false。
当执行成功后，v$session视图中的SQL_TRACE被修改为ENABLED，SQL_TRACE_WAITS和SQL_TRACE_BINDS为你设置的对应值。
下面的PL/SQL用于关闭SQL跟踪：
?
|
1 2 3 |
begin dbms_monitor.session_trace_disable(session_id => 122, serial_num => 6734); end; |
客户端级
下面的PL/SQL调用为所有具有指定客户端标记的会话开启第8级的SQL跟踪：
?
|
1 2 3 4 5 |
begin dbms_monitor.client_id_trace_enable(client_id => 'test', waits => true, binds => false); end; |
需要注意客户端标记区分大小写，可以通过下面的方法看是否设置成功：
?
|
1 2 3 |
select primary_id as client_id, waits, binds from dba_enabled_traces where trace_type = 'CLIENT_ID' |
当设置成功后，每次查询前指定对应的客户端标记就可以开启SQL跟踪，指定客户端标记的方法如下：
?
|
1 2 3 4 |
begin DBMS_SESSION.SET_IDENTIFIER('test'); end; //该会话的SQL跟踪已经开启 |
当你为一个session设置了标记后，可以在v$session的client_identifier列查看该标记。
下面的PL/SQL用于关闭SQL跟踪：
?
|
1 2 3 |
begin dbms_monitor.client_id_trace_disable(client_id => 'test'); end; |
组件级
下面的PL/SQL调用为所有具有指定客户端标记的会话开启第8级的SQL跟踪：
?
|
1 2 3 4 5 6 7 8 |
begin dbms_monitor.serv_mod_act_trace_enable(service_name => 'ly', module_name => 'PL/SQL Developer', action_name => 'SQL 窗口 - 新建', waits => true, binds => false, instance_name => null); end; |
参数中的service_name对应v$session视图的service_name，module_name对应v$session视图的的module，action_name对应v$session视图的action，查询方式如下：
?
|
1 2 3 |
SELECT sid, serial#, client_identifier, service_name, action, module FROM V$SESSION |
设置之后可以通过如下方法查看设置：
?
|
1 2 3 4 5 6 7 |
select primary_id as service_name, qualifier_id1 as module_name, qualifier_id2 as action_name, waits, binds from dba_enabled_traces where trace_type = 'SERVICE_MODULE_ACTION' |
下面的PL/SQL用于关闭SQL跟踪：
?
|
1 2 3 4 5 6 |
begin dbms_monitor.serv_mod_act_trace_disable(service_name => 'ly', module_name => 'PL/SQL Developer', action_name => 'SQL 窗口 - 新建', instance_name => null); end; |
数据库级
下面的PL/SQL调用开启了数据库的12级SQL跟踪：
?
|
1 2 3 4 5 |
begin dbms_monitor.database_trace_enable(waits => true, binds => true, instance_name => null); end; |
下面的方法查看设置是否成功：
?
|
1 2 3 4 5 |
select instance_name, waits, binds from dba_enabled_traces where trace_type = 'DATABASE' |
下面的PL/SQL用于关闭SQL跟踪：
?
|
1 2 3 |
begin dbms_monitor.database_trace_disable(instance_name => null); end; |
trace文件中的计时信息
下面的语句用于为trace文件提供计时信息：
?
|
1 |
alter session set timed_statistics = true |
一般情况下默认都为true，如果不提供计时信息，trace文件就没有什么用了，因此开启SQL跟踪之前，最好确认一下参数被设置为true。
获取生成的trace文件
开启SQL跟踪后，会生成一个trace文件，通过初始化参数user_dump_dest配置其所在目录，该参数的值可以通过下面方法获取到：
?
|
1 |
select name, value from v$parameter where name = 'user_dump_dest' |
但如果我们需要定位到具体的文件，则需要了解trace文件的命名。trace文件的名字是独立于版本和平台的，在大部分常见的平台下，命名结构如下：
{instance name}_{process name}_{process id}.trc
1）instance name
初始化参数instance_name的小写值。通过v$instance视图的instance_name列可以得到这个值。
2）process name
产生跟踪文件进程的名字的小写值。对于专有服务器进程，使用ora，对于共享服务器进程，可以通过v$diapatcher或 v$shared_server视图的name列获得。对于并行从属进程，可以通过v$px_process视图server_name列获得，对于其他 多数后台进程来说，可以通过v$bgprocess视图的name列获得。
3）process id
操作系统层面的进程标记。这个值可以通过v$process视图的spid列获取。
根据这些信息，可以通过下面的方式获取trace文件名：
?
|
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 |
select s.SID, s.SERVER, lower(case when s.SERVER in ('DEDICATED', 'SHARED') then i.INSTANCE_NAME || '_' || nvl(pp.SERVER_NAME, nvl(ss.NAME, 'ora')) || '_' || p.SPID || '.trc' else null end) as trace_file_name from v$instance i, v$session s, v$process p, v$px_process pp, v$shared_server ss where s.PADDR = p.ADDR and s.SID = pp.SID(+) and s.PADDR = ss.PADDR(+) and s.TYPE = 'USER' and s.SID = 'your sid' order by s.SID |
将上面的'your sid'替换为你的session的sid就可以查出指定session生成的trace文件的名字，session的sid在v$session视图中得到，或者直接查询当前session的sid：
?
|
1 |
select userenv('sid') from dual |
将路径（user_dump_dest）和文件名结合在一起，我们就得到了trace文件的完整路径。
而在Oracel 11g中，查询当前会话生成的trace文件则非常简单：
?
|
1 |
select value from v$diag_info where name = 'Default Trace File' |
Oracle性能分析2：trace文件解读
下面是trace文件中的一个片段，表示一个SQL执行的过程，一个trace文件由很多这样的片段组成：
?
|
1 2 3 4 5 6 7 8 9 10 11 |
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 andDBMS_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，微秒在Oracle9和之后版本）
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 #
--------------------------------------------------------------------------
STAT：为
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=24offset=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 #
--------------------------------------------------------------------------
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
参见：
http://www.2cto.com/database/201408/326439.html