共计 9440 个字符，预计需要花费 24 分钟才能阅读完成。
目录
- 主要说明
- 关键选项
- 用法示例
- 对 SCOTT 开启跟踪
- 执行一条 SQL 语句
- 对 SCOTT 关闭跟踪
- tkprof 分析 trace 文件
- 总结
- 参考
正文
另一篇博文总结了关于 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)
更多 Oracle 相关信息见Oracle 专题页面 https://www.linuxidc.com/topicnews.aspx?tid=12
：
正文完
星哥玩云-微信公众号
