Oracle 11g R2性能优化 tkprof
- 作者: MrG37088382
- 来源: 51数据库
- 2021-08-17
正文
另一篇博文总结了关于sql trace工具的使用方式，但是产生的trace文件格式阅读起来并不是十分友好，为了更好的分析trace文件，oracle也自带了一个格式化工具tkprof。tkprof工具用于处理原始的trace文件，合并汇总trace文件当中一些项目值，然后进行格式化，这样就使得trace文件的可读性更好。
关于tkprof的详细说明可以参考官方文档：understanding sql trace and tkprof
关于trace文件的生成可以参考另一篇博文：oracle 11g r2性能优化 sql trace
主要说明
tkprof命令位于 $oracle_home/bin/路径下，通过命令tkprof直接获取相关选项参数：
$ tkprof
usage: tkprof tracefile outputfile [explain= ] [table= ]
[print= ] [insert= ] [sys= ] [sort= ]
关键选项
tracefile
需要格式化的trace文件outputfile
格式化完成后的输出文件explain=
通过给定方式连接数据库，并为每条语句生成执行计划sort=
指定排序键来展示sql语句
其他选项如下：
table=schema.tablename use 'schema.tablename' with 'explain=' option. -- 指定plan_table生成执行计划，默认为系统的plan_table
explain=user/password connect to oracle and issue explain plan.
print=integer list only the first 'integer' sql statements. -- 显示指定数目的sql语句
aggregate=yes|no -- 指定是否对重复sql语句信息合并，默认yes合并，如果指定为no，对重复sql语句信息会独立输出一个条目
insert=filename list sql statements and data inside insert statements. -- 创建一张表将每个跟踪的sql语句的一行统计信息插入到表中
sys=no tkprof does not list sql statements run as user sys. -- 指定不记录由sys用户执行的语句
record=filename record non-recursive statements found in the trace file. -- 指定生成不包含递归语句的sql语句文件
waits=yes|no record summary for any wait events found in the trace file. -- 指定为语句生成等待事件信息(如有)
-- 以下为排序选项说明
sort=option set of zero or more of the following sort options:
-- 1、解析调用期间执行排序
prscnt number of times parse was called -- 解析次数
prscpu cpu time parsing -- 解析消耗cpu时间
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 -- 解析时库缓存区未命中次数
-- 2、执行调用期间执行排序
execnt number of execute was called -- 执行次数
execpu cpu time spent executing -- 执行时消耗cpu时间
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 -- 执行时库缓冲区未命中次数
-- 3、提取调用期间执行排序
fchcnt number of times fetch was called -- 提取数据次数
fchcpu cpu time spent fetching -- 提取时消耗cpu时间
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 -- 按游标解析时的userid排序
关于tkprof工具更详细的用法可以参考oracle mos文档：tkprof interpretation (9i and above) (文档 id 760786.1)
用法示例
对scott开启跟踪
$ sqlplus scott/tiger scott@dbabd> alter session set tracefile_identifier = 'scott'; session altered. scott@dbabd> exec dbms_session.session_trace_enable(true, true, 'all_executions'); pl/sql procedure successfully completed.
执行一条sql语句
scott@dbabd> select * from emp;
empno ename job mgr hiredate sal comm deptno
---------- ---------- --------------- ---------- ------------------- ---------- ---------- ----------
7369 smith clerk 7902 1980-12-17 00:00:00 800 20
7499 allen salesman 7698 1981-02-20 00:00:00 1600 300 30
7521 ward salesman 7698 1981-02-22 00:00:00 1250 500 30
7566 jones manager 7839 1981-04-02 00:00:00 2975 20
7654 martin salesman 7698 1981-09-28 00:00:00 1250 1400 30
7698 blake manager 7839 1981-05-01 00:00:00 2850 30
7782 clark manager 7839 1981-06-09 00:00:00 2450 10
7788 scott analyst 7566 1987-04-19 00:00:00 3000 20
7839 king president 1981-11-17 00:00:00 5000 10
7844 turner salesman 7698 1981-09-08 00:00:00 1500 0 30
7876 adams clerk 7788 1987-05-23 00:00:00 1100 20
7900 james clerk 7698 1981-12-03 00:00:00 950 30
7902 ford analyst 7566 1981-12-03 00:00:00 3000 20
7934 miller clerk 7782 1982-01-23 00:00:00 1300 10
14 rows selected.
对scott关闭跟踪
scott@dbabd> exec dbms_session.session_trace_disable(); pl/sql procedure successfully completed.
tkprof分析trace文件
执行如下命令生成格式化文件：
$ tkprof /data/app/oracle/diag/rdbms/dbabd/dbabd/trace/dbabd_ora_18629_scott.trc /data/app/scott_trace.log explain=scott/tiger aggregate=yes sys=no waits=yes sort=fchela
查看tkprof生成文件：
$ cat /data/app/scott_trace.log
-- 开头概要部分，基本信息说明，包括tkprof版本、trace文件路径、排序选项和报告参数说明
tkprof: release 11.2.0.4.0 - development on thu jan 17 17:41:04 2019
copyright (c) 1982, 2011, oracle and/or its affiliates. all rights reserved.
trace file: /data/app/oracle/diag/rdbms/dbabd/dbabd/trace/dbabd_ora_18629_scott.trc
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
********************************************************************************
-- 跟踪的sql语句文本、sql id和执行计划hash
sql id: a2dk8bdn0ujx7 plan hash: 3956160932
select *
from
emp
-- sql执行的统计信息
/*
call:调用类型
count:调用执行次数
cpu:需要的cpu时间(单位:秒)
elapsed:需要消耗的时间(单位:秒)
disk:发生物理读次数
query:发生一致读次数
current:发生当前读次数
rows:获取的行数
*/
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 7 0 14
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 4 0.00 0.00 0 7 0 14
misses in library cache during parse: 1 -- 库缓存没有命中数，说明是硬解析
optimizer mode: all_rows -- 优化器模式
parsing user id: 83 (scott) -- 解析用户
number of plan statistics captured: 1 -- 执行计划统计信息获取数
-- sql语句实际执行消耗的资源信息
/*
rows:操作实际返回记录数
row source operation:当前行操作的访问方式
cr:一致性读的数据块，对应query的fetch值
pr:物理读的数据块，对应disk的fetch值
pw:物理写的数据块
time:执行时间
cost:优化器执行成本
size:处理的字节数
card:处理的记录数
*/
rows (1st) rows (avg) rows (max) row source operation
---------- ---------- ---------- ---------------------------------------------------
14 14 14 table access full emp (cr=7 pr=0 pw=0 time=211 us cost=3 size=532 card=14)
-- 指定explain选项输出的执行计划
rows execution plan
------- ---------------------------------------------------
0 select statement mode: all_rows
14 table access mode: analyzed (full) of 'emp' (table)
-- 指定选项waits=yes选项输出的等待事件信息统计
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 128.00 128.00
********************************************************************************
sql id: bnqn0qyvy59qf plan hash: 0
begin dbms_session.session_trace_enable(true, true, 'all_executions'); end;
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
parse 0 0.00 0.00 0 0 0 0
execute 1 0.00 0.00 0 61 0 1
fetch 0 0.00 0.00 0 0 0 0
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 1 0.00 0.00 0 61 0 1
misses in library cache during parse: 0
misses in library cache during execute: 1
optimizer mode: all_rows
parsing user id: 83 (scott)
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 68.47 68.47
********************************************************************************
sql id: 23d3sap7cask4 plan hash: 0
begin dbms_session.session_trace_disable(); end;
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 1
fetch 0 0.00 0.00 0 0 0 0
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 2 0.00 0.00 0 0 0 1
misses in library cache during parse: 1
optimizer mode: all_rows
parsing user id: 83 (scott)
********************************************************************************
-- 开启跟踪期间所有非递归sql语句执行信息统计汇总
overall totals for all non-recursive statements
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
parse 2 0.01 0.01 0 0 0 0
execute 3 0.00 0.00 0 61 0 2
fetch 2 0.00 0.00 0 7 0 14
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 7 0.01 0.01 0 68 0 16
misses in library cache during parse: 2
misses in library cache during execute: 1
elapsed times include waiting on following events:
event waited on times max. wait total waited
---------------------------------------- waited ---------- ------------
sql*net message to client 3 0.00 0.00
sql*net message from client 3 128.00 196.48
-- 开启跟踪期间所有递归sql语句执行信息统计汇总
overall totals for all recursive statements
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
parse 0 0.00 0.00 0 0 0 0
execute 23 0.00 0.00 0 0 0 0
fetch 37 0.00 0.00 2 82 0 28
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 60 0.00 0.00 2 82 0 28
misses in library cache during parse: 0
elapsed times include waiting on following events:
event waited on times max. wait total waited
---------------------------------------- waited ---------- ------------
db file sequential read 2 0.00 0.00
-- 所有分析的sql语句汇总统计
3 user sql statements in session.
13 internal sql statements in session.
16 sql statements in session.
1 statement explained in this session.
********************************************************************************
trace file: /data/app/oracle/diag/rdbms/dbabd/dbabd/trace/dbabd_ora_18629_scott.trc
trace file compatibility: 11.1.0.7
sort options: fchela
1 session in tracefile.
3 user sql statements in trace file.
13 internal sql statements in trace file.
16 sql statements in trace file.
16 unique sql statements in trace file.
1 sql statements explained using schema:
scott.prof$plan_table
default table was used.
table was created.
table was dropped.
411 lines in trace file.
196 elapsed seconds in trace file.
总结
以上梳理了关于tkprof工具的简单用法，经过它格式化之后的trace文件更具有可读性，真实地统计了sql语句在执行过程当中资源的消耗。但是它提供的是汇总后的统计信息，如果需要了解sql语句执行时每个步骤的资源消耗情况可以通过阅读原始的trace文件，这里不再进行深入讨论了。sql性能优化博大精深，涉及的知识面广泛，也经常涉及oracle底层运行机制和操作系统底层实现，需要自己学习与提高的地方还有很多。
参考
https://docs.oracle.com/cd/e11882_01/server.112/e41573/sqltrace.htm#pfgrf94981
tkprof interpretation (9i and above) (文档 id 760786.1)
☆〖本人水平有限，文中如有错误还请留言批评指正！〗☆
推荐阅读
