???? oracle? tkprof 工具詳解
???? 今天是2013-09-26，進(jìn)行tkprof工具使用學(xué)習(xí)，在此記錄一下筆記：
一）查看需要跟蹤會話信息：
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：就是把格式化之后的信息存入一個(gè)新的文件中
table：每次解析執(zhí)行sql過程的時(shí)候會在數(shù)據(jù)庫自動(dòng)創(chuàng)建一個(gè)表，執(zhí)行完后自動(dòng)刪除，也可以手動(dòng)創(chuàng)建一個(gè) 表，然把信息存入該表中
這個(gè)表的結(jié)構(gòu)需要和utlxplan.sql文件中表的結(jié)構(gòu)一樣。當(dāng)執(zhí)行完后該表信息被清空。
explain：使用哪個(gè)用戶對sql進(jìn)行解析
print：打印出integer個(gè)sql，可以和sort聯(lián)合使用，打印出指定sort序列的幾個(gè)sql
例如我可以找去消耗cpu最多的sql等等。
sort：按照要求進(jìn)行排序，排序種類如下：
??? 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：在進(jìn)行sql運(yùn)行的時(shí)候，或出現(xiàn)遞歸查詢，設(shè)置sys為no則忽略這些recursive sql，設(shè)置為yes則在執(zhí)行計(jì)劃中包括這些recursive sql
aggregate：對sql的運(yùn)行情況進(jìn)行統(tǒng)計(jì)
waits：顯示wait event的概要信息
insert：把執(zhí)行計(jì)劃都生成一個(gè)sql文件，使用這個(gè)sql可以創(chuàng)建sql的整個(gè)過程。
record：創(chuàng)建一個(gè)包含客戶端發(fā)出的所有sql的腳本文件，并不包括recursive sql，
可以通過該參數(shù)查看客戶端程序是怎么運(yùn)行的，整個(gè)運(yùn)行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]$
?
查看我執(zhí)行這個(gè)sql語句的整個(gè)過程如下：
[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 語句的執(zhí)行計(jì)劃就此學(xué)習(xí)完了，工具會使用了，那么最關(guān)鍵的是，我們?nèi)绾畏治霭l(fā)現(xiàn)問題，然后優(yōu)化問題。見下篇sql執(zhí)行計(jì)劃分析。
?
?
?
更多文章、技術(shù)交流、商務(wù)合作、聯(lián)系博主
微信掃碼或搜索：z360901061
微信掃一掃加我為好友
QQ號聯(lián)系： 360901061
您的支持是博主寫作最大的動(dòng)力，如果您喜歡我的文章，感覺我的文章對您有幫助，請用微信掃描下面二維碼支持博主2元、5元、10元、20元等您想捐的金額吧，狠狠點(diǎn)擊下面給點(diǎn)支持吧，站長非常感激您！手機(jī)微信長按不能支付解決辦法：請將微信支付二維碼保存到相冊，切換到微信，然后點(diǎn)擊微信右上角掃一掃功能，選擇支付二維碼完成支付。
【本文對您有幫助就好】元
