数据库性能问题诊断与分析

1.SQL_TRACE及10046事件的基础介绍

SQL_TRACE/10046事件是oracle提供的用于进行SQL跟踪的手段，是强有力的辅助诊断工具。当在数据库中启用SQL_TRACE或者设置10046事件后，Oracle将会启动内核跟踪程序，持续记录会话的相关信息，并写入到相应的trace文件中。跟踪记录的内容包括SQL的解析过程、SQL的执行计划、绑定变量的使用以及会话中发生的等待事件等。

1.1在全局启用SQL_TRACE

可以通过sql命令启动SQL_TRACE，或者在初始化参数里面。

SQL> alter database set sql_trace=true;

在全局启用SQL_TRACE会导致所有的进程的活动被跟踪，包括后台进程和所有用户进程，这通常会导致比较严重的性能问题，所以在生产环节中要谨慎使用。

1.2在当前session级设置

SQL>alter session set sql_trace=true;

大多数时候使用SQL_TRACE来跟踪当前进程。通过跟踪当前进程可以发现当前操作的后台数据库的递归活动，研究SQL执行及发现后台错误等。
此时的SQL操作将被跟踪：

SQL> select count(*)  from dba_users;
  COUNT(*)
----------
        49

结束跟踪：

SQL>alter session set sql_trace=false;

在session级别设置，只对当前session进行跟踪，在实例级别，会对实例上所有的SQL做跟踪，这种方式跟踪的SQL太多，代价是非常大的，所有很少用。如果是在初始化文件里面设置，只需要在参数文件里添加一个sql_trace 参数即可。

1.3跟踪其他用户进程

在很多时候需要跟踪其他用户的进程，而不是当前用户，可以通过Oracle提供的系统包DBMS_SYSTEM.SET_SQL_TRACE_IN_SESSION来完成。

1）trace文件的路径

启用sql_trace前我们首先要确定跟踪文件的存放位置，即user_dump_dest下

SQL> show parameter user_dump_dest;
NAME                                 TYPE        VALUE
------------------------------------ ----------- ------------------------------
user_dump_dest                 string      f:\app\administrator\diag\rdbms\orcl\orcl\trace

其中user_dump_dest,instance_name的值可以通过show命令得到，backgroudProcessID的值就需要首先获取session的sid然后根据sid的值查询v$session中进程的地址，然后根据进程地址找到processID，在11G以前可以通过下面这个语句获取当前session的sql_trace文件的路径

SQL> select
a.value || '/' || b.instance_name || '_ora_' || c.spid || '.trc' trace_file
from
(select value from v$parameter where name= 'user_dump_dest') a,
(select instance_name from v$instance) b,
(select spid from v$process where addr=(select paddr from v$session where sid=(select distinct sid from v$mystat))) c;
TRACE_FILE
--------------------------------------------------------------------------------
f:\app\administrator\diag\rdbms\orcl\orcl\trace/orcl_ora_10680.trc

在11g以后v$process视图里面tracefile 字段直接给出了这个值，因此不需要写上面那么麻烦的语句

SQL> select tracefile from v$process where addr=(select paddr from v$session where sid=(select distinct sid from v$mystat));

另外也可以手工更改产生trace文件的名称例如

SQL> alter session set tracefile_identifier='测试组'

2) 通过查询v$session可以获得SID/SERIAL等信息，获得进程信息后，选择需要跟踪的进程，设置跟踪。

SQL> select sid,serial# ,username from v$session where username is not  null;

设置跟踪：

SQL> exec dbms_system.set_sql_trace_in_session(63,52173,true);

停止跟踪：

SQL> exec dbms_system.set_sql_trace_in_session(63,52173,false);

3）查看trace文件信息

如果你想确切地知道sql语句的每一步执行时如何操作的，就需要分析原始的trace文件，下面给出了这条sql语句的关键部分

Trace file f:\app\administrator\diag\rdbms\orcl\orcl\trace\orcl_ora_11584.trc
Oracle Database 11g Enterprise Edition Release 11.2.0.1.0 - 64bit Production
With the Partitioning, OLAP, Data Mining and Real Application Testing options
Windows NT Version V6.1 Service Pack 1 
CPU                 : 4 - type 8664, 2 Physical Cores
Process Affinity    : 0x0x0000000000000000
Memory (Avail/Total): Ph:2714M/8092M, Ph+PgF:9477M/16182M 
Instance name: orcl
Redo thread mounted by this instance: 1
Oracle process number: 29
Windows thread id: 11584, image: ORACLE.EXE (SHAD)


