Oracle 10046事件介绍(二) —tkprof

403次阅读

共计 4617 个字符，预计需要花费 12 分钟才能阅读完成。

之前简单的写了 Oracle 10046 事件介绍的文章 http://www.linuxidc.com/Linux/2017-02/140729.htm，当然收集 10046 trace 不是最终的目的，能够读懂并且通过分析 10046 trace 进而分析相应 sql 的性能问题才是 10046 trace 真正发挥作用的地方。但是 10046 事件所产生的原始 trace 文件习惯称之为裸 trace 文件 (raw trace)，Oracle 记录在裸 trace 文件中的内容一眼看上去并不是那么观，也不是那么容易看懂。为了祼 trace 文件能够以一种更直观、更容易懂的方式展现出来，Oracle 提供了 tkprof 命令，这个命令是 Oracle 自带的，可以用它来翻译祼 trace 文件。

1、tkprof 的语法：

tkprof filename1 filename2 [waits=yes|no] [sort=option] [print=n] 
    [aggregate=yes|no] [insert=filename3] [sys=yes|no] [table=schema.table] 
    [explain=user/password] [record=filename4] [width=n]

最简单的使用方法是 tkprof trace_filename output_filename

具体使用方法及参数含义参考官方文档 http://docs.oracle.com/cd/E11882_01/server.112/e41573/sqltrace.htm#PFGRF94985

tkprof 生成的输出文件中会包含一些 Oracle 内部调用的 sql 的 trace 记录，这些 SQL 是由用户的 SQL 触发，一般来说是查一些数据字典基表例如 obj$、tab$ 等，常规情况下这些 SQL 运行消耗的资源和时间都非常少。我们不需要关心，我们关心的就是我们运行的 sql 所对应的各种信息。

2、一个简单 sql 对应的 trace 经过 tkprof 后的示例

SQL ID: 484dcpmb3vazu Plan Hash: 2949544139 
  
select * 
from 
 scott.emp where empno=:x 
  
  
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.00       0.00          0          2          0           1 
------- ------  -------- ---------- ---------- ---------- ----------  ---------- 
total        4      0.00       0.00          0          2          0           1 
  
Misses in library cache during parse: 1 
Optimizer mode: ALL_ROWS 
Parsing user id: SYS 
Number of plan statistics captured: 1 
  
Rows (1st) Rows (avg) Rows (max)  Row Source Operation 
---------- ---------- ----------  --------------------------------------------------- 
         1          1          1  TABLE ACCESS BY INDEX ROWID EMP (cr=2 pr=0 pw=0 time=38 us cost=1 size=38 card=1) 
         1          1          1   INDEX UNIQUE SCAN PK_EMP (cr=1 pr=0 pw=0 time=19 us cost=0 size=0 card=1)(object id 87109) 
  
  
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 
  SQL*Net message from client                     2        0.01          0.01

3、各部分详细分析

1) 第一部分是 SQL ID、Plan Hash 和 sql 文本

SQL ID: 484dcpmb3vazu Plan Hash: 2949544139 
  
select * 
from 
 scott.emp where empno=:x

2) 第二部分是此次 SQL 运行时各项指标的统计信息的汇总

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.00       0.00          0          2          0           1 
------- ------  -------- ---------- ---------- ---------- ----------  ---------- 
total        4      0.00       0.00          0          2          0           1

行名解释

parse 解析 SQL 语句部分
execute SQL 语句的执行执行部分，对于 INSERT/UPDATE/DELETE 语句，对就的是修改的行，对于 SELECT 语句标示返回的行数
fetch 查询的返回行数，只在 select 语句有效

列名解释

count 语句在解析、执行或 FETCH 阶段的次数
cpu 语句在解析、执行或 FETCH 阶段所消耗的总 CPU 时间 (秒)，如果 TIMED_STATISTICS 没有打开则值为 0
elapsed 语句在解析、执行或 FETCH 阶段所消耗的总时间 (秒)，如果 TIMED_STATISTICS 没有打开则值为 0
disk 语句在解析、执行或 FETCH 阶段对在磁盘上的数据文件的总物理读数量
query 语句在解析、执行或 FETCH 阶段对 buffer 一致读模式的次数，通常对应查询语句
current 语句在解析、执行或 FETCH 阶段对 buffer 当前读模式的次数，对应 INSERT/UPDATE/DELETE 语句
rows 语句总共产生的行数，不包含 SQL 中子查询产生的行数

3) 第三部分 Library Cache information

列出了语句在解析和执行阶段时 library cache miss 的次数，如果语句没有 library cache miss, 则 tkprof 不显示。还列出了优化器模式等信息

Misses in library cache during parse: 1 
Optimizer mode: ALL_ROWS 
Parsing user id: SYS 
Number of plan statistics captured: 1

4) 第四部分为 Row source plan

Rows (1st) Rows (avg) Rows (max)  Row Source Operation 
---------- ---------- ----------  --------------------------------------------------- 
         1          1          1  TABLE ACCESS BY INDEX ROWID EMP (cr=2 pr=0 pw=0 time=38 us cost=1 size=38 card=1) 
         1          1          1   INDEX UNIQUE SCAN PK_EMP (cr=1 pr=0 pw=0 time=19 us cost=0 size=0 card=1)(object id 87109)

cr 一致读次数
pr 物理读次数
pw 物理写次数
time 消耗的时间 (微秒)
cost 这个操作的消耗
size 预估的返回大小 (bytes)
card 预估的 cardinality

第五部分：语句执行的等待事件信息

包括各个等待事件的等待次数和等待时间。

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 
  SQL*Net message from client                     2        0.01          0.01