Error message here!

Hide Error message here!

忘记密码?

Error message here!

请输入正确邮箱

Hide Error message here!

密码丢失?请输入您的电子邮件地址。您将收到一个重设密码链接。

Error message here!

返回登录

Close

Oracle 11g R2性能优化 tkprof

H_Johnny 2019-01-21 17:10:00 阅读数:183 评论数:0 点赞数:0 收藏数:0

正文

另一篇博文总结了关于SQL TRACE工具的使用方式,但是产生的trace文件格式阅读起来并不是十分友好,为了更好的分析trace文件,Oracle也自带了一个格式化工具tkproftkprof工具用于处理原始的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)

☆〖本人水平有限,文中如有错误还请留言批评指正!〗☆

版权声明
本文为[H_Johnny]所创,转载请带上原文链接,感谢
https://www.cnblogs.com/dbabd/p/10297694.html

编程之旅,人生之路,不止于编程,还有诗和远方。
阅代码原理,看框架知识,学企业实践;
赏诗词,读日记,踏人生之路,观世界之行;

支付宝红包,每日可领