欢迎您访问程序员文章站本站旨在为大家提供分享程序员计算机编程知识!
您现在的位置是: 首页  >  IT编程

Oracle 11g R2性能优化 tkprof

程序员文章站 2022-11-21 20:47:13
正文 另一篇博文总结了关于SQL TRACE工具的使用方式,但是产生的trace文件格式阅读起来并不是十分友好,为了更好的分析trace文件,Oracle也自带了一个格式化工具 tkprof 。 tkprof 工具用于处理原始的trace文件,合并汇总trace文件当中一些项目值,然后进行格式化,这 ......

正文

另一篇博文总结了关于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)

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