解读tkprof格式化后的trace跟踪文件！

来源：互联网发布：mac识别u盘教程编辑：程序博客网时间：2024/05/02 08:24

下面先生成一个执行计划：

SQL> select spid from v$process where addr = (select paddr from v$session where sid = (select sid from v$mystat where rownum = 1));SPID------------3679SQL> alter session set sql_trace = true;会话已更改。SQL> select * from t where object_id = 100;OWNER------------------------------OBJECT_NAME--------------------------------------------------------------------------------SUBOBJECT_NAME                  OBJECT_ID DATA_OBJECT_ID OBJECT_TYPE------------------------------ ---------- -------------- -------------------CREATED        LAST_DDL_TIME  TIMESTAMP           STATUS  T G S-------------- -------------- ------------------- ------- - - -SYSI_TYPED_VIEW1                                      100            100 INDEX17-2月 -08     17-2月 -08     2008-02-17:01:50:58 VALID   N N NSQL> alter session set sql_trace = false;会话已更改。

[oracle@linux udump]$ tkprof orcl_ora_3679.trc traceTKPROF: Release 10.2.0.4.0 - Production on 星期六 10月 29 13:02:12 2011Copyright (c) 1982, 2007, Oracle.  All rights reserved.[oracle@linux udump]$ cat trace.prf TKPROF: Release 10.2.0.4.0 - Production on 星期六 10月 29 13:01:21 2011Copyright (c) 1982, 2007, Oracle.  All rights reserved.Trace file: orcl_ora_3679.trcSort options: default********************************************************************************count    = number of times OCI procedure was executedcpu      = cpu time in seconds executing elapsed  = elapsed time in seconds executingdisk     = number of physical reads of buffers from diskquery    = number of buffers gotten for consistent readcurrent  = number of buffers gotten in current mode (usually for update)rows     = number of rows processed by the fetch or execute call********************************************************************************select /*+ rule */ bucket_cnt, row_cnt, cache_cnt, null_cnt, timestamp#,   sample_size, minimum, maximum, distcnt, lowval, hival, density, col#,   spare1, spare2, avgcln from hist_head$ where obj#=:1 and intcol#=:2call     count       cpu    elapsed       disk      query    current        rows------- ------  -------- ---------- ---------- ---------- ----------  ----------Parse        1      0.00       0.00          0          0          0           0Execute      9      0.00       0.00          0          0          0           0Fetch        9      0.00       0.00          0         27          0           9------- ------  -------- ---------- ---------- ---------- ----------  ----------total       19      0.00       0.00          0         27          0           9Misses in library cache during parse: 1Misses in library cache during execute: 1Optimizer mode: RULEParsing user id: SYS   (recursive depth: 1)Rows     Row Source Operation-------  ---------------------------------------------------      1  TABLE ACCESS BY INDEX ROWID HIST_HEAD$ (cr=3 pr=0 pw=0 time=64 us)      1   INDEX RANGE SCAN I_HH_OBJ#_INTCOL# (cr=2 pr=0 pw=0 time=35 us)(object id 257)********************************************************************************select * from t where object_id = 100call     count       cpu    elapsed       disk      query    current        rows------- ------  -------- ---------- ---------- ---------- ----------  ----------Parse        1      0.01       0.01          0         27          0           0Execute      1      0.00       0.00          0          0          0           0Fetch        2      0.00       0.00          1        731          0           1------- ------  -------- ---------- ---------- ---------- ----------  ----------total        4      0.01       0.01          1        758          0           1Misses in library cache during parse: 1Optimizer mode: ALL_ROWSParsing user id: 65  Rows     Row Source Operation-------  ---------------------------------------------------      1  TABLE ACCESS FULL T (cr=731 pr=1 pw=0 time=2532 us)********************************************************************************alter session set sql_trace = falsecall     count       cpu    elapsed       disk      query    current        rows------- ------  -------- ---------- ---------- ---------- ----------  ----------Parse        1      0.00       0.00          0          0          0           0Execute      1      0.00       0.00          0          0          0           0Fetch        0      0.00       0.00          0          0          0           0------- ------  -------- ---------- ---------- ---------- ----------  ----------total        2      0.00       0.00          0          0          0           0Misses in library cache during parse: 0Parsing user id: 65  ********************************************************************************OVERALL TOTALS FOR ALL NON-RECURSIVE STATEMENTScall     count       cpu    elapsed       disk      query    current        rows------- ------  -------- ---------- ---------- ---------- ----------  ----------Parse        2      0.01       0.01          0         27          0           0Execute      2      0.00       0.00          0          0          0           0Fetch        2      0.00       0.00          1        731          0           1------- ------  -------- ---------- ---------- ---------- ----------  ----------total        6      0.01       0.01          1        758          0           1Misses in library cache during parse: 1OVERALL TOTALS FOR ALL RECURSIVE STATEMENTScall     count       cpu    elapsed       disk      query    current        rows------- ------  -------- ---------- ---------- ---------- ----------  ----------Parse        1      0.00       0.00          0          0          0           0Execute      9      0.00       0.00          0          0          0           0Fetch        9      0.00       0.00          0         27          0           9------- ------  -------- ---------- ---------- ---------- ----------  ----------total       19      0.00       0.00          0         27          0           9Misses in library cache during parse: 1Misses in library cache during execute: 1    2  user  SQL statements in session.    9  internal SQL statements in session.   11  SQL statements in session.********************************************************************************Trace file: orcl_ora_3679.trcTrace file compatibility: 10.01.00Sort options: default       1  session in tracefile.       2  user  SQL statements in trace file.       9  internal SQL statements in trace file.      11  SQL statements in trace file.       3  unique SQL statements in trace file.     107  lines in trace file.      17  elapsed seconds in trace file.

