oracle gather trace,读懂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

接下来看一个最简单droptablefullscan;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          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的例子：

在上述例子中我们可以看到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=56dep=1uid=0 ct=6 lid=0 tim=1345130672819745 hv=3509762282 ad=’a7525f30′

UPDATE FULLSCAN SET WNER=’MACLEAN’ WHERE OBJECT_ID=:B1

COMMIT也是这样：

PARSING IN CURSOR #2 len=6dep=1uid=0 ct=44 lid=0 tim=1345130672822889 hv=255718823 ad=’0′

COMMIT