oracle tkprof 工具详解

     oracle  tkprof 工具详解

     今天是2013-09-26，进行tkprof工具使用学习，在此记录一下笔记：
一）查看需要跟踪会话信息：

select s.sid,s.serial#,s.username,s.logon_time,s.osuser,(select sys_context('userenv','ip_address') from dual) as ipa,
s.machine,p.username,p.program,p.spid
   from v$session s,v$process p
     where s.paddr=p.addr and s.username='SCOTT';

二）对会话开启sql trace功能：

SQL> begin  2    dbms_system.set_int_param_in_session(47,43,'max_dump_file_size',10485760);  3      4    dbms_system.set_bool_param_in_session(47,43,'timed_statistics',true);  5    dbms_system.set_sql_trace_in_session(47,43,true);  6  end;  7  /PL/SQL procedure successfully completed.SQL> begin  2  dbms_system.set_sql_trace_in_session(47,43,false);  3  end;  4  /PL/SQL procedure successfully completed.SQL> 

 

3）tkprof工具介绍：
[oracle@oracle-one trace]$ tkprof
Usage: tkprof tracefile outputfile [explain= ] [table= ]
              [print= ] [insert= ] [sys= ] [sort= ]
  table=schema.tablename   Use 'schema.tablename' with 'explain=' option.
  explain=user/password    Connect to ORACLE and issue EXPLAIN PLAN.
  print=integer    List only the first 'integer' SQL statements.
  aggregate=yes|no
  insert=filename  List SQL statements and data inside INSERT statements.
  sys=no           TKPROF does not list SQL statements run as user SYS.
  record=filename  Record non-recursive statements found in the trace file.
  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:
    prscnt  number of times parse was called
    prscpu  cpu time parsing
    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
    execnt  number of execute was called
    execpu  cpu time spent executing
    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
    fchcnt  number of times fetch was called
    fchcpu  cpu time spent fetching
    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

[oracle@oracle-one trace]$
tracefile:就是跟着的tracefile名字
outputfile：就是把格式化之后的信息存入一个新的文件中
table：每次解析执行sql过程的时候会在数据库自动创建一个表，执行完后自动删除，也可以手动创建一个 表，然把信息存入该表中
这个表的结构需要和utlxplan.sql文件中表的结构一样。当执行完后该表信息被清空。
explain：使用哪个用户对sql进行解析
print：打印出integer个sql，可以和sort联合使用，打印出指定sort序列的几个sql
例如我可以找去消耗cpu最多的sql等等。
sort：按照要求进行排序，排序种类如下：
    prscnt  number of times parse was called
    prscpu  cpu time parsing
    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
    execnt  number of execute was called
    execpu  cpu time spent executing
    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
    fchcnt  number of times fetch was called
    fchcpu  cpu time spent fetching
    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
sys：在进行sql运行的时候，或出现递归查询，设置sys为no则忽略这些recursive sql，设置为yes则在执行计划中包括这些recursive sql
aggregate：对sql的运行情况进行统计
waits：显示wait event的概要信息
insert：把执行计划都生成一个sql文件，使用这个sql可以创建sql的整个过程。
record：创建一个包含客户端发出的所有sql的脚本文件，并不包括recursive sql，
可以通过该参数查看客户端程序是怎么运行的，整个运行sql的过程顺序是什么样的。
四）tkprof工具使用案例：
案例一：
eg：

