欢迎您访问程序员文章站本站旨在为大家提供分享程序员计算机编程知识!
您现在的位置是: 首页  >  数据库

Oracle性能分析:开启SQL跟踪和获取trace文件

程序员文章站 2022-05-10 14:53:49
...

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