*** 2017-06-20 14:41:50.548
*** SESSION ID:(63.52173) 2017-06-20 14:41:50.548
*** CLIENT ID:() 2017-06-20 14:41:50.548
*** SERVICE NAME:(orcl) 2017-06-20 14:41:50.548
*** MODULE NAME:(w3wp.exe) 2017-06-20 14:41:50.548
*** ACTION NAME:() 2017-06-20 14:41:50.548
 
CLOSE #2:c=0,e=27,dep=0,type=1,tim=368624802714
=====================
PARSING IN CURSOR #3 len=154 dep=0 uid=102 oct=3 lid=102 tim=368624807375 hv=2174186802 ad='7ffbee326f0' sqlid='1x22q820tfx9k'
select * from SYS_ROLE  where exists (select ROLE_ID from sys_user_role where sys_user_role.ROLE_ID=SYS_ROLE.ROLE_ID and sys_user_role.user_id=:"SYS_B_0")
END OF STMT
PARSE #3:c=0,e=1135,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=1,plh=0,tim=368624807374
EXEC #3:c=0,e=1984,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=3232332846,tim=368624809497
FETCH #3:c=0,e=164,p=0,cr=9,cu=0,mis=0,r=1,dep=0,og=1,plh=3232332846,tim=368624810883
STAT #3 id=1 cnt=1 pid=0 pos=1 obj=0 op='NESTED LOOPS  (cr=9 pr=0 pw=0 time=0 us)'
STAT #3 id=2 cnt=1 pid=1 pos=1 obj=0 op='NESTED LOOPS  (cr=8 pr=0 pw=0 time=0 us cost=5 size=101 card=1)'
STAT #3 id=3 cnt=1 pid=2 pos=1 obj=0 op='SORT UNIQUE (cr=7 pr=0 pw=0 time=0 us cost=3 size=29 card=1)'
STAT #3 id=4 cnt=1 pid=3 pos=1 obj=92656 op='TABLE ACCESS FULL SYS_USER_ROLE (cr=7 pr=0 pw=0 time=0 us cost=3 size=29 card=1)'
STAT #3 id=5 cnt=1 pid=2 pos=2 obj=92648 op='INDEX UNIQUE SCAN PK_SYS_ROLE (cr=1 pr=0 pw=0 time=0 us cost=0 size=0 card=1)'
STAT #3 id=6 cnt=1 pid=1 pos=2 obj=92647 op='TABLE ACCESS BY INDEX ROWID SYS_ROLE (cr=1 pr=0 pw=0 time=0 us cost=1 size=72 card=1)'
CLOSE #3:c=0,e=18,dep=0,type=0,tim=368624812253

我们看到Oracle首先对这条sql语句做分析，并且有一个游标号CURSOR #3，这个在整个trace文件中不是唯一的，当一条sql语句执行完毕后，这个号会被另外一个sql语句重用
我们还可以看到这条sql语句被分析了一次，执行了一次，fetch了1次，stat#3是对这条sql语句执行过程中的资源消耗的统计，这些输出顺序就是sql语句的执行顺序，通过这些顺序就可以了解到sql语句是如何一步一步执行的。
下面是列出了这些指标的解释

==PARSING IN CURSOR 部分==

len：被分析sql的长度
dep：产生递归sql的深度
uid：user id
otc：Oracle command type命令的类型
lid：私有用的id
tim：时间戳
hv： hash value
ad： sql address

==PARSE，EXEC，FETCH部分==

c: 消耗的cpu time
e：elapsed time 操作的用时
p：physical reads次数
cr：consistent reads数据的块
cu：current方式读取的数据块
mis：cursor miss in canche硬分析次数
r：rows处理的行数
dep：depth递归sql的深度
og：optimize goal优化器模式
tim：timstamp时间戳

==stats部分==

id：执行计划的行源号
cnt：当前行源返回的行数
pid：当前行源的父号
pos：执行计划中的位置
obj：当前操作的对象id
op：当前行源的数据访问操作

2.10046事件说明

10046事件是Oracle提供的内部事件，是对SQL_TRACE的增强。
10046事件可以设置一下4个级别：