[oracle@oracle-one trace]$ tkprof RHYS_ora_3191.trc sql_explain.txt sys=no explain=scott/root aggregate=yes record=sql_path.txt waits=yesTKPROF: Release 11.2.0.4.0 - Development on Thu Sep 26 22:37:26 2013Copyright (c) 1982, 2011, Oracle and/or its affiliates.  All rights reserved.[oracle@oracle-one trace]$ [oracle@oracle-one trace]$ more sql_explain.txt TKPROF: Release 11.2.0.4.0 - Development on Thu Sep 26 22:37:26 2013Copyright (c) 1982, 2011, Oracle and/or its affiliates.  All rights reserved.Trace file: RHYS_ora_3191.trcSort options: default********************************************************************************count    = number of times OCI procedure was executedcpu      = cpu time in seconds executing elapsed  = elapsed time in seconds executingdisk     = number of physical reads of buffers from diskquery    = number of buffers gotten for consistent readcurrent  = number of buffers gotten in current mode (usually for update)rows     = number of rows processed by the fetch or execute call********************************************************************************The following statement encountered a error during parse:select * from rhys.amy_deptPARSE #1399268Error encountered: ORA-00942********************************************************************************SQL ID: 9m7787camwh4m Plan Hash: 0begin :id := sys.dbms_transaction.local_transaction_id; end;call     count       cpu    elapsed       disk      query    current        rows------- ------  -------- ---------- ---------- ---------- ----------  ----------Parse        5      0.00       0.00          0          0          0           0Execute      6      0.00       0.00          0          0          0           6Fetch        0      0.00       0.00          0          0          0           0------- ------  -------- ---------- ---------- ---------- ----------  ----------total       11      0.00       0.00          0          0          0           6Misses in library cache during parse: 0Optimizer mode: ALL_ROWSParsing user id: 83  (SCOTT)********************************************************************************SQL ID: cf06fwacdmgfk Plan Hash: 1388734953select 'x' from dualcall     count       cpu    elapsed       disk      query    current        rows------- ------  -------- ---------- ---------- ---------- ----------  ----------Parse        3      0.00       0.00          0          0          0           0Execute      3      0.00       0.00          0          0          0           0Fetch        3      0.00       0.00          0          0          0           3------- ------  -------- ---------- ---------- ---------- ----------  ----------total        9      0.00       0.00          0          0          0           3Misses in library cache during parse: 1Optimizer mode: ALL_ROWSParsing user id: 83  (SCOTT)Number of plan statistics captured: 3Rows (1st) Rows (avg) Rows (max)  Row Source Operation---------- ---------- ----------  ---------------------------------------------------         1          1          1  FAST DUAL  (cr=0 pr=0 pw=0 time=2 us cost=2 size=0 card=1)Rows     Execution Plan-------  ---------------------------------------------------      0  SELECT STATEMENT   MODE: ALL_ROWS      1   FAST DUAL********************************************************************************SQL ID: 25qnz9xr43bvy Plan Hash: 3383998547select * from deptcall     count       cpu    elapsed       disk      query    current        rows------- ------  -------- ---------- ---------- ---------- ----------  ----------Parse        1      0.00       0.00          0          0          0           0Execute      1      0.00       0.00          0          0          0           0Fetch        1      0.00       0.05          6          6          0           4------- ------  -------- ---------- ---------- ---------- ----------  ----------total        3      0.00       0.05          6          6          0           4Misses in library cache during parse: 1Optimizer mode: ALL_ROWSParsing user id: 83  (SCOTT)Number of plan statistics captured: 1Rows (1st) Rows (avg) Rows (max)  Row Source Operation---------- ---------- ----------  ---------------------------------------------------         4          4          4  TABLE ACCESS FULL DEPT (cr=6 pr=6 pw=0 time=52995 us cost=3 size=80 card=4)Rows     Execution Plan-------  ---------------------------------------------------      0  SELECT STATEMENT   MODE: ALL_ROWS      4   TABLE ACCESS   MODE: ANALYZED (FULL) OF 'DEPT' (TABLE)********************************************************************************SQL ID: 3fuwk9jhwd624 Plan Hash: 1973284518select * from emp where rownum<5call     count       cpu    elapsed       disk      query    current        rows------- ------  -------- ---------- ---------- ---------- ----------  ----------Parse        1      0.00       0.01          0          0          0           0Execute      1      0.00       0.00          0          0          0           0Fetch        1      0.00       0.00          6          6          0           4------- ------  -------- ---------- ---------- ---------- ----------  ----------total        3      0.00       0.01          6          6          0           4Misses in library cache during parse: 1Optimizer mode: ALL_ROWSParsing user id: 83  (SCOTT)Number of plan statistics captured: 1Rows (1st) Rows (avg) Rows (max)  Row Source Operation---------- ---------- ----------  ---------------------------------------------------         4          4          4  COUNT STOPKEY (cr=6 pr=6 pw=0 time=213 us)         4          4          4   TABLE ACCESS FULL EMP (cr=6 pr=6 pw=0 time=208 us cost=2 size=152 card=4)Rows     Execution Plan-------  ---------------------------------------------------      0  SELECT STATEMENT   MODE: ALL_ROWS      4   COUNT (STOPKEY)      4    TABLE ACCESS   MODE: ANALYZED (FULL) OF 'EMP' (TABLE) ********************************************************************************OVERALL TOTALS FOR ALL NON-RECURSIVE STATEMENTScall     count       cpu    elapsed       disk      query    current        rows------- ------  -------- ---------- ---------- ---------- ----------  ----------Parse       10      0.01       0.02          0          0          0           0Execute     11      0.00       0.00          0          0          0           6Fetch        5      0.00       0.05         12         12          0          11------- ------  -------- ---------- ---------- ---------- ----------  ----------total       26      0.01       0.07         12         12          0          17Misses in library cache during parse: 3OVERALL TOTALS FOR ALL RECURSIVE STATEMENTScall     count       cpu    elapsed       disk      query    current        rows------- ------  -------- ---------- ---------- ---------- ----------  ----------Parse       10      0.00       0.00          0          0          0           0Execute     81      0.02       0.03          0          0          0           0Fetch      108      0.00       0.00          7        270          0         287------- ------  -------- ---------- ---------- ---------- ----------  ----------total      199      0.03       0.04          7        270          0         287Misses in library cache during parse: 4Misses in library cache during execute: 4    6  user  SQL statements in session.   14  internal SQL statements in session.   20  SQL statements in session.    3  statements EXPLAINed in this session.********************************************************************************Trace file: RHYS_ora_3191.trcTrace file compatibility: 11.1.0.7Sort options: default       1  session in tracefile.       6  user  SQL statements in trace file.      14  internal SQL statements in trace file.      20  SQL statements in trace file.      18  unique SQL statements in trace file.       3  SQL statements EXPLAINed using schema:           SCOTT.prof$plan_table             Default table was used.             Table was created.             Table was dropped.     469  lines in trace file.      22  elapsed seconds in trace file.[oracle@oracle-one trace]$  

 

