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=yes TKPROF: Release 11.2.0.4.0 - Development on Thu Sep 26 22:37:26 2013 Copyright (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 2013 Copyright (c) 1982, 2011, Oracle and/or its affiliates. All rights reserved. Trace file: RHYS_ora_3191.trc
Sort options: default ********************************************************************************
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
******************************************************************************** The following statement encountered a error during parse: select * from rhys.amy_dept
PARSE #1399268
Error encountered: ORA-00942
******************************************************************************** SQL ID: 9m7787camwh4m Plan Hash: 0 begin :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 0
Execute 6 0.00 0.00 0 0 0 6
Fetch 0 0.00 0.00 0 0 0 0
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 11 0.00 0.00 0 0 0 6 Misses in library cache during parse: 0
Optimizer mode: ALL_ROWS
Parsing user id: 83 (SCOTT)
******************************************************************************** SQL ID: cf06fwacdmgfk Plan Hash: 1388734953 select 'x'
from
dual call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 3 0.00 0.00 0 0 0 0
Execute 3 0.00 0.00 0 0 0 0
Fetch 3 0.00 0.00 0 0 0 3
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 9 0.00 0.00 0 0 0 3 Misses in library cache during parse: 1
Optimizer mode: ALL_ROWS
Parsing user id: 83 (SCOTT)
Number of plan statistics captured: 3 Rows (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: 3383998547 select *
from
dept 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 1 0.00 0.05 6 6 0 4
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 3 0.00 0.05 6 6 0 4 Misses in library cache during parse: 1
Optimizer mode: ALL_ROWS
Parsing user id: 83 (SCOTT)
Number of plan statistics captured: 1 Rows (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: 1973284518 select *
from
emp where rownum<5 call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.00 0.01 0 0 0 0
Execute 1 0.00 0.00 0 0 0 0
Fetch 1 0.00 0.00 6 6 0 4
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 3 0.00 0.01 6 6 0 4 Misses in library cache during parse: 1
Optimizer mode: ALL_ROWS
Parsing user id: 83 (SCOTT)
Number of plan statistics captured: 1 Rows (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 STATEMENTS call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 10 0.01 0.02 0 0 0 0
Execute 11 0.00 0.00 0 0 0 6
Fetch 5 0.00 0.05 12 12 0 11
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 26 0.01 0.07 12 12 0 17 Misses in library cache during parse: 3 OVERALL TOTALS FOR ALL RECURSIVE STATEMENTS call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 10 0.00 0.00 0 0 0 0
Execute 81 0.02 0.03 0 0 0 0
Fetch 108 0.00 0.00 7 270 0 287
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 199 0.03 0.04 7 270 0 287 Misses in library cache during parse: 4
Misses 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.trc
Trace file compatibility: 11.1.0.7
Sort 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_table TKPROF: Release 11.2.0.4.0 - Development on Thu Sep 26 23:05:52 2013 Copyright (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_dept
PARSE #1399268
Error encountered: ORA-00942
******************************************************************************** SQL ID: 3fuwk9jhwd624 Plan Hash: 1973284518 select *
from
emp where rownum<5 call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.00 0.01 0 0 0 0
Execute 1 0.00 0.00 0 0 0 0
Fetch 1 0.00 0.00 6 6 0 4
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 3 0.00 0.01 6 6 0 4 Misses in library cache during parse: 1
Optimizer mode: ALL_ROWS
Parsing user id: 83 (SCOTT)
Number of plan statistics captured: 1 Rows (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: 3383998547 select *
from
dept 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 1 0.00 0.05 6 6 0 4
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 3 0.00 0.05 6 6 0 4 Misses in library cache during parse: 1
Optimizer mode: ALL_ROWS
Parsing user id: 83 (SCOTT)
Number of plan statistics captured: 1 Rows (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: 1388734953 select 'x'
from
dual call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 3 0.00 0.00 0 0 0 0
Execute 3 0.00 0.00 0 0 0 0
Fetch 3 0.00 0.00 0 0 0 3
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 9 0.00 0.00 0 0 0 3 Misses in library cache during parse: 1
Optimizer mode: ALL_ROWS
Parsing user id: 83 (SCOTT)
Number of plan statistics captured: 3 Rows (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: 3992920156 select 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 0
Execute 3 0.01 0.01 0 0 0 0
Fetch 6 0.00 0.00 2 21 0 3
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 10 0.01 0.02 2 21 0 3 Misses in library cache during parse: 1
Misses in library cache during execute: 1
Optimizer mode: CHOOSE
Parsing user id: SYS (recursive depth: 1)
Number of plan statistics captured: 1 Rows (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 car
d=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)(objec
t id 54) ******************************************************************************** SQL ID: 9tgj4g8y4rwy8 Plan Hash: 3755742892 select 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#=:3 call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.00 0.00 0 0 0 0
Execute 6 0.00 0.00 0 0 0 0
Fetch 6 0.00 0.00 0 18 0 6
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 13 0.00 0.00 0 18 0 6 Misses in library cache during parse: 1
Misses in library cache during execute: 1
Optimizer mode: CHOOSE
Parsing user id: SYS (recursive depth: 1)
Number of plan statistics captured: 1 Rows (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执行计划分析。