Tkprof可以分析oracle跟踪文件，然后得出一个清晰的报告。主要就是让我们查看起来更方便。使用方法：
SQL> select * from v$mystat where rownum=1;
SID STATISTIC# VALUE
---------- ---------- ----------
173 0 0
SQL> select s.USERNAME,s.SID,s.SERIAL#,s.COMMAND from v$session s where username='SYS';
USERNAME SID SERIAL# COMMAND
------------------------------ ---------- ---------- ----------
SYS 23 3129 0
SYS 173 8497 3
SQL> show parameter sql_trace
NAME TYPE VALUE
------------------------------------ ----------- ------------------------------
sql_trace boolean FALSE
SQL> alter session set sql_trace='TRUE';
alter session set sql_trace='TRUE'
ORA-00922: missing or invalid option
SQL> alter session set sql_trace=TRUE;
Session altered
SQL> show parameter sql_trace
NAME TYPE VALUE
------------------------------------ ----------- ------------------------------
sql_trace boolean FALSE
SQL> exec sys.dbms_system.set_sql_trace_in_session(173,8497,true);
PL/SQL procedure successfully completed
SQL> show parameter user_dump_dest
NAME TYPE VALUE
------------------------------------ ----------- ------------------------------
user_dump_dest string /pmsdb/oracle/TEST/diag/rdbms/test/TEST/trace
SQL> create table t1 as select * from dba_objects;
create table t1 as select * from dba_objects
ORA-00955: name is already used by an existing object
SQL> drop table t1;
Table dropped
SQL> exec sys.dbms_system.set_sql_trace_in_session(173,8497,false);
PL/SQL procedure successfully completed
查看trace文件，内容很是乱，看不明白：
*** 2013-12-30 14:32:16.314
Ioctl ASYNC_CONFIG error, errno = 1
=====================
*** 2013-12-30 16:25:58.377
*** SESSION ID:(173.8497) 2013-12-30 16:25:58.377
*** SERVICE NAME:(TEST) 2013-12-30 16:25:58.377
*** MODULE NAME:(PL/SQL Developer) 2013-12-30 16:25:58.377
*** ACTION NAME:(Command Window - New) 2013-12-30 16:25:58.377
PARSING IN CURSOR #11529215044981930632 len=34 dep=0 uid=0 oct=42 lid=0 tim=5961986311313 hv=4038253584 ad='9fffffffbf39fe10' sqlid=
'aag2y37sb5r0h'
alter session set sql_trace=TRUE
END OF STMT
EXEC #11529215044981930632:c=0,e=71,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=1,plh=0,tim=5961986311309
CLOSE #11529215044981930632:c=0,e=4,dep=0,type=0,tim=5961986418194
=====================
PARSING IN CURSOR #11529215044981902952 len=61 dep=0 uid=0 oct=47 lid=0 tim=5961986418265 hv=356401299 ad='c0000004fbabde88' sqlid='
9m7787camwh4m'
begin :id := sys.dbms_transaction.local_transaction_id; end;
END OF STMT
PARSE #11529215044981902952:c=0,e=25,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=0,tim=5961986418264
EXEC #11529215044981902952:c=0,e=53,p=0,cr=0,cu=0,mis=0,r=1,dep=0,og=1,plh=0,tim=5961986418389
*** 2013-12-30 16:26:22.026
CLOSE #11529215044981902952:c=0,e=48,dep=0,type=3,tim=5962009988417
=====================
PARSING IN CURSOR #11529215044981930632 len=58 dep=0 uid=0 oct=3 lid=0 tim=5962009989924 hv=3223932713 ad='c0000004fbd1fd80' sqlid='
74d9jtg02kmt9'
select sys_context('userenv', 'current_schema') from dual
END OF STMT
PARSE #11529215044981930632:c=10000,e=1348,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=1,plh=1546270724,tim=5962009989921
EXEC #11529215044981930632:c=0,e=46,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=1546270724,tim=5962009990063
FETCH #11529215044981930632:c=0,e=32,p=0,cr=0,cu=0,mis=0,r=1,dep=0,og=1,plh=1546270724,tim=5962010017688
STAT #11529215044981930632 id=1 cnt=1 pid=0 pos=1 obj=0 op='FAST DUAL (cr=0 pr=0 pw=0 time=6 us cost=2 size=0 card=1)'
*** 2013-12-30 16:26:29.591
CLOSE #11529215044981930632:c=0,e=22,dep=0,type=0,tim=5962017552966
=====================
PARSING IN CURSOR #11529215044981930632 len=58 dep=0 uid=0 oct=3 lid=0 tim=5962017553263 hv=3223932713 ad='c0000004fbd1fd80' sqlid='
74d9jtg02kmt9'
select sys_context('userenv', 'current_schema') from dual
END OF STMT
PARSE #11529215044981930632:c=0,e=129,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=1546270724,tim=5962017553260
EXEC #11529215044981930632:c=0,e=48,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=1546270724,tim=5962017553396
FETCH #11529215044981930632:c=0,e=36,p=0,cr=0,cu=0,mis=0,r=1,dep=0,og=1,plh=1546270724,tim=5962017583499
STAT #11529215044981930632 id=1 cnt=1 pid=0 pos=1 obj=0 op='FAST DUAL (cr=0 pr=0 pw=0 time=4 us cost=2 size=0 card=1)'
*** 2013-12-30 16:26:33.206
CLOSE #11529215044981930632:c=0,e=24,dep=0,type=0,tim=5962021167524
=====================
PARSING IN CURSOR #11529215044981930632 len=21 dep=0 uid=0 oct=3 lid=0 tim=5962021169064 hv=2564406738 ad='c0000004fb981e10' sqlid='
cf06fwacdmgfk'
select 'x' from dual
END OF STMT
PARSE #11529215044981930632:c=0,e=1345,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=1,plh=1546270724,tim=5962021169061
EXEC #11529215044981930632:c=0,e=45,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=1546270724,tim=5962021169200
FETCH #11529215044981930632:c=0,e=21,p=0,cr=0,cu=0,mis=0,r=1,dep=0,og=1,plh=1546270724,tim=5962021196882
STAT #11529215044981930632 id=1 cnt=1 pid=0 pos=1 obj=0 op='FAST DUAL (cr=0 pr=0 pw=0 time=5 us cost=2 size=0 card=1)'
*** 2013-12-30 16:26:33.277
CLOSE #11529215044981930632:c=0,e=4,dep=0,type=0,tim=5962021238641
PARSE #11529215044981902952:c=0,e=38,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=0,tim=5962021238739
EXEC #11529215044981902952:c=0,e=121,p=0,cr=0,cu=0,mis=0,r=1,dep=0,og=1,plh=0,tim=5962021238889
CLOSE #11529215044981902952:c=0,e=18,dep=0,type=3,tim=5962021269988
=====================
PARSING IN CURSOR #11529215044981933152 len=132 dep=1 uid=0 oct=3 lid=0 tim=5962021271462 hv=2328831744 ad='c0000004fbec8898' sqlid=
'ga9j9xk5cy9s0'
select /*+ index(idl_sb4$ i_idl_sb41) +*/ piece#,length,piece from idl_sb4$ where obj#=:1 and part=:2 and version=:3 order by piece#
END OF STMT
PARSE #11529215044981933152:c=0,e=712,p=0,cr=0,cu=0,mis=1,r=0,dep=1,og=4,plh=0,tim=5962021271461
EXEC #11529215044981933152:c=0,e=1199,p=0,cr=0,cu=0,mis=1,r=0,dep=1,og=4,plh=467424113,tim=5962021272784
FETCH #11529215044981933152:c=0,e=178,p=1,cr=4,cu=0,mis=0,r=1,dep=1,og=4,plh=467424113,tim=5962021273010
FETCH #11529215044981933152:c=0,e=27,p=0,cr=3,cu=0,mis=0,r=1,dep=1,og=4,plh=467424113,tim=5962021273105
FETCH #11529215044981933152:c=0,e=5,p=0,cr=1,cu=0,mis=0,r=0,dep=1,og=4,plh=467424113,tim=5962021273133
STAT #11529215044981933152 id=1 cnt=2 pid=0 pos=1 obj=219 op='TABLE ACCESS BY INDEX ROWID IDL_SB4$ (cr=6 pr=1 pw=0 time=176 us cost=
3 size=19 card=1)'
STAT #11529215044981933152 id=2 cnt=2 pid=1 pos=1 obj=230 op='INDEX RANGE SCAN I_IDL_SB41 (cr=4 pr=0 pw=0 time=84 us cost=2 size=0 c
ard=1)'
CLOSE #11529215044981933152:c=0,e=6,dep=1,type=0,tim=5962021273223
=====================
PARSING IN CURSOR #11529215044981933152 len=132 dep=1 uid=0 oct=3 lid=0 tim=5962021273724 hv=4260389146 ad='c0000004fce6fa28' sqlid=
'cvn54b7yz0s8u'
select /*+ index(idl_ub1$ i_idl_ub11) +*/ piece#,length,piece from idl_ub1$ where obj#=:1 and part=:2 and version=:3 order by piece#
END OF STMT
PARSE #11529215044981933152:c=0,e=481,p=0,cr=0,cu=0,mis=1,r=0,dep=1,og=4,plh=0,tim=5962021273723
EXEC #11529215044981933152:c=0,e=773,p=0,cr=0,cu=0,mis=1,r=0,dep=1,og=4,plh=2991757387,tim=5962021274597
FETCH #11529215044981933152:c=0,e=103,p=1,cr=4,cu=0,mis=0,r=1,dep=1,og=4,plh=2991757387,tim=5962021274732
FETCH #11529215044981933152:c=0,e=8,p=0,cr=1,cu=0,mis=0,r=0,dep=1,og=4,plh=2991757387,tim=5962021274776
STAT #11529215044981933152 id=1 cnt=1 pid=0 pos=1 obj=216 op='TABLE ACCESS BY INDEX ROWID IDL_UB1$ (cr=4 pr=1 pw=0 time=99 us cost=3
size=18 card=1)'
转化：
$ tkprof TEST_ora_4133.trc TEST_ora_4133.txt
TKPROF: Release 11.2.0.3.0 - Development on Mon Dec 30 16:34:16 2013
Copyright (c) 1982, 2011, Oracle and/or its affiliates. All rights reserved.
$ ll
-rw-r----- 1 oratest oinstall 343655 Dec 30 16:30 TEST_ora_4133.trc
-rw-r----- 1 oratest oinstall 481 Dec 30 16:30 TEST_ora_4133.trm
-rw-r--r-- 1 oratest oinstall 166249 Dec 30 16:34 TEST_ora_4133.txt
-rw-r----- 1 oratest oinstall 319271691 Dec 30 14:00 alert_TEST.log
查看内容：
$ more TEST_ora_4133.txt---内容方便查看
TKPROF: Release 11.2.0.3.0 - Development on Mon Dec 30 16:34:16 2013
Copyright (c) 1982, 2011, Oracle and/or its affiliates. All rights reserved.
Trace file: TEST_ora_4133.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
********************************************************************************
SQL ID: aag2y37sb5r0h Plan Hash: 0
alter session set sql_trace=TRUE
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 0 0 0
Fetch 0 0.00 0.00 0 0 0 0
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 1 0.00 0.00 0 0 0 0
Misses in library cache during parse: 0
Misses in library cache during execute: 1
Optimizer mode: ALL_ROWS
Parsing user id: SYS
********************************************************************************
SQL ID: 74d9jtg02kmt9 Plan Hash: 1546270724
select sys_context('userenv', 'current_schema')
from
dual
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 2 0.01 0.00 0 0 0 0
Execute 2 0.00 0.00 0 0 0 0
Fetch 2 0.00 0.00 0 0 0 2
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 6 0.01 0.00 0 0 0 2
Misses in library cache during parse: 1
Optimizer mode: ALL_ROWS
Parsing user id: SYS
Number of plan statistics captured: 2
Rows (1st) Rows (avg) Rows (max) Row Source Operation
---------- ---------- ---------- ---------------------------------------------------
1 1 1 FAST DUAL (cr=0 pr=0 pw=0 time=5 us cost=2 size=0 card=1)
********************************************************************************
SQL ID: cf06fwacdmgfk Plan Hash: 1546270724
oracle的跟踪文件该有SQL和PL/SQL调用，定时信息、等待事件信息，逻辑I/O和物理I/O的数量、CPU和挂钟时间、已经处理的行数、带有行记数的查询计划等。
来自 “ ITPUB博客 ” ，链接：http://blog.itpub.net/24500180/viewspace-1065791/，如需转载，请注明出处，否则将追究法律责任。
转载于:http://blog.itpub.net/24500180/viewspace-1065791/
87
被折叠的 条评论
为什么被折叠?
到【灌水乐园】发言