查看我执行这个sql语句的整个过程如下：

[oracle@oracle-one trace]$ more sql_path.txt select 'x' from dual ;begin :id := sys.dbms_transaction.local_transaction_id; end; /select 'x' from dual ;select * from dept ;select 'x' from dual ;select * from emp where rownum<5 ;[oracle@oracle-one trace]$ 

案例二：

[oracle@oracle-one trace]$ tkprof RHYS_ora_3191.trc sort_sql_plan.txt sys=yes waits=yes sort=prscpu,execnt explain=scott/root table=scott.plan_tableTKPROF: Release 11.2.0.4.0 - Development on Thu Sep 26 23:05:52 2013Copyright (c) 1982, 2011, Oracle and/or its affiliates.  All rights reserved.[oracle@oracle-one trace]$ [oracle@oracle-one trace]$ The following statement encountered a error during parse:select * from rhys.amy_deptPARSE #1399268Error encountered: ORA-00942********************************************************************************SQL ID: 3fuwk9jhwd624 Plan Hash: 1973284518select * from emp where rownum<5call     count       cpu    elapsed       disk      query    current        rows------- ------  -------- ---------- ---------- ---------- ----------  ----------Parse        1      0.00       0.01          0          0          0           0Execute      1      0.00       0.00          0          0          0           0Fetch        1      0.00       0.00          6          6          0           4------- ------  -------- ---------- ---------- ---------- ----------  ----------total        3      0.00       0.01          6          6          0           4Misses in library cache during parse: 1Optimizer mode: ALL_ROWSParsing user id: 83  (SCOTT)Number of plan statistics captured: 1Rows (1st) Rows (avg) Rows (max)  Row Source Operation---------- ---------- ----------  ---------------------------------------------------         4          4          4  COUNT STOPKEY (cr=6 pr=6 pw=0 time=213 us)         4          4          4   TABLE ACCESS FULL EMP (cr=6 pr=6 pw=0 time=208 us cost=2 size=152 card=4)Rows     Execution Plan-------  ---------------------------------------------------      0  SELECT STATEMENT   MODE: ALL_ROWS      4   COUNT (STOPKEY)      4    TABLE ACCESS   MODE: ANALYZED (FULL) OF 'EMP' (TABLE)********************************************************************************SQL ID: 25qnz9xr43bvy Plan Hash: 3383998547select * from deptcall     count       cpu    elapsed       disk      query    current        rows------- ------  -------- ---------- ---------- ---------- ----------  ----------Parse        1      0.00       0.00          0          0          0           0Execute      1      0.00       0.00          0          0          0           0Fetch        1      0.00       0.05          6          6          0           4------- ------  -------- ---------- ---------- ---------- ----------  ----------total        3      0.00       0.05          6          6          0           4Misses in library cache during parse: 1Optimizer mode: ALL_ROWSParsing user id: 83  (SCOTT)Number of plan statistics captured: 1Rows (1st) Rows (avg) Rows (max)  Row Source Operation---------- ---------- ----------  ---------------------------------------------------         4          4          4  TABLE ACCESS FULL DEPT (cr=6 pr=6 pw=0 time=52995 us cost=3 size=80 card=4)Rows     Execution Plan-------  ---------------------------------------------------      0  SELECT STATEMENT   MODE: ALL_ROWS      4   TABLE ACCESS   MODE: ANALYZED (FULL) OF 'DEPT' (TABLE)********************************************************************************SQL ID: cf06fwacdmgfk Plan Hash: 1388734953select 'x' from dualcall     count       cpu    elapsed       disk      query    current        rows------- ------  -------- ---------- ---------- ---------- ----------  ----------Parse        3      0.00       0.00          0          0          0           0Execute      3      0.00       0.00          0          0          0           0Fetch        3      0.00       0.00          0          0          0           3------- ------  -------- ---------- ---------- ---------- ----------  ----------total        9      0.00       0.00          0          0          0           3Misses in library cache during parse: 1Optimizer mode: ALL_ROWSParsing user id: 83  (SCOTT)Number of plan statistics captured: 3Rows (1st) Rows (avg) Rows (max)  Row Source Operation---------- ---------- ----------  ---------------------------------------------------         1          1          1  FAST DUAL  (cr=0 pr=0 pw=0 time=2 us cost=2 size=0 card=1)Rows     Execution Plan-------  ---------------------------------------------------      0  SELECT STATEMENT   MODE: ALL_ROWS      1   FAST DUAL********************************************************************************SQL ID: 7ng34ruy5awxq Plan Hash: 3992920156select i.obj#,i.ts#,i.file#,i.block#,i.intcols,i.type#,i.flags,i.property,  i.pctfree$,i.initrans,i.maxtrans,i.blevel,i.leafcnt,i.distkey,i.lblkkey,  i.dblkkey,i.clufac,i.cols,i.analyzetime,i.samplesize,i.dataobj#,  nvl(i.degree,1),nvl(i.instances,1),i.rowcnt,mod(i.pctthres$,256),  i.indmethod#,i.trunccnt,nvl(c.unicols,0),nvl(c.deferrable#+c.valid#,0),  nvl(i.spare1,i.intcols),i.spare4,i.spare2,i.spare6,decode(i.pctthres$,null,  null,mod(trunc(i.pctthres$/256),256)),ist.cachedblk,ist.cachehit,  ist.logicalread from ind$ i, ind_stats$ ist, (select enabled, min(cols) unicols,  min(to_number(bitand(defer,1))) deferrable#,min(to_number(bitand(defer,4)))   valid# from cdef$ where obj#=:1 and enabled > 1 group by enabled) c where   i.obj#=c.enabled(+) and i.obj# = ist.obj#(+) and i.bo#=:1 order by i.obj#call     count       cpu    elapsed       disk      query    current        rows------- ------  -------- ---------- ---------- ---------- ----------  ----------Parse        1      0.00       0.00          0          0          0           0Execute      3      0.01       0.01          0          0          0           0Fetch        6      0.00       0.00          2         21          0           3------- ------  -------- ---------- ---------- ---------- ----------  ----------total       10      0.01       0.02          2         21          0           3Misses in library cache during parse: 1Misses in library cache during execute: 1Optimizer mode: CHOOSEParsing user id: SYS   (recursive depth: 1)Number of plan statistics captured: 1Rows (1st) Rows (avg) Rows (max)  Row Source Operation---------- ---------- ----------  ---------------------------------------------------         1          1          1  SORT ORDER BY (cr=6 pr=0 pw=0 time=1055 us cost=6 size=372 card=2)         1          1          1   HASH JOIN OUTER (cr=6 pr=0 pw=0 time=510 us cost=5 size=372 card=2)         1          1          1    NESTED LOOPS OUTER (cr=4 pr=0 pw=0 time=54 us cost=2 size=286 card=2)         1          1          1     TABLE ACCESS CLUSTER IND$ (cr=3 pr=0 pw=0 time=38 us cost=2 size=182 card=2)         1          1          1      INDEX UNIQUE SCAN I_OBJ# (cr=2 pr=0 pw=0 time=16 us cost=1 size=0 card=1)(object id 3)         0          0          0     TABLE ACCESS BY INDEX ROWID IND_STATS$ (cr=1 pr=0 pw=0 time=11 us cost=0 size=52 card=1)         0          0          0      INDEX UNIQUE SCAN I_IND_STATS$_OBJ# (cr=1 pr=0 pw=0 time=10 us cost=0 size=0 card=1)(object id 456)         0          0          0    VIEW  (cr=2 pr=0 pw=0 time=45 us cost=3 size=43 card=1)         0          0          0     SORT GROUP BY (cr=2 pr=0 pw=0 time=45 us cost=3 size=15 card=1)         0          0          0      TABLE ACCESS BY INDEX ROWID CDEF$ (cr=2 pr=0 pw=0 time=25 us cost=2 size=15 card=1)         0          0          0       INDEX RANGE SCAN I_CDEF2 (cr=2 pr=0 pw=0 time=25 us cost=1 size=0 card=4)(object id 54)********************************************************************************SQL ID: 9tgj4g8y4rwy8 Plan Hash: 3755742892select type#,blocks,extents,minexts,maxexts,extsize,extpct,user#,iniexts,  NVL(lists,65535),NVL(groups,65535),cachehint,hwmincr, NVL(spare1,0),  NVL(scanhint,0),NVL(bitmapranges,0) from seg$ where ts#=:1 and file#=:2 and block#=:3call     count       cpu    elapsed       disk      query    current        rows------- ------  -------- ---------- ---------- ---------- ----------  ----------Parse        1      0.00       0.00          0          0          0           0Execute      6      0.00       0.00          0          0          0           0Fetch        6      0.00       0.00          0         18          0           6------- ------  -------- ---------- ---------- ---------- ----------  ----------total       13      0.00       0.00          0         18          0           6Misses in library cache during parse: 1Misses in library cache during execute: 1Optimizer mode: CHOOSEParsing user id: SYS   (recursive depth: 1)Number of plan statistics captured: 1Rows (1st) Rows (avg) Rows (max)  Row Source Operation---------- ---------- ----------  ---------------------------------------------------         1          1          1  TABLE ACCESS CLUSTER SEG$ (cr=3 pr=0 pw=0 time=161 us cost=2 size=68 card=1)         1          1          1   INDEX UNIQUE SCAN I_FILE#_BLOCK# (cr=2 pr=0 pw=0 time=112 us cost=1 size=0 card=1)(object id 9)********************************************************************************。。。。。。。。。。。。。。。。。。。。。。。

 

好了，既然我们sql 语句的执行计划就此学习完了，工具会使用了，那么最关键的是，我们如何分析发现问题，然后优化问题。见下篇sql执行计划分析。

http://blog.csdn.net/xiaohai20102010/article/details/12454577