下面来逐部解释这个trace文件：

TKPROF: Release 10.2.0.4.0 - Production on 星期六 10月 29 13:01:21 2011Copyright (c) 1982, 2007, Oracle.  All rights reserved.Trace file: orcl_ora_3679.trcSort options: default********************************************************************************count    = number of times OCI procedure was executedcpu      = cpu time in seconds executing elapsed  = elapsed time in seconds executingdisk     = number of physical reads of buffers from diskquery    = number of buffers gotten for consistent readcurrent  = number of buffers gotten in current mode (usually for update)rows     = number of rows processed by the fetch or execute call

这是trace文件的头部，包含版本、时间以及报告中每一项的解释等信息。

********************************************************************************select /*+ rule */ bucket_cnt, row_cnt, cache_cnt, null_cnt, timestamp#,   sample_size, minimum, maximum, distcnt, lowval, hival, density, col#,   spare1, spare2, avgcln from hist_head$ where obj#=:1 and intcol#=:2call     count       cpu    elapsed       disk      query    current        rows------- ------  -------- ---------- ---------- ---------- ----------  ----------Parse        1      0.00       0.00          0          0          0           0Execute      9      0.00       0.00          0          0          0           0Fetch        9      0.00       0.00          0         27          0           9------- ------  -------- ---------- ---------- ---------- ----------  ----------total       19      0.00       0.00          0         27          0           9Misses in library cache during parse: 1Misses in library cache during execute: 1Optimizer mode: RULEParsing user id: SYS   (recursive depth: 1)Rows     Row Source Operation-------  ---------------------------------------------------      1  TABLE ACCESS BY INDEX ROWID HIST_HEAD$ (cr=3 pr=0 pw=0 time=64 us)      1   INDEX RANGE SCAN I_HH_OBJ#_INTCOL# (cr=2 pr=0 pw=0 time=35 us)(object id 257)

这些信息是解释sql用需要访问数据字典的查询，通常来讲不用太关注，在用tkprof生成trace文件的时候指定sys=no可以忽略这些信息。

********************************************************************************select * from t where object_id = 100call     count       cpu    elapsed       disk      query    current        rows------- ------  -------- ---------- ---------- ---------- ----------  ----------Parse        1      0.01       0.01          0         27          0           0Execute      1      0.00       0.00          0          0          0           0Fetch        2      0.00       0.00          1        731          0           1------- ------  -------- ---------- ---------- ---------- ----------  ----------total        4      0.01       0.01          1        758          0           1Misses in library cache during parse: 1Optimizer mode: ALL_ROWSParsing user id: 65  Rows     Row Source Operation-------  ---------------------------------------------------      1  TABLE ACCESS FULL T (cr=731 pr=1 pw=0 time=2532 us)

这是sql执行过程中的信息，通常来讲，每条sql都应该包含3个步骤：

分析（Parse）：sql的分析阶段。

执行（Execute）：sql的执行阶段。对于select语句，在许多情况下此阶段为空。对于update语句，此阶段将是执行所有工作的所在。

数据提取（Fetch）：数据的提取阶段。对于select语句，大多数工作将在此阶段。对于update语句，将不显示任何工作。

横向的列除了call（调用）之外，还包括以下信息：

