Maclean教你读SQL TRACE TKProf报告

在《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

 

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

 

Comments

  1. ttman says

    “TKPROF中简要描述了 语句相关的等待事件, 包括遇到了 多少次该等待事件(Times Waited)、 最长的等待是多久 Max.Wait, 总的等待时间Total Waited ,单位均为 S。”—–此处单位是S吗,好像不是吧?

Comment

*

沪ICP备14014813号-2

沪公网安备 31010802001379号