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 # id=N cnt=0 [pid=0 pos=0 obj=0 op='SORT AGGREGATE ']
--------------------------------------------------------------------------
STAT：为的执行计划统计报告
：统计应用到的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=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 #: 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
参见：
http://www.2cto.com/database/201408/326439.html
