新博客http://www.cnblogs.com/zhjh256 欢迎访问
分类： Oracle
2008-01-22 21:15:13
SQL调优中最有价值的五个工具是：SQL_TRACE,TKPROF, autotrace, 10046 event，EXPLAIN PLAN。它们会告诉你提交到数据库的SQL语句，运行使用的执行计划，执行计划中每一步骤所处理后返回的行数，返回给客户端的行数，为了得到结果集执行的推进次数，每一步骤花费的CPU，以及使用的墙上时钟时间（延时）。
通常这些工具会交互使用，而不是单独的使用。另外在进行SQL调优时，理解系统的业务，以及数据的分布很重要，只有这样才能理解优化器是否按照预计的方式执行以及出错的位置。
SQL Trace和TKPROF
SQL Trace可以提供单独SQL语句的性能信息。对于执行的每一个SQL语句，SQL Trace会在跟踪文件中写入以下信息：
·解析，执行，推进的次数；
·CPU和延迟时间；
·物理读和逻辑读；
·是否为硬解析；
·每次执行解析的用户；
·每一个提交和回滚；
不过在开发环境下，通常最关注的应该是物理读和逻辑读，CPU时间。至于解析，执行，推进，延迟等等相关的信息并没有实质的意义。因为我觉得对于开发环境来讲，真实的生产环境是不可能模拟的，一个生产环境可能并发用户数高达上千，而生产环境则很少很能够达到100。并且在开发环境而言，解析也没有意义，因为开发人员在调整SQL时基本上会产生解析。因为物理读多必然导致逻辑读的增加，逻辑读的增加必然导致SQL执行使用更多的CPU时间（逻辑读是CPU密集型操作），而且在生产环境下也是这种关系。
解析，执行，推进，延迟等等相关的信息应该在生产环境下通过STATSPACK，TOP sql，以及OWI等进行捕获并解决。
SQL Trace应该在会话级别启用，因为其代价是很昂贵的。
对于初学者而言，通常TKPROF和SQL Trace一起使用，以产生可读性报告。并且TKPROF还可以执行以下任务：
·确定SQL的执行计划；
·创建一个SQL脚本存储统计在数据库中；
TKPROF能够报告每个执行的SQL以及消耗的资源，调用的次数，以及处理的行数。这样就可以很容易的定位那些消耗资源最多的SQL。
使用SQL Trace和TKPROF的总体步骤如下：
1． 首先设置初始化参数；
2． 对特定的会话启用跟踪；
3． 运行TKPROF；
4． 推断TKPROF的输出文件；
5． 可以考虑运行SQL创建统计存储在数据库，通常会比较有用；
设置初始化参数
1． 检查TIMED_STATISTICS, MAX_DUMP_FILE_SIZE,USER_DUMP_DEST；
首先应该确保TIMED_STATISTICS为TRUE，这样Oracle才会纪录时间相关的信息，如果该参数为false，将不会纪录（默认），这样的话查看执行情况当然也就没有意义。通常在实例级别启用该参数，因为其代价很小。在Oracle9i中，这是一个动态参数，也是会话参数；
MAX_DUMP_FILE_SIZE，应该确保跟踪目录足够大，否则输出会被截断；这也是会话参数；
USER_DUMP_DEST，用户跟踪的目录，即跟踪文件存储的位置；这也是会话参数；
注：如果STATISTICS_LEVEL为TYPICAL或者ALL，时间统计会自动收集；否则，如果为BASIC，则必须设置为TRUE才能启用；
2． 识别结果跟踪文件的位置，可以使用以下SQL查找跟踪文件名，不过通常比较简单的方法是查看最近产生的文件：
NT:
SELECT s.sid,
s.serial#,
pa.value || '\' || LOWER(SYS_CONTEXT('userenv', 'instance_name')) ||
'_ora_' || p.spid || '.trc' AS trace_file
FROM v$session s, v$process p, v$parameter pa
WHERE pa.name = 'user_dump_dest'
AND s.paddr = p.addr
AND s.audsid = SYS_CONTEXT('USERENV', 'SESSIONID');
UNIX：
SELECT s.sid,
s.serial#,
pa.value || '/' || LOWER(SYS_CONTEXT('userenv', 'instance_name')) ||
'_ora_' || p.spid || '.trc' AS trace_file
FROM v$session s, v$process p, v$parameter pa
WHERE pa.name = 'user_dump_dest'
AND s.paddr = p.addr
AND s.audsid = SYS_CONTEXT('USERENV', 'SESSIONID');
3． 产生的跟踪文件通常是OS拥有，因此用户需要在TKPROF之前使跟踪文件可访问；通常应该是拷贝到其他目录即可；
启用SQL Trace工具
为会话启用的方法：
·DBMS_SESSION.SET_SQL_TRACE；
·ALTER SESSION SET SQL_TRACE = TRUE;
通过DBMS_SYSTEM.SET_SQL_TRACE_IN_SESSION可以在其他会话上启用SQL跟踪；
要停止跟踪，只需要执行ALTER SESSION SET SQL_TRACE = FALSE;即可；另外当应用程序断开时，SQL Trace也会自动停止。
要在实例识别启用，设置SQL_TRACE = TRUE。
使用TKPROF格式化输出
TKPROF可以接受一个/多个跟踪文件作为输入。产生一个会话/整个实例的输出。
其中TKPROF几个比较有用的选项如下：
·WAITS：YES，NO。声明是否记录等待事件；
·SORTS：这个选项主要指示按照特定的度量标准进行将序排序，比如解析花费的CPU: PRSCPU,解析的延时：PRSELA，解析期间物理读的数量：PRSDSK，是否为硬解析，PRSMIS等等。完整的列表可以参照联机文档。
·EXPLAIN：是否包含执行计划；通常要连接到正确的用户才能确保结果的正确。
·RECORD：创建一个SQL脚本包含所有的非递归SQL，通常如果使用默认的选项会包含很多的递归SQL，可以使用该选项单独创建一个。
·PRINT：表示输出的语句数，如PRINT=0表示根据SORT的排序后输出前10个语句；
推断TKPROF的输出
TKPROF中的Tabular统计
TKPROF回列出每个SQL语句的统计，每行响应于一个SQL处理的三个步骤中的一个，统计通过CALL列的值来进行识别。三个步骤是：PARSE，EXECUTE，FETCH。
SQL Trace的统计包括：
COUNT：语句解析，执行，推进的次数；
CPU：语句解析，执行，推进的CPU耗用时间；
ELAPSED：语句解析，执行，推进的墙上时钟延时时间；
DISK：磁盘读取的块数；
QUERY：一致性读的缓冲数，即块数；
CURRENT：当前模式读的块数；
其中QUERY和current的总和称为逻辑读。
ROWS：SQL语句处理的行数，不包括子查询处理的行数；
通常SELECT的处理行数在fetch的步骤，UPDATE, DELETE, INSERT则在execute步骤。
统计的时间单元通常以0.01秒为单位。因此这需要额外小心。
递归调用
通常如果递归SQL执行的开销比较大，也需要仔细研究。不过在开发环境中因为实际的限制，应该很难确定是否有问题，不过最重要的应该是确定执行一个SQL的全部递归调用的代价，这也可以作为一种度量标准进行调优，以尽可能的较少递归调用，如果开发环境配置的好，还可以作为生产环境SQL调优的标准。
TKPROF中的硬解析
如果不需要硬解析，TKPROF不会提示。通常只有在生产环境中这种情况才会有现实意义，在开发环境是没有意义的。不过通常需要考虑解析调用的次数；因为软解析太多也不好。
SQL Trace中的语句截断
SET ROLE、GRANT、ALTER USER、ALTER ROLE、CREATE USER、CREATE ROLE等会话语句会被截断为25个字符。
标识TKPROF中执行SQL的会话
如果TKPROF中包含多个会话的SQL语句，TKPROF回列出执行SQL语句的会话的ID，是ALL_USERS.USER_ID。
TKPROF中的执行计划
TKPROF会在其中的执行计划的每一步显示处理的行数。
确定要调整的SQL语句
一般来说是找CPU或磁盘资源最大的SQL语句调整，这些资源的代价通常会很大。
在出现锁问题和低效的PL/SQL循环时，通常无法通过CPU时间或者延时时间进行确定问题。这个时候关键就是块访问的次数，包括一致性读和当前读。
存储SQL Trace统计
TKPROF可以产生一个SQL脚本创建一个表并插入数据。该脚本的内容如下：
·CREATE TABLE创建一个TKPROF_TABLE表；
·包含行统计的INSERT语句；
只要在运行TKPROF时包含INSERT选项，将一个文件名作为参数即可。
TKPROF_TABLE表中的大部分列基本上与格式化输出文件中的统计直接对应。用于识别行统计的列包括如下：
·SQL_STATEMENT，收集行统计的SQL语句；
·DATE_OF_INSERT，将统计插入表的时间，而不是收集的时间；
·DEPTH：递归SQL的深度，0表示用户执行的SQL语句；
·USER_ID：执行SQL语句的用户；
·CURSOR_NUM：Oracle用来跟踪分配语句的游标；
TKPROF的陷阱
避免参数陷阱
如果没有意识到运行时绑定的值，可能会掉入这个陷阱。EXPLAIN PLAN无法从SQL语句确定绑定变量值得类型，并且总假设为varchar。如果事实上是DATE类型，则TKPROF会导致隐示数据类型转换，导致非高效的执行计划（不过通常这和索引列有关系，一般的列应该不会有关系）。
因此应该测试各种不同的数据类型，并且自己执行转换。
避免读一致性陷阱
这通常是由于未提交的很多DML事务引起的。
避免时间陷阱
这通常出现在CPU时间和延时时间的非常大，但是磁盘读和一致性读并不大。通常是由于其他事务的干涉引起的，如锁。应该另外捕获一个跟踪，不过更应该研究哪个会话，哪个事务，哪个SQL引起的。
避免触发器陷阱
如果DML消耗的资源远远超过了预计的代价，应该检查是否有触发器或者约束之类的低级别的SQL造成的。
TKPROF例子
Dump file d:\oracle\product\10.2.0\admin\test\udump\test_ora_4464.trc
Tue Jan 22
ORACLE V10.2.0.1.0 - Production vsnsta=0
vsnsql=14 vsnxtr=3
Oracle Database 10g
With the Partitioning, OLAP and Data Mining options
Windows XP Version V5.1 Service Pack 2
CPU : 1 - type 586
Process Affinity : 0x00000000
Memory (Avail/Total): Ph:52M/502M, Ph+PgF:384M/1642M, VA:1636M/2047M
Instance name: test
Redo thread mounted by this instance: 1
Oracle process number: 30
Windows thread id: 4464, image: ORACLE.EXE (SHAD)
*** ACTION NAME:(Command Window - New) 2008-01-22 13:05:12.043
*** MODULE NAME:(PL/SQL Developer) 2008-01-22 13:05:12.043
*** SERVICE NAME:(TEST) 2008-01-22 13:05:12.043
*** SESSION ID:(130.3498) 2008-01-22 13:05:12.043
=====================
PARSING IN CURSOR #2 len=34 dep=0 uid=5 oct=42 lid=5 tim=2597314995841 hv=2584034267 ad='6691b57c'
ALTER SESSION SET SQL_TRACE=TRUE
END OF STMT
EXEC #2:c=0,e=435,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=1,tim=2597314995836
=====================
PARSING IN CURSOR #1 len=61 dep=0 uid=5 oct=47 lid=5 tim=2597315107942 hv=356401299 ad='6685f1a4'
begin :id := sys.dbms_transaction.local_transaction_id; end;
END OF STMT
PARSE #1:c=0,e=45,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,tim=2597315107936
EXEC #1:c=0,e=122,p=0,cr=0,cu=0,mis=0,r=1,dep=0,og=1,tim=2597315113996
=====================
PARSING IN CURSOR #2 len=28 dep=0 uid=5 oct=3 lid=5 tim=2597318203402 hv=2848210951 ad='669ac9d4'
select :"SYS_B_0" from dual
END OF STMT
PARSE #2:c=0,e=98,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,tim=2597318203397
EXEC #2:c=0,e=51,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,tim=2597318209435
FETCH #2:c=0,e=30,p=0,cr=0,cu=0,mis=0,r=1,dep=0,og=1,tim=2597318213833
STAT #2 id=1 cnt=1 pid=0 pos=1 obj=0 op='FAST DUAL (cr=0 pr=0 pw=0 time=11 us)'
=====================
PARSING IN CURSOR #1 len=61 dep=0 uid=5 oct=47 lid=5 tim=2597318222412 hv=356401299 ad='6685f1a4'
begin :id := sys.dbms_transaction.local_transaction_id; end;
END OF STMT
PARSE #1:c=0,e=46,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,tim=2597318222406
EXEC #1:c=0,e=115,p=0,cr=0,cu=0,mis=0,r=1,dep=0,og=1,tim=2597318229004
=====================
PARSING IN CURSOR #2 len=243 dep=0 uid=5 oct=3 lid=5 tim=2597318234464 hv=1663762426 ad='66a377b8'
select last_name, department_name, salary
from hr.employees e, hr.departments d, hr.locations l
where l.location_id = d.location_id
and d.department_id = e.department_id
and l.city = :"SYS_B_0"
and e.salary > :"SYS_B_1"
order by salary desc
END OF STMT
PARSE #2:c=0,e=825,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=1,tim=2597318234459
=====================
PARSING IN CURSOR #1 len=42 dep=1 uid=0 oct=3 lid=0 tim=2597318253308 hv=844002283 ad='6cda7f3c'
select condition from cdef$ where rowid=:1
END OF STMT
PARSE #1:c=0,e=63,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,tim=2597318253303
EXEC #1:c=0,e=42,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,tim=2597318260069
FETCH #1:c=0,e=42,p=0,cr=2,cu=0,mis=0,r=1,dep=1,og=4,tim=2597318261478
STAT #1 id=1 cnt=1 pid=0 pos=1 obj=31 op='TABLE ACCESS BY USER ROWID CDEF$ (cr=1 pr=0 pw=0 time=33 us)'
EXEC #2:c=15625,e=17867,p=0,cr=2,cu=0,mis=1,r=0,dep=0,og=1,tim=2597318270284
FETCH #2:c=0,e=42996,p=7,cr=137,cu=0,mis=0,r=12,dep=0,og=1,tim=2597318315506
STAT #2 id=1 cnt=12 pid=0 pos=1 obj=0 op='SORT ORDER BY (cr=137 pr=7 pw=0 time=43028 us)'
STAT #2 id=2 cnt=12 pid=1 pos=1 obj=51910 op='TABLE ACCESS BY INDEX ROWID EMPLOYEES (cr=137 pr=7 pw=0 time=43030 us)'
STAT #2 id=3 cnt=40 pid=2 pos=1 obj=0 op='NESTED LOOPS (cr=25 pr=3 pw=0 time=1042416 us)'
STAT #2 id=4 cnt=21 pid=3 pos=1 obj=0 op='NESTED LOOPS (cr=4 pr=2 pw=0 time=23125 us)'
STAT #2 id=5 cnt=1 pid=4 pos=1 obj=51900 op='TABLE ACCESS BY INDEX ROWID LOCATIONS (cr=2 pr=1 pw=0 time=18136 us)'
STAT #2 id=6 cnt=1 pid=5 pos=1 obj=51902 op='INDEX RANGE SCAN LOC_CITY_IX (cr=1 pr=1 pw=0 time=18107 us)'
STAT #2 id=7 cnt=21 pid=4 pos=2 obj=51905 op='TABLE ACCESS BY INDEX ROWID DEPARTMENTS (cr=2 pr=1 pw=0 time=4886 us)'
STAT #2 id=8 cnt=21 pid=7 pos=1 obj=51907 op='INDEX RANGE SCAN DEPT_LOCATION_IX (cr=1 pr=1 pw=0 time=4723 us)'
STAT #2 id=9 cnt=18 pid=3 pos=2 obj=51913 op='INDEX RANGE SCAN EMP_DEPARTMENT_IX (cr=21 pr=1 pw=0 time=4168 us)'
=====================
PARSING IN CURSOR #1 len=61 dep=0 uid=5 oct=47 lid=5 tim=2597318353523 hv=356401299 ad='6685f1a4'
begin :id := sys.dbms_transaction.local_transaction_id; end;
END OF STMT
PARSE #1:c=0,e=48,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,tim=2597318353516
EXEC #1:c=0,e=115,p=0,cr=0,cu=0,mis=0,r=1,dep=0,og=1,tim=2597318361888
*** 2008-01-22 13:05:30.715
=====================
PARSING IN CURSOR #2 len=28 dep=0 uid=5 oct=3 lid=5 tim=2597333675447 hv=2848210951 ad='669ac9d4'
select :"SYS_B_0" from dual
END OF STMT
PARSE #2:c=0,e=89,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,tim=2597333675442
EXEC #2:c=0,e=61,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,tim=2597333688502
FETCH #2:c=0,e=29,p=0,cr=0,cu=0,mis=0,r=1,dep=0,og=1,tim=2597333690678
STAT #2 id=1 cnt=1 pid=0 pos=1 obj=0 op='FAST DUAL (cr=0 pr=0 pw=0 time=11 us)'
=====================
PARSING IN CURSOR #1 len=61 dep=0 uid=5 oct=47 lid=5 tim=2597333702588 hv=356401299 ad='6685f1a4'
begin :id := sys.dbms_transaction.local_transaction_id; end;
END OF STMT
PARSE #1:c=0,e=47,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,tim=2597333702582
EXEC #1:c=0,e=157,p=0,cr=0,cu=0,mis=0,r=1,dep=0,og=1,tim=2597333713402
=====================
PARSING IN CURSOR #2 len=243 dep=0 uid=5 oct=3 lid=5 tim=2597333716023 hv=1663762426 ad='66a377b8'
select last_name, department_name, salary
from hr.employees e, hr.departments d, hr.locations l
where l.location_id = d.location_id
and d.department_id = e.department_id
and l.city = :"SYS_B_0"
and e.salary > :"SYS_B_1"
order by salary desc
END OF STMT
PARSE #2:c=0,e=227,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,tim=2597333716018
=====================
PARSING IN CURSOR #1 len=42 dep=1 uid=0 oct=3 lid=0 tim=2597333739232 hv=844002283 ad='6cda7f3c'
select condition from cdef$ where rowid=:1
END OF STMT
PARSE #1:c=0,e=24,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,tim=2597333739227
EXEC #1:c=0,e=46,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,tim=2597333752260
FETCH #1:c=0,e=42,p=0,cr=2,cu=0,mis=0,r=1,dep=1,og=4,tim=2597333753981
STAT #1 id=1 cnt=1 pid=0 pos=1 obj=31 op='TABLE ACCESS BY USER ROWID CDEF$ (cr=1 pr=0 pw=0 time=30 us)'
EXEC #2:c=31250,e=26481,p=0,cr=2,cu=0,mis=1,r=0,dep=0,og=1,tim=2597333764241
FETCH #2:c=0,e=948,p=0,cr=137,cu=0,mis=0,r=12,dep=0,og=1,tim=2597333767759
STAT #2 id=1 cnt=12 pid=0 pos=1 obj=0 op='SORT ORDER BY (cr=137 pr=0 pw=0 time=978 us)'
STAT #2 id=2 cnt=12 pid=1 pos=1 obj=51910 op='TABLE ACCESS BY INDEX ROWID EMPLOYEES (cr=137 pr=0 pw=0 time=953 us)'
STAT #2 id=3 cnt=40 pid=2 pos=1 obj=0 op='NESTED LOOPS (cr=25 pr=0 pw=0 time=3612 us)'
STAT #2 id=4 cnt=21 pid=3 pos=1 obj=0 op='NESTED LOOPS (cr=4 pr=0 pw=0 time=347 us)'
STAT #2 id=5 cnt=1 pid=4 pos=1 obj=51900 op='TABLE ACCESS BY INDEX ROWID LOCATIONS (cr=2 pr=0 pw=0 time=54 us)'
STAT #2 id=6 cnt=1 pid=5 pos=1 obj=51902 op='INDEX RANGE SCAN LOC_CITY_IX (cr=1 pr=0 pw=0 time=32 us)'
STAT #2 id=7 cnt=21 pid=4 pos=2 obj=51905 op='TABLE ACCESS BY INDEX ROWID DEPARTMENTS (cr=2 pr=0 pw=0 time=209 us)'
STAT #2 id=8 cnt=21 pid=7 pos=1 obj=51907 op='INDEX RANGE SCAN DEPT_LOCATION_IX (cr=1 pr=0 pw=0 time=95 us)'
STAT #2 id=9 cnt=18 pid=3 pos=2 obj=51913 op='INDEX RANGE SCAN EMP_DEPARTMENT_IX (cr=21 pr=0 pw=0 time=224 us)'
=====================
PARSING IN CURSOR #1 len=61 dep=0 uid=5 oct=47 lid=5 tim=2597333818522 hv=356401299 ad='6685f1a4'
begin :id := sys.dbms_transaction.local_transaction_id; end;
END OF STMT
PARSE #1:c=0,e=47,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,tim=2597333818516
EXEC #1:c=0,e=123,p=0,cr=0,cu=0,mis=0,r=1,dep=0,og=1,tim=2597333829486
=====================
PARSING IN CURSOR #2 len=28 dep=0 uid=5 oct=3 lid=5 tim=2597342331549 hv=2848210951 ad='669ac9d4'
select :"SYS_B_0" from dual
END OF STMT
PARSE #2:c=0,e=95,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,tim=2597342331544
EXEC #2:c=0,e=50,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,tim=2597342340236
FETCH #2:c=0,e=29,p=0,cr=0,cu=0,mis=0,r=1,dep=0,og=1,tim=2597342345138
STAT #2 id=1 cnt=1 pid=0 pos=1 obj=0 op='FAST DUAL (cr=0 pr=0 pw=0 time=11 us)'
=====================
PARSING IN CURSOR #1 len=61 dep=0 uid=5 oct=47 lid=5 tim=2597342356044 hv=356401299 ad='6685f1a4'
begin :id := sys.dbms_transaction.local_transaction_id; end;
END OF STMT
PARSE #1:c=0,e=45,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,tim=2597342356039
EXEC #1:c=0,e=103,p=0,cr=0,cu=0,mis=0,r=1,dep=0,og=1,tim=2597342356219
=====================
PARSING IN CURSOR #2 len=35 dep=0 uid=5 oct=42 lid=5 tim=2597342357077 hv=2507904085 ad='66b0ab2c'
ALTER SESSION SET SQL_TRACE=FALSE
END OF STMT
PARSE #2:c=0,e=450,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=1,tim=2597342357072
EXEC #2:c=0,e=419,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,tim=2597342357557
格式化输出后的结果：
TKPROF: Release 10.2.0.1.0 - Production on 星期二 1月 22 13:06:11 2008
Copyright (c) 1982, 2005, Oracle. All rights reserved.
Trace file: D:\oracle\product\10.2.0\admin\TEST\test_ora_4464.trc
Sort options: default
********************************************************************************
count = number of times OCI procedure was executed
cpu = cpu time in seconds executing
elapsed = elapsed time in seconds executing
disk = number of physical reads of buffers from disk
query = number of buffers gotten for consistent read
current = number of buffers gotten in current mode (usually for update)
rows = number of rows processed by the fetch or execute call
********************************************************************************
ALTER SESSION SET SQL_TRACE=TRUE
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 0 0.00 0.00 0 0 0 0
Execute 1 0.00 0.00 0 0 0 0
Fetch 0 0.00 0.00 0 0 0 0
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 1 0.00 0.00 0 0 0 0
Misses in library cache during parse: 0
Misses in library cache during execute: 1
Optimizer mode: ALL_ROWS
Parsing user id: 5
********************************************************************************
begin :id := sys.dbms_transaction.local_transaction_id; end;
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 6 0.00 0.00 0 0 0 0
Execute 6 0.00 0.00 0 0 0 6
Fetch 0 0.00 0.00 0 0 0 0
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 12 0.00 0.00 0 0 0 6
Misses in library cache during parse: 0
Optimizer mode: ALL_ROWS
Parsing user id: 5
********************************************************************************
select :"SYS_B_0"
from
dual
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 3 0.00 0.00 0 0 0 0
Execute 3 0.00 0.00 0 0 0 0
Fetch 3 0.00 0.00 0 0 0 3
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 9 0.00 0.00 0 0 0 3
Misses in library cache during parse: 0
Optimizer mode: ALL_ROWS
Parsing user id: 5
Rows Row Source Operation
------- ---------------------------------------------------
1 FAST DUAL (cr=0 pr=0 pw=0 time=11 us)
********************************************************************************
select last_name, department_name, salary
from hr.employees e, hr.departments d, hr.locations l
where l.location_id = d.location_id
and d.department_id = e.department_id
and l.city = :"SYS_B_0"
and e.salary > :"SYS_B_1"
order by salary desc
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 2 0.00 0.00 0 0 0 0
Execute 2 0.04 0.04 0 0 0 0
Fetch 2 0.00 0.04 7 274 0 24
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 6 0.04 0.08 7 274 0 24
Misses in library cache during parse: 1
Misses in library cache during execute: 2
Optimizer mode: ALL_ROWS
Parsing user id: 5
Rows Row Source Operation
------- ---------------------------------------------------
12 SORT ORDER BY (cr=137 pr=7 pw=0 time=43028 us)
12 TABLE ACCESS BY INDEX ROWID EMPLOYEES (cr=137 pr=7 pw=0 time=43030 us)
40 NESTED LOOPS (cr=25 pr=3 pw=0 time=1042416 us)
21 NESTED LOOPS (cr=4 pr=2 pw=0 time=23125 us)
1 TABLE ACCESS BY INDEX ROWID LOCATIONS (cr=2 pr=1 pw=0 time=18136 us)
1 INDEX RANGE SCAN LOC_CITY_IX (cr=1 pr=1 pw=0 time=18107 us)(object id 51902)
21 TABLE ACCESS BY INDEX ROWID DEPARTMENTS (cr=2 pr=1 pw=0 time=4886 us)
21 INDEX RANGE SCAN DEPT_LOCATION_IX (cr=1 pr=1 pw=0 time=4723 us)(object id 51907)
18 INDEX RANGE SCAN EMP_DEPARTMENT_IX (cr=21 pr=1 pw=0 time=4168 us)(object id 51913)
********************************************************************************
ALTER SESSION SET SQL_TRACE=FALSE
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.00 0.00 0 0 0 0
Execute 1 0.00 0.00 0 0 0 0
Fetch 0 0.00 0.00 0 0 0 0
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 2 0.00 0.00 0 0 0 0
Misses in library cache during parse: 1
Optimizer mode: ALL_ROWS
Parsing user id: 5
********************************************************************************
OVERALL TOTALS FOR ALL NON-RECURSIVE STATEMENTS
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 12 0.00 0.00 0 0 0 0
Execute 13 0.04 0.04 0 0 0 6
Fetch 5 0.00 0.04 7 274 0 27
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 30 0.04 0.09 7 274 0 33
Misses in library cache during parse: 2
Misses in library cache during execute: 3
OVERALL TOTALS FOR ALL RECURSIVE STATEMENTS
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 2 0.00 0.00 0 0 0 0
Execute 2 0.00 0.00 0 0 0 0
Fetch 2 0.00 0.00 0 4 0 2
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 6 0.00 0.00 0 4 0 2
Misses in library cache during parse: 0
13 user SQL statements in session.
2 internal SQL statements in session.
15 SQL statements in session.
********************************************************************************
Trace file: D:\oracle\product\10.2.0\admin\TEST\test_ora_4464.trc
Trace file compatibility: 10.01.00
Sort options: default
1 session in tracefile.
13 user SQL statements in trace file.
2 internal SQL statements in trace file.
15 SQL statements in trace file.
6 unique SQL statements in trace file.
155 lines in trace file.
27 elapsed seconds in trace file.
EXPLAIN PLAN
EXPLAIN PLAN显示了优化器选择的应该的SQL执行计划。
行源树SQL执行计划的核心。它主要提供以下的信息：
·语句引用的对象的顺序；
·语句中每个对象的访问方法；
·语句中连接操作的连接方法；
·数据操作，如filter, sort, aggregation；
plan table中还包括以下信息：
·优化，每一操作的cost和cardinality（确保执行计划的集的势和实际执行的集的势相同是很重要的，这决定了优化器连接表的顺序）；
·分区；
·并行执行；
执行计划改变的原因
在CBO下，底层代价的改变可能随时导致优化器选择不同的执行计划。主要是由于不同的模式和不同的代价。
不同的模式
·不同用户执行相同的语句；
·模式变化，索引的改变；
不同的代价
·数据列和统计；
·绑定变量类型（在PL/SQL过程中，传递的参数是通过在调用过程的入口进行转换，因此不会改变执行计划，但是如果使用本地变量，则会改变执行计划）；
·初始化参数；
EXPLAIN PLAN和实际的执行计划
执行计划本身的使用并不能确定一个语句调整的好坏，如果EXPLAIN PLAN可能会显示语句使用了某些索引，但是有可能索引是非常低效的。在查看执行计划选择的索引时，我们应该去确定索引使用的列，列的选择性。
因此通常考虑使用EXPLAIN PLAN查看访问的计划，如果对查询当前的执行计划比较满足，然后查看实际的执行计划确定语句的效率。可以使用Oracle Trace或SQL trace。
显示执行计划：@?/RDBMS/ADMIN/UTLXPLS
PLAN_TABLE_OUTPUT
--------------------------------------------------------------------------------
Plan hash value: 542496325
--------------------------------------------------------------------------------
| Id | Operation | Name | Rows | Bytes | Co
--------------------------------------------------------------------------------
| 0 | SELECT STATEMENT | | 13 | 598 |
| 1 | SORT ORDER BY | | 13 | 598 |
|* 2 | TABLE ACCESS BY INDEX ROWID | EMPLOYEES | 3 | 45 |
| 3 | NESTED LOOPS | | 13 | 598 |
| 4 | NESTED LOOPS | | 4 | 124 |
| 5 | TABLE ACCESS BY INDEX ROWID| LOCATIONS | 1 | 12 |
|* 6 | INDEX RANGE SCAN | LOC_CITY_IX | 1 | |
| 7 | TABLE ACCESS BY INDEX ROWID| DEPARTMENTS | 4 | 76 |
|* 8 | INDEX RANGE SCAN | DEPT_LOCATION_IX | 4 | |
|* 9 | INDEX RANGE SCAN | EMP_DEPARTMENT_IX | 10 | |
--------------------------------------------------------------------------------
Predicate Information (identified by operation id):
---------------------------------------------------
PLAN_TABLE_OUTPUT
--------------------------------------------------------------------------------
2 - filter("E"."SALARY">5000)
6 - access("L"."CITY"='
8 - access("D"."LOCATION_ID"="L"."LOCATION_ID")
9 - access("D"."DEPARTMENT_ID"="E"."DEPARTMENT_ID")
CPU代价模型
默认情况下，CPU代价是不启用的。不过，Oracle9i开始支持将CPU作为代价。
其计算方式：
Cost = (#SRds * sreadtim +
#MRds * mreadtim +
#CPUCycles / cpuspeed ) / sreadtim
EXPLAIN PLAN的限制
Oracle不支持EXPLAIN PLAN为语句执行隐示日期类型的绑定变量转换。从SQL语句的文本中，TKPROF无法确定绑定变量的类型，并假设为CHARACTER。可以通过在SQL语句中放入恰当的类型转换避免。
关于执行计划的详细输出解释，可以参考Database Performance Tuning Guide and Reference或者Oracle Reference。
10046 event
使用autotrace可以产生很详细的SQL语句执行计划，同样，10046事件的跟踪结果可以通过TKPROF进行格式化。
可以通过ALTER SESSION SET events '10046 trace name context forever, level N’或者EXECUTE SYS.DBMS_SUPPORT.START_TRACE启用；
该跟踪的输出会很大，并且可以在各个级别进行跟踪。跟踪文件的裸解释见相关章节。
Autotrace
在SQL*Plus下可以使用AUTOTRACE报告执行的SQL语句的执行路径和执行统计。
可以通过AUTOTRACE系统变量控制该报告的输出，如下：
·SET AUTOTRACE OFF
·SET AUTOTRACE ON EXPLAIN
·SET AUTOTRACE ON STATISTICS
·SET AUTOTRACE ON
·SET AUTOTRACE TRACEONLY
使用该特征，必须启用PLUSTRACE角色并授予用户。该角色可以通过@$ORACLE_HOME/SQLPLUS/ADMIN/PLUSTRCE.SQL创建。
SQL的执行计划
执行计划的输出其实是由EXPLAIN PLAN产生的。因此输出格式可以通过COLUMN控制。
SQL的数据库统计
其中重要的统计包括：recursive calls，db block gets，consistent gets，physical reads，sorts (memory)，sorts (disk)，以及rows processed。
可以使用SQL*Plus TIMING收集和显示整个查询或整个的延时。