1）Level 1：启用标准的SQL_TRACE功能，等同于sql_trace的功能。
2）Level 4 在Level 1的基础上收集绑定变量的信息
3）level 8 在Level 1的基础上增加了等待事件的信息
4）level12 等同于Level 4 + Level *，集同时收集绑定变量和等待事件信息

可以看出level级别越高，收集的信息越全面，我们用下面例子来分别看下这几个级别的作用

2.1 LEVEL 4

--首先查询trace文件路径

SQL> select tracefile from v$process where addr=(select paddr from v$session where sid=(select distinct sid from v$mystat));
SQL> create table test as select * from dba_objects;
SQL> exec dbms_stats.gather_table_stats('sys','test');

--设定10046事件的级别为4

SQL> alter session set events '10046 trace name context forever,level 4';

--定义2个变量x，y

SQL> var x number;
SQL> var y varchar2(10);
SQL> exec :x := 20;
SQL> exec :y :='TEST';

--通过绑定变量查询表

SQL> select object_id,object_name from test where object_id=:x or object_name=:y;

这样就完成了使用10046事件做SQL trace的工作，注意，LEVEL 4获取的绑定变量的信息只能在原始的trace文件里面获取，在通过tkprof工具格式化后是看不到的，下面是这条sql在原始文件中的关键部分。

2.2 LEVEL8

--打开另外一个session 2 模拟TX - row lock contention等待事件

SQL> update test set object_id=10 where object_name='TEST';

--更新同一行，这个时候session就被另外一个session阻塞了

SQL> update test set object_id=20 where object_name='TEST';

--等待1分钟后，在session 2 commit

SQL> commit;

--回到session 通过绑定变量做查询

SQL> var x number;
SQL> var y varchar2(10);
SQL> exec :x := 20;
SQL> exec :y :='TEST';
SQL> col object_name for a10;
SQL> select object_id,object_name from test where object_id=:x or object_name=:y;
SQL> alter session set events '10046 trace name context off';

3.ORACLE TKPROF使用

Tkprof是一个用于分析Oracle跟踪文件并且产生一个更加清晰合理的输出结果的可执行工具。如果一个系统的执行效率比较低，一个比较好的方法是通过跟踪用户的会话并且使用Tkprof工具使用排序功能格式化输出，从而找出有问题的SQL语句。

3.1 TKPROF 命令语法：

TKPROF filename1, filename2 [ SORT = [ opion][,option] ]
[ PRINT = integer ]
[ AGGREGATE = [ YES | NO ] ]
[ INSERT = filename3 ]
[ SYS = [ YES | NO ] ]
[ [ TABLE = schema.table ] | [ EXPLAIN = user/password ] ]
[ RECORD = filename ]

3.2 对Tkprof命令输出的解释

SQL处理的不同的阶段

image

CALL：每次SQL语句的处理都分成三个部分
Parse：这步将SQL语句转换成执行计划，包括检查是否有正确的授权和所需要用到的表、列以及其他引用到的对象是否存在。
Execute：这步是真正的由oracle来执行语句。对于insert、update、delete操作，这步会修改数据，对于select操作，这步就只是确定选择的记录。
Fetch：返回查询语句中所获得的记录，这步只有select语句会被执行。
COUNT:这个语句被parse、execute、fetch的次数。
CPU：这个语句对于所有的parse、execute、fetch所消耗的cpu的时间，以秒为单位。
ELAPSED：这个语句所有消耗在parse、execute、fetch的总的时间。
DISK：从磁盘上的数据文件中物理读取的块的数量。一般来说更想知道的是正在从缓存中读取的数据而不是从磁盘上读取的数据。
QUERY：在一致性读模式下，所有parse、execute、fetch所获得的buffer的数量。一致性模式的buffer是用于给一个长时间运行的事务提供一个一致性读的快照，缓存实际上在头部存储了状态。
CURRENT：在current模式下所获得的buffer的数量。一般在current模式下执行insert、update、delete操作都会获取buffer。在current模式下如果在高速缓存区发现有新的缓存足够给当前的事务使用，则这些buffer都会被读入了缓存区中。
ROWS: 所有SQL语句返回的记录数目，但是不包括子查询中返回的记录数目。对于select语句，返回记录是在fetch这步，对于insert、update、delete操作，返回记录则是在execute这步。

3.3 使用Tkprof命令分析trace文件