正文
另一篇博文总结了关于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)
〖本人水平有限，文中如有错误还请留言批评指正！〗