在《Maclean教你读Oracle 10046 SQL TRACE》中我介绍了10046 TRACE的阅读以及其中个字段的含义， 接着我们介绍 10046 sql trace的搭档工具TKPROF。
TKPROF是一个可执行文件，自带在Oracle Server软件中，无需额外的安装。 该工具文件可以用来解析ORACLE的SQL TRACE(10046) 以便生成更可读的内容。 实际上tkprof是对10046 SQL trace的内容作了汇总，例如一个语句遇到过的wait event 、其在PARSE、Execute、Fetch三阶段的耗时、CPU_TIME等等。
由于tkprof是对10046 SQL TRACE的汇总，所以tkprof中的信息 完全可以从10046中获得， 10046的问题是 由于巨细靡遗 所以TRACE内容可能过多，内容多则难以快速分析， TKPROF将10046 trace 解析过后更适合调优者阅读。
TKPROF的语法如下：
tkprof tracefile outfile [explain=user/password] [options…]
几个选项
print=integer 只列出前几个SQL语句，integer 为指定的数量，例如print=10
sys=no 不列出以SYS用户运行的语句
sort=option 排序选项， 选项列表如下：
- prscnt number of times parse was called
- prscpu cpu time parsing
- prsela elapsed time parsing
- prsdsk number of disk reads during parse
- prsqry number of buffers for consistent read during parse
- prscu number of buffers for current read during parse
- prsmis number of misses in library cache during parse
- execnt number of execute was called
- execpu cpu time spent executing
- exeela elapsed time executing
- exedsk number of disk reads during execute
- exeqry number of buffers for consistent read during execute
- execu number of buffers for current read during execute
- exerow number of rows processed during execute
- exemis number of library cache misses during execute
- fchcnt number of times fetch was called
- fchcpu cpu time spent fetching
- fchela elapsed time fetching
- fchdsk number of disk reads during fetch
- fchqry number of buffers for consistent read during fetch
- fchcu number of buffers for current read during fetch
- fchrow number of rows fetched
- userid userid of user that parsed the cursor
接下来看一个最简单的 TKPROF的例子：
drop table fullscan; create table fullscan as select * from dba_objects; exec dbms_stats.gather_table_stats(user,'FULLSCAN'); alter system flush shared_pool; alter system flush buffer_cache; alter session set events '10046 trace name context forever,level 12'; select count(*) from fullscan; oradebug setmypid oradebug tracefile_name; /s01/admin/G10R25/udump/g10r25_ora_30334.trc [oracle@vrh8 udump]$ tkprof /s01/admin/G10R25/udump/g10r25_ora_30334.trc 30334.tkf TKPROF: Release 10.2.0.5.0 - Production on Sun Aug 25 02:21:27 2013 askmac.cn Copyright (c) 1982, 2007, Oracle. All rights reserved. vi 30334.tkf Trace file: /s01/admin/G10R25/udump/g10r25_ora_30334.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 ******************************************************************************** select obj#,type#,ctime,mtime,stime,status,dataobj#,flags,oid$, spare1, spare2 from obj$ where owner#=:1 and name=:2 and namespace=:3 and remoteowner is null and linkname is null and subname is null 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 1 0.00 0.00 2 4 0 1 ------- ------ -------- ---------- ---------- ---------- ---------- ---------- total 3 0.00 0.00 2 4 0 1 Misses in library cache during parse: 1 Misses in library cache during execute: 1 Optimizer mode: CHOOSE Parsing user id: SYS (recursive depth: 1) Rows Row Source Operation ------- --------------------------------------------------- 1 TABLE ACCESS BY INDEX ROWID OBJ$ (cr=4 pr=2 pw=0 time=133 us) 1 INDEX RANGE SCAN I_OBJ2 (cr=3 pr=1 pw=0 time=74 us)(object id 37) Elapsed times include waiting on following events: Event waited on Times Max. Wait Total Waited ---------------------------------------- Waited ---------- ------------ SQL*Net message to client 1 0.00 0.00 SQL*Net message from client 1 0.01 0.01 db file sequential read 2 0.00 0.00 ******************************************************************************** select count(*) from fullscan call count cpu elapsed disk query current rows ------- ------ -------- ---------- ---------- ---------- ---------- ---------- Parse 1 0.00 0.00 4 15 0 0 Execute 1 0.00 0.00 0 0 0 0 Fetch 2 0.01 0.01 1139 1143 0 1 ------- ------ -------- ---------- ---------- ---------- ---------- ---------- total 4 0.02 0.02 1143 1158 0 1 Misses in library cache during parse: 1 Optimizer mode: ALL_ROWS Parsing user id: SYS Rows Row Source Operation ------- --------------------------------------------------- 1 SORT AGGREGATE (cr=1143 pr=1139 pw=0 time=15759 us) 77268 TABLE ACCESS FULL FULLSCAN (cr=1143 pr=1139 pw=0 time=463719 us) Elapsed times include waiting on following events: Event waited on Times Max. Wait Total Waited ---------------------------------------- Waited ---------- ------------ SQL*Net message to client 2 0.00 0.00 db file sequential read 1 0.00 0.00 db file scattered read 80 0.00 0.00 SQL*Net message from client 2 0.00 0.00
在上述例子中我们可以看到TKPROF将 一个SQL Statement 的运行 划分为几个部分的信息：
1. SQL 语句的parse 、execute 、fetch 阶段的耗时：
select count(*) from fullscan call count cpu elapsed disk query current rows ------- ------ -------- ---------- ---------- ---------- ---------- ---------- Parse 1 0.00 0.00 4 15 0 0 Execute 1 0.00 0.00 0 0 0 0 Fetch 2 0.01 0.01 1139 1143 0 1 ------- ------ -------- ---------- ---------- ---------- ---------- ---------- total 4 0.02 0.02 1143 1158 0 1
call: 每一个游标的行为被分成三个步骤：
- Parse: 解析该游标并生成执行计划的统计信息
- Execute: 执行该游标阶段的统计信息
- Fetch : Fetch取得数据行阶段的统计信息
- count 指的是该游标的相关操作 的次数，例如parse count : 2 ，即该游标解析了2次
- CPU : 相关栏目 所消耗的CPU时间，单位为s
- elapsed: 相关栏目所消耗的时间，单位为s
- disk : 相关栏目所消耗的物理读
- query : 相关栏目所消耗的一致性逻辑读 consistent logical read ==>一般对于SELECT查询而言 只有query 没有current
- current: 相关栏目当前逻辑读 current logical read
- rows 该步骤取回的行数 ==》在本例中由于是 count(*) 所以只有一行
- Misses in library cache during parse: 1 在解析阶段 library cache 发生了miss，则说明本次解析是硬解析
几点释疑：
1、对于PL/SQL而言 匿名块/存储过程 以及其中包含的SQL语句会同时体现在TKPROF中，即存在重叠；且SQL将以递归SQL的形式出现：
PARSING IN CURSOR #4 len=56 dep=1 uid=0 oct=6 lid=0 tim=1345130672819745 hv=3509762282 ad=’a7525f30′
UPDATE FULLSCAN SET OWNER=’MACLEAN’ WHERE OBJECT_ID=:B1
COMMIT也是这样：
PARSING IN CURSOR #2 len=6 dep=1 uid=0 oct=44 lid=0 tim=1345130672822889 hv=255718823 ad=’0′
COMMIT
我们来看一个实际的例子：
alter system flush shared_pool;
alter system flush buffer_cache;
set timing on;
alter session set events '10046 trace name context forever,level 12';
create index ind_objd on fullscan(object_id);
begin
for i in 1..10000 loop
update fullscan set owner='MACLEAN' where object_id=i;
commit;
end loop;
end;
/
PL/SQL procedure successfully completed.
Elapsed: 00:00:04.00
begin
for i in 1..10000 loop
update fullscan set owner='MACLEAN' where object_id=i;
commit;
end loop;
end;
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.00 0.00 0 0 0 0
Execute 1 0.62 0.68 178 20037 0 1
Fetch 0 0.00 0.00 0 0 0 0
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 2 0.62 0.68 178 20037 0 1
Misses in library cache during parse: 1
Optimizer mode: ALL_ROWS
Parsing user id: SYS
Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total Waited
---------------------------------------- Waited ---------- ------------
log file sync 1 0.00 0.00
SQL*Net message to client 1 0.00 0.00
********************************************************************************
UPDATE FULLSCAN SET OWNER='MACLEAN'
WHERE
OBJECT_ID=:B1
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.00 0.00 0 0 0 0
Execute 10000 2.90 2.69 178 20037 19364 9564
Fetch 0 0.00 0.00 0 0 0 0
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 10001 2.90 2.69 178 20037 19364 9564
Misses in library cache during parse: 1
Misses in library cache during execute: 1
Optimizer mode: ALL_ROWS
Parsing user id: SYS (recursive depth: 1)
Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total Waited
---------------------------------------- Waited ---------- ------------
db file sequential read 177 0.00 0.00
COMMIT
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.00 0.00 0 0 0 0
Execute 10000 0.43 0.52 0 0 9564 0
Fetch 0 0.00 0.00 0 0 0 0
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 10001 0.43 0.52 0 0 9564 0
Misses in library cache during parse: 0
Parsing user id: SYS (recursive depth: 1)
以上通过一个匿名块 循环执行了10000次的 “update fullscan set owner=’MACLEAN’ where object_id=i;” 以及commit 总的执行 Elapsed: 00:00:04.00 。
该匿名块总耗时为0.68s， 10000次循环update fullscan为2.69s，10000次commit总耗时0.52s ， 0.68+0.52+2.69=3.89s ，此外还有少量的递归SQL耗时也算在这个4.0s里。
2、 在以上例子中看到， 对于 PL/SQL匿名块、update、commit而言 有execute 阶段 ，而没有 fetch阶段，fetch的次数为0。 对于SELECT语句而言 ，有execute阶段，但是execute阶段的disk、query、current一般为零，统统算在Fetch阶段。
begin
for i in 1..10000 loop
update fullscan set owner='MACLEAN' where object_id=i;
commit;
end loop;
end;
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.00 0.00 0 0 0 0
Execute 1 0.62 0.68 178 20037 0 1
Fetch 0 0.00 0.00 0 0 0 0
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 2 0.62 0.68 178 20037 0 1
Misses in library cache during parse: 1
Optimizer mode: ALL_ROWS
Parsing user id: SYS
Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total Waited
---------------------------------------- Waited ---------- ------------
log file sync 1 0.00 0.00
SQL*Net message to client 1 0.00 0.00
PARSING IN CURSOR #5 len=106 dep=0 uid=0 oct=47 lid=0 tim=1345130672819492 hv=3631473533 ad='a750b960'
begin
for i in 1..10000 loop
update fullscan set owner='MACLEAN' where object_id=i;
commit;
end loop;
end;
END OF STMT
PARSE #5:c=1000,e=891,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=1,tim=1345130672819487
BINDS #5:
EXEC #5:c=3968396,e=3907489,p=178,cr=20037,cu=28928,mis=0,r=1,dep=0,og=1,tim=1345130676727033
WAIT #5: nam='log file sync' ela= 162 buffer#=8084 sync scn=14950441 p3=0 obj#=96606 tim=1345130676727293
WAIT #5: nam='SQL*Net message to client' ela= 5 driver id=1650815232 #bytes=1 p3=0 obj#=96606 tim=1345130676727343
*** 2013-08-25 03:00:52.748
WAIT #5: nam='SQL*Net message from client' ela= 234159641 driver id=1650815232 #bytes=1 p3=0 obj#=96606 tim=1345130910887016
3、实际在10046 中真实反映了 上述匿名块的执行时间为 3907489 μs = 3.9s 以及其总的cr=20037 cu=28928( update的19364+commit的9564)，但在TKPROF中 匿名块等PL/SQL对象显示的信息并不全面，这可能是为了避免用户的误解。
TKPROF提供了多种排序的方法
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
一般我们对于查询的调优 常用的组合是 SYS=NO fchela， fchela即按照fetch阶段的elapsed time按照从大到小排列
[oracle@vrh8 udump]$ tkprof g10r25_ora_30731.trc 30731.tkf sys=no sort=fchela
TKPROF: Release 10.2.0.5.0 - Production on Sun Aug 25 03:39:46 2013
Copyright (c) 1982, 2007, Oracle. All rights reserved.
Sort options: fchela
********************************************************************************
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
********************************************************************************
select count(*)
from
fullscan
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 2 0.01 0.01 1140 1144 0 1
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 4 0.01 0.01 1140 1144 0 1
Misses in library cache during parse: 1
Optimizer mode: ALL_ROWS
Parsing user id: 64
Rows Row Source Operation
------- ---------------------------------------------------
1 SORT AGGREGATE (cr=1144 pr=1140 pw=0 time=14476 us)
77270 TABLE ACCESS FULL FULLSCAN (cr=1144 pr=1140 pw=0 time=386457 us)
如上Sort options: fchela 后，trace中信息按照fetch elapsed time从长到短排列。
执行计划
Rows Row Source Operation
------- ---------------------------------------------------
1 SORT AGGREGATE (cr=1144 pr=1140 pw=0 time=14476 us)
77270 TABLE ACCESS FULL FULLSCAN (cr=1144 pr=1140 pw=0 time=386457 us)
TKPROF中的执行计划并不现实card、cost等CBO指标， 其所提供的每一个步骤的Rows 、CR、PR 信息对于诊断执行计划到底慢在哪一步有一定帮助， 但是其time耗时信息并不准确。
等待事件
Event waited on Times Max. Wait Total Waited ---------------------------------------- Waited ---------- ------------ SQL*Net message to client 2 0.00 0.00 db file sequential read 1 0.00 0.00 db file scattered read 81 0.00 0.00 SQL*Net message from client 2 0.00 0.00
TKPROF中简要描述了 语句相关的等待事件， 包括遇到了 多少次该等待事件(Times Waited)、 最长的等待是多久 Max.Wait， 总的等待时间Total Waited ，单位均为 S。
10046 中的等待时间描述过于简单，仅为让阅读者简要把握等待问题， 针对等待时间的调优 强烈建议 基于AWR中的wait histogram和ASH去分析， 与他们对比TKPROF显然已经过时了。
示例解析
select count(1) from big1
where object_id between 10 and 100000
and data_object_id between 1 and 1000
and status like 'VALI%'
and object_type IN ('TABLE', 'INDEX')
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 20.02 (c) 20.12 (b) 0 1 0 0
Execute 1 0.00 0.00 0 0 0 0
Fetch 2 1.13 1.33 0 9087 0 1
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 4 21.15 21.45 (a) 0 9088 0 1
Misses in library cache during parse: 1 <== 说明是硬解析
Optimizer mode: ALL_ROWS
Parsing user id: 54
- (a)说明该语句总耗时 21.45s
- (b) 说明该语句花在解析上的耗时20.12s
- (c) 说明该语句花在解析上的CPU时间为20.02s
- 语句解析等待时间= 语句解析耗时 – 语句解析CPU耗时 = 20.12 – 20.02 = 0.10 s
以上分析说明 该语句运行的绝大多数耗时花费在解析上， 而解析时 大多数时间是CPU运算， 一般有几种可能导致这么多的CPU运算：
- 语句过于复杂，导致parse解析和optimize优化 消耗较多CPU
- 主机CPU忙，进程分配不到足够的CPU时间片
- 可能遇到resource manager 限制实现CPU
视乎实际情况，需要具体分析。
Leave a Reply