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

最新推荐文章于 2021-04-15 22:53:21 发布

事后诸葛亮

最新推荐文章于 2021-04-15 22:53:21 发布

阅读量1.9k

点赞数

分类专栏：诊断事件文章标签： sql library cache query parsing

本文链接：https://blog.csdn.net/zq9017197/article/details/6924750

版权

诊断事件专栏收录该内容

9 篇文章 0 订阅

订阅专栏

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

SQL> select spid from v$process where addr = (select paddr from v$session where sid = (select sid from v$mystat where rownum = 1));

SPID
------------
3679

SQL> 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
-------------- -------------- ------------------- ------- - - -
SYS
I_TYPED_VIEW1
                                      100            100 INDEX
17-2月 -08     17-2月 -08     2008-02-17:01:50:58 VALID   N N N


SQL> alter session set sql_trace = false;

会话已更改。

[oracle@linux udump]$ tkprof orcl_ora_3679.trc trace
TKPROF: Release 10.2.0.4.0 - Production on 星期六 10月 29 13:02:12 2011

Copyright (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 2011

Copyright (c) 1982, 2007, Oracle.  All rights reserved.

Trace file: orcl_ora_3679.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 /*+ 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#=:2


call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.00       0.00          0          0          0           0
Execute      9      0.00       0.00          0          0          0           0
Fetch        9      0.00       0.00          0         27          0           9
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total       19      0.00       0.00          0         27          0           9

Misses in library cache during parse: 1
Misses in library cache during execute: 1
Optimizer mode: RULE
Parsing 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 = 100


call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.01       0.01          0         27          0           0
Execute      1      0.00       0.00          0          0          0           0
Fetch        2      0.00       0.00          1        731          0           1
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        4      0.01       0.01          1        758          0           1

Misses in library cache during parse: 1
Optimizer mode: ALL_ROWS
Parsing 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 = false


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        0      0.00       0.00          0          0          0           0
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        2      0.00       0.00          0          0          0           0

Misses in library cache during parse: 0
Parsing user id: 65  



********************************************************************************

OVERALL TOTALS FOR ALL NON-RECURSIVE STATEMENTS

call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        2      0.01       0.01          0         27          0           0
Execute      2      0.00       0.00          0          0          0           0
Fetch        2      0.00       0.00          1        731          0           1
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        6      0.01       0.01          1        758          0           1

Misses in library cache during parse: 1


OVERALL TOTALS FOR ALL RECURSIVE STATEMENTS

call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.00       0.00          0          0          0           0
Execute      9      0.00       0.00          0          0          0           0
Fetch        9      0.00       0.00          0         27          0           9
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total       19      0.00       0.00          0         27          0           9

Misses in library cache during parse: 1
Misses 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.trc
Trace file compatibility: 10.01.00
Sort 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 2011

Copyright (c) 1982, 2007, Oracle.  All rights reserved.

Trace file: orcl_ora_3679.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

这是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#=:2


call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.00       0.00          0          0          0           0
Execute      9      0.00       0.00          0          0          0           0
Fetch        9      0.00       0.00          0         27          0           9
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total       19      0.00       0.00          0         27          0           9

Misses in library cache during parse: 1
Misses in library cache during execute: 1
Optimizer mode: RULE
Parsing 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 = 100


call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.01       0.01          0         27          0           0
Execute      1      0.00       0.00          0          0          0           0
Fetch        2      0.00       0.00          1        731          0           1
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        4      0.01       0.01          1        758          0           1

Misses in library cache during parse: 1
Optimizer mode: ALL_ROWS
Parsing 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 = false


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        0      0.00       0.00          0          0          0           0
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        2      0.00       0.00          0          0          0           0

Misses in library cache during parse: 0
Parsing user id: 65

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

********************************************************************************

OVERALL TOTALS FOR ALL NON-RECURSIVE STATEMENTS

call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        2      0.01       0.01          0         27          0           0
Execute      2      0.00       0.00          0          0          0           0
Fetch        2      0.00       0.00          1        731          0           1
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        6      0.01       0.01          1        758          0           1

Misses in library cache during parse: 1


OVERALL TOTALS FOR ALL RECURSIVE STATEMENTS

call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.00       0.00          0          0          0           0
Execute      9      0.00       0.00          0          0          0           0
Fetch        9      0.00       0.00          0         27          0           9
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total       19      0.00       0.00          0         27          0           9

Misses in library cache during parse: 1
Misses 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.trc
Trace file compatibility: 10.01.00
Sort 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。

事后诸葛亮

关注

0
点赞
踩
0

收藏

觉得还不错? 一键收藏
0
评论
解读tkprof格式化后的trace跟踪文件！

下面先生成一个执行计划：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_
复制链接

扫一扫