count：计数器，表示当前操作被执行了多少次。

cpu：表示当前操作消耗cpu的时间。（单位为秒）

elapsed：当前的操作一共消耗多少时间。（包括cpu事件和等待时间）

disk：当前操作的物理读。（磁盘I/O次数）

query：当前操作的一致性读方式读取的数据块数。（一致性读取，读undo，逻辑I/O次数。）

current：当前操作的current的方式读取的数据块数。（读前读取，读buffer_cache，逻辑I/O次数。）

rows：当前操作处理的数据记录数。在select查询中，该值出现在Fetch阶段。在更改操作中，该值出现在Execute阶段。

可以看这个sql被分析1次，执行1次，提取的2次。其中消耗cpu的时间是0.01秒，总耗时也是0.01秒。物理读取了1个块，一致性读取了758个数据块，没有发生current方式读取，供返回1行记录。

Misses in library cache during parse: 1    --shared pool中没有命中，这说明是一次硬解析，软分析这里为0。
Optimizer mode: ALL_ROWS                     --当前CBO优化器的模式。
Parsing user id: 65                                       --分析用户的id。

Rows：当前操作实际返回的记录数。

Row Source Operation：行源操作，表示当前操作的数据访问方式。

cr：consistent read 一致性方式读取的数据块，相当于query列上Fetch步骤的值。

pr：物理读取的数据块，相当于disk列上Fetch步骤的值。

pw：物理写。

time：当前操作执行的时间，us代表微妙。

如果在格式化trace文件的时候，加上explain=u1/u1还会看见sql的执行计划：

Rows     Execution Plan-------  ---------------------------------------------------      0  SELECT STATEMENT   MODE: ALL_ROWS      1   TABLE ACCESS   MODE: ANALYZED (FULL) OF 'T' (TABLE)

********************************************************************************alter session set sql_trace = falsecall     count       cpu    elapsed       disk      query    current        rows------- ------  -------- ---------- ---------- ---------- ----------  ----------Parse        1      0.00       0.00          0          0          0           0Execute      1      0.00       0.00          0          0          0           0Fetch        0      0.00       0.00          0          0          0           0------- ------  -------- ---------- ---------- ---------- ----------  ----------total        2      0.00       0.00          0          0          0           0Misses in library cache during parse: 0Parsing user id: 65

可以看见这个sql就是软解析的。

********************************************************************************OVERALL TOTALS FOR ALL NON-RECURSIVE STATEMENTScall     count       cpu    elapsed       disk      query    current        rows------- ------  -------- ---------- ---------- ---------- ----------  ----------Parse        2      0.01       0.01          0         27          0           0Execute      2      0.00       0.00          0          0          0           0Fetch        2      0.00       0.00          1        731          0           1------- ------  -------- ---------- ---------- ---------- ----------  ----------total        6      0.01       0.01          1        758          0           1Misses in library cache during parse: 1OVERALL TOTALS FOR ALL RECURSIVE STATEMENTScall     count       cpu    elapsed       disk      query    current        rows------- ------  -------- ---------- ---------- ---------- ----------  ----------Parse        1      0.00       0.00          0          0          0           0Execute      9      0.00       0.00          0          0          0           0Fetch        9      0.00       0.00          0         27          0           9------- ------  -------- ---------- ---------- ---------- ----------  ----------total       19      0.00       0.00          0         27          0           9Misses in library cache during parse: 1Misses in library cache during execute: 1

OVERALL TOTALS FOR ALL NON-RECURSIVE STATEMENTS：对这个sql_trace期间所有非递归sql语句执行的信息统计汇总。
OVERALL TOTALS FOR ALL RECURSIVE STATEMENTS：对这个sql_trace期间所有递归sql语句执行的信息统计汇总。

递归sql：执行一条sql语句衍生出执行一些其他的sql，这些衍生出的sql就叫做递归sql。

    2  user  SQL statements in session.    9  internal SQL statements in session.   11  SQL statements in session.********************************************************************************Trace file: orcl_ora_3679.trcTrace file compatibility: 10.01.00Sort options: default       1  session in tracefile.       2  user  SQL statements in trace file.       9  internal SQL statements in trace file.      11  SQL statements in trace file.       3  unique SQL statements in trace file.     107  lines in trace file.      17  elapsed seconds in trace file.

    2 user SQL statements in session.            --在这个trace中，用户sql有2条。
    9 internal SQL statements in session.         --在这个trace中，内部sql有9条。
   11 SQL statements in session.                  --在这个trace中，总共11条sql。