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 #<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=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 #<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
参见:
http://www.2cto.com/database/201408/326439.html