您的位置：首页 > 数据库

SQL TRACE TKProf报告

2014-09-26 20:54 302 查看

SQL TRACE TKProf报告

2013/08/25 BY MACLEAN
LIU 1条评论

在《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   askmaclean.com

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       
10859
   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

视乎实际情况，需要具体分析。

内容来自用户分享和网络整理，不保证内容的准确性，如有侵权内容，可联系管理员处理

标签：

相关文章推荐

新的分享

章节导航