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