1。登录sqlplus
2。执行
--使用tkprof工具分析oracle trace跟踪文件
alter system set timed_statistics=true scope=both;
--设置trace文件的信息生成
alter session set sql_trace = true;
--查看trace生成的目录
show parameter user_dump_dest;
3。执行SQL：
select t1.empno, t1.ename, t2.deptno, t2.dname from emp t1, dept t2 where t1.deptno = t2.deptno(+);
select t1.empno, t1.ename, t2.deptno, t2.dname from emp t1, dept t2 where t1.deptno = t2.deptno;
--这里选择关闭trace信息生成
alter session set sql_trace = false;
4.退出sqlplus
5。 在trace生成目录下，执行TKPROF格式化语句：
TKPROF orcl_ora_1200.trc , TRC_ORA_1200.TXT SORT = PRSELA,EXEELA,FCHELA PRINT = 2 EXPLAIN = SH/SH ;
trc文件内容：
Dump file d:\oracle\product\10.2.0\admin\orcl\udump\orcl_ora_1200.trc
Thu Apr 14 12:38:02 2016
ORACLE V10.2.0.1.0 - Production vsnsta=0
vsnsql=14 vsnxtr=3
Oracle Database 10g Enterprise Edition Release 10.2.0.1.0 - Production
With the Partitioning, OLAP and Data Mining options
Windows XP Version V5.1 Service Pack 3
CPU : 2 - type 586, 2 Physical Cores
Process Affinity : 0x00000000
Memory (Avail/Total): Ph:604M/2008M, Ph+PgF:2247M/3901M, VA:1284M/2047M
Instance name: orcl
Redo thread mounted by this instance: 1
Oracle process number: 19
Windows thread id: 1200, image: ORACLE.EXE (SHAD)
*** 2016-04-14 12:38:02.515
*** ACTION NAME:() 2016-04-14 12:38:02.500
*** MODULE NAME:(SQL*Plus) 2016-04-14 12:38:02.500
*** SERVICE NAME:(SYS$USERS) 2016-04-14 12:38:02.500
*** SESSION ID:(149.241) 2016-04-14 12:38:02.500
=====================
PARSING IN CURSOR #1 len=34 dep=0 uid=54 oct=42 lid=54 tim=12281762464 hv=2069488880 ad='332ddb58'
alter session set sql_trace = true
END OF STMT
EXEC #1:c=0,e=510,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,tim=12281762456
*** 2016-04-14 12:38:13.875
=====================
PARSING IN CURSOR #2 len=100 dep=0 uid=54 oct=3 lid=54 tim=12293142670 hv=1722633938 ad='2f8cd4d4'
select t1.empno, t1.ename, t2.deptno, t2.dname from emp t1, dept t2 where t1.deptno = t2.deptno(+)
END OF STMT
PARSE #2:c=0,e=54,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,tim=12293142664
EXEC #2:c=0,e=55,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,tim=12293144092
FETCH #2:c=0,e=137,p=0,cr=9,cu=0,mis=0,r=1,dep=0,og=1,tim=12293144495
FETCH #2:c=0,e=568,p=0,cr=15,cu=0,mis=0,r=13,dep=0,og=1,tim=12293145607
STAT #2 id=1 cnt=14 pid=0 pos=1 obj=0 op='NESTED LOOPS OUTER (cr=24 pr=0 pw=0 time=135 us)'
STAT #2 id=2 cnt=14 pid=1 pos=1 obj=51151 op='TABLE ACCESS FULL EMP (cr=8 pr=0 pw=0 time=246 us)'
STAT #2 id=3 cnt=14 pid=1 pos=2 obj=51149 op='TABLE ACCESS BY INDEX ROWID DEPT (cr=16 pr=0 pw=0 time=472 us)'
STAT #2 id=4 cnt=14 pid=3 pos=1 obj=51150 op='INDEX UNIQUE SCAN PK_DEPT (cr=2 pr=0 pw=0 time=200 us)'
*** 2016-04-14 12:38:24.218
=====================
PARSING IN CURSOR #1 len=97 dep=0 uid=54 oct=3 lid=54 tim=12303478048 hv=3595513092 ad='33121eec'
select t1.empno, t1.ename, t2.deptno, t2.dname from emp t1, dept t2 where t1.deptno = t2.deptno
END OF STMT
PARSE #1:c=15625,e=1375,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=1,tim=12303478041
EXEC #1:c=0,e=54,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,tim=12303479513
FETCH #1:c=0,e=125,p=0,cr=9,cu=0,mis=0,r=1,dep=0,og=1,tim=12303479929
FETCH #1:c=0,e=574,p=0,cr=15,cu=0,mis=0,r=13,dep=0,og=1,tim=12303481045
STAT #1 id=1 cnt=14 pid=0 pos=1 obj=0 op='NESTED LOOPS (cr=24 pr=0 pw=0 time=120 us)'
STAT #1 id=2 cnt=14 pid=1 pos=1 obj=51151 op='TABLE ACCESS FULL EMP (cr=8 pr=0 pw=0 time=263 us)'
STAT #1 id=3 cnt=14 pid=1 pos=2 obj=51149 op='TABLE ACCESS BY INDEX ROWID DEPT (cr=16 pr=0 pw=0 time=471 us)'
STAT #1 id=4 cnt=14 pid=3 pos=1 obj=51150 op='INDEX UNIQUE SCAN PK_DEPT (cr=2 pr=0 pw=0 time=199 us)'
*** 2016-04-14 12:38:42.312
XCTEND rlbk=0, rd_only=1
TKPROF转换格式化的效果：
TKPROF: Release 10.2.0.1.0 - Production on 星期四 4月 14 12:39:43 2016
Copyright (c) 1982, 2005, Oracle. All rights reserved.
Trace file: orcl_ora_1200.trc
Sort options: prsela exeela 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
********************************************************************************
error connecting to database using: ;
ORA-01005: 给出空口令; 登录被拒绝
EXPLAIN PLAN option disabled.
********************************************************************************
select t1.empno, t1.ename, t2.deptno, t2.dname
from
emp t1, dept t2 where t1.deptno = t2.deptno
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.01 0.00 0 0 0 0
Execute 1 0.00 0.00 0 0 0 0
Fetch 2 0.00 0.00 0 24 0 14
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 4 0.01 0.00 0 24 0 14
Misses in library cache during parse: 1
Optimizer mode: ALL_ROWS
Parsing user id: 54
Rows Row Source Operation
------- ---------------------------------------------------
14 NESTED LOOPS (cr=24 pr=0 pw=0 time=120 us)
14 TABLE ACCESS FULL EMP (cr=8 pr=0 pw=0 time=263 us)
14 TABLE ACCESS BY INDEX ROWID DEPT (cr=16 pr=0 pw=0 time=471 us)
14 INDEX UNIQUE SCAN PK_DEPT (cr=2 pr=0 pw=0 time=199 us)(object id 51150)
********************************************************************************
select t1.empno, t1.ename, t2.deptno, t2.dname
from
emp t1, dept t2 where t1.deptno = t2.deptno(+)
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 24 0 14
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 4 0.00 0.00 0 24 0 14
Misses in library cache during parse: 0
Optimizer mode: ALL_ROWS
Parsing user id: 54
Rows Row Source Operation
------- ---------------------------------------------------
14 NESTED LOOPS OUTER (cr=24 pr=0 pw=0 time=135 us)
14 TABLE ACCESS FULL EMP (cr=8 pr=0 pw=0 time=246 us)
14 TABLE ACCESS BY INDEX ROWID DEPT (cr=16 pr=0 pw=0 time=472 us)
14 INDEX UNIQUE SCAN PK_DEPT (cr=2 pr=0 pw=0 time=200 us)(object id 51150)
********************************************************************************
OVERALL TOTALS FOR ALL NON-RECURSIVE STATEMENTS
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 2 0.01 0.00 0 0 0 0
Execute 3 0.00 0.00 0 0 0 0
Fetch 4 0.00 0.00 0 48 0 28
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 9 0.01 0.00 0 48 0 28
Misses in library cache during parse: 1
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 0 0.00 0.00 0 0 0 0
Fetch 0 0.00 0.00 0 0 0 0
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 0 0.00 0.00 0 0 0 0
Misses in library cache during parse: 0
3 user SQL statements in session.
0 internal SQL statements in session.
3 SQL statements in session.
0 statements EXPLAINed in this session.
********************************************************************************
Trace file: orcl_ora_1200.trc
Trace file compatibility: 10.01.00
Sort options: prsela exeela fchela
1 session in tracefile.
3 user SQL statements in trace file.
0 internal SQL statements in trace file.
3 SQL statements in trace file.
3 unique SQL statements in trace file.
57 lines in trace file.
21 elapsed seconds in trace file.
下面列出一些tkprof生成文件中常看到的几个性能方面的数字：
count：表示执行的数据库调用数量。
cpu：表示处理数据调用花去的CPU时间，以秒为单位。
elapsed：表示处理数据库调用花费的总时间，以秒为单位。
disk：表示物理读的数据块数量。
query：表示在consistent mode下从高速缓存逻辑读取的块数量。
current：表示在当前模式下从高速缓存逻辑读取的块数量。
rows：表示处理的数据行数量。
****************************************************************************************************************************************************************************************************************************************************************************************************************************************************************************************************************************下面的测试数据：
主要是测试全表扫描和索引扫描 性能。
查看大量数据。还是要走全表扫描 效率快些。虽然CBO在一定数据还是走索引扫描，通过trace文件对比，就可以知全表扫描效率稍快些。
TKPROF: Release 10.2.0.1.0 - Production on 星期四 4月 14 14:41:02 2016
Copyright (c) 1982, 2005, Oracle. All rights reserved.
Trace file: orcl_ora_8072.trc
Sort options: prsela exeela 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
********************************************************************************
error connecting to database using: SH/SH
ORA-28000: the account is locked
EXPLAIN PLAN option disabled.
********************************************************************************
select *
from
t500w t where t.id <= 610000
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.00 0.01 0 2 0 0
Execute 1 0.00 0.00 0 0 0 0
Fetch 40668 1.70 2.01 2609 83781 0 610000
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 40670 1.70 2.02 2609 83783 0 610000
Misses in library cache during parse: 1
Optimizer mode: ALL_ROWS
Parsing user id: 54
Rows Row Source Operation
------- ---------------------------------------------------
610000 TABLE ACCESS BY INDEX ROWID T500W (cr=83781 pr=2609 pw=0 time=10405626 us)
610000 INDEX RANGE SCAN IND_T500W (cr=41936 pr=1348 pw=0 time=2459859 us)(object id 53750)
********************************************************************************
select *
from
t500w t where t.id <= 620000
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.00 0.04 0 2 0 0
Execute 1 0.00 0.00 0 0 0 0
Fetch 41335 1.00 1.59 9956 52720 0 620000
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 41337 1.00 1.63 9956 52722 0 620000
Misses in library cache during parse: 1
Optimizer mode: ALL_ROWS
Parsing user id: 54
Rows Row Source Operation
------- ---------------------------------------------------
620000 TABLE ACCESS FULL T500W (cr=52720 pr=9956 pw=0 time=2481416 us)
********************************************************************************
OVERALL TOTALS FOR ALL NON-RECURSIVE STATEMENTS
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 11 0.01 0.05 0 8 0 0
Execute 12 0.00 0.00 0 9 5 5
Fetch 82011 2.73 3.61 12565 136501 0 1230036
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 82034 2.75 3.67 12565 136518 5 1230041
Misses in library cache during parse: 4
OVERALL TOTALS FOR ALL RECURSIVE STATEMENTS
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 18 0.01 0.00 0 0 0 0
Execute 24 0.01 0.00 0 2 23 5
Fetch 22 0.12 0.11 0 336 34 53
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 64 0.15 0.12 0 338 57 58
Misses in library cache during parse: 2
Misses in library cache during execute: 2
28 user SQL statements in session.
3 internal SQL statements in session.
31 SQL statements in session.
0 statements EXPLAINed in this session.
********************************************************************************
Trace file: orcl_ora_8072.trc
Trace file compatibility: 10.01.00
Sort options: prsela exeela fchela
5 sessions in tracefile.
70 user SQL statements in trace file.
7 internal SQL statements in trace file.
31 SQL statements in trace file.
17 unique SQL statements in trace file.
82327 lines in trace file.
55 elapsed seconds in trace file.
参考：
http://blog.csdn.net/weiwenhp/article/details/6932835
http://yedward.net/?id=140
1353
被折叠的 条评论
为什么被折叠?
到【灌水乐园】发言
