如何跟踪SQL（SQL_TRACE & TKPROF）
我们在做SQL性能调优的时候，首先就是跟踪这个SQL的执行过程。
环境
- DB:Oracle10g
SQL_TRACE
SQL TRACE是Oracle提供的用于进行SQL跟踪的手段，是强有力的辅助诊断工具。在日常的数据库问题诊断和解决中，SQL_TRACE是非常常用的方法。
如何使用SQL_TRACE
-- 首先设置SQL_TRACE的文件标示，否则这生成的文件可不太好找
alter session set tracefile_identifier="oracle_test";
--对当前的会话 启动SQL_TRACE。
alter session set sql_trace=true;
--开始执行想要被跟踪的SQL
select * from dba_objects where rownum<10;
--对当前的会话 关闭SQL_TRACE。
alter session set sql_trace=false;
- SQLTRACE生成的trace文件默认路径是$ORACLEBASE/admin/SID/udump这个文件夹中。
SQL_TRACE的其它设定
--允许SQL_TRACE和其他的一些动态性能视图收集与时间有关的参数
alter session set titimed_statistics=true
--指定跟踪文件的大小
alter system set max_dump_file_size=500;
--指定跟踪文件的路径
alter system set user_dump_dest=/oracle/oracle/diag/rdbms/orcl/orcl/trace;
SAMPLE
Dump file d:\oracle\product\10.2.0\admin\orcl\udump\orcl_ora_2508_oracle_test.trc
Sun Sep 18 20:35:12 2011
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 : 1 - type 586, 1 Physical Cores
Process Affinity : 0x00000000
Memory (Avail/Total): Ph:1254M/1999M, Ph+PgF:2995M/3896M, VA:1285M/2047M
Instance name: orcl
Redo thread mounted by this instance: 1
Oracle process number: 17
Windows thread id: 2508, image: ORACLE.EXE (SHAD)
*** 2011-09-18 20:35:12.223
*** SERVICE NAME:(SYS$USERS) 2011-09-18 20:35:12.223
*** SESSION ID:(149.39) 2011-09-18 20:35:12.223
=====================
PARSING IN CURSOR #1 len=32 dep=0 uid=0 oct=42 lid=0 tim=1150471365 hv=1569151342 ad='2e897bdc'
alter session set sql_trace=true
END OF STMT
EXEC #1:c=0,e=269,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=1,tim=1150471354
*** 2011-09-18 20:35:44.810
=====================
PARSING IN CURSOR #2 len=348 dep=1 uid=0 oct=3 lid=0 tim=1183056108 hv=2512561537 ad='336ea480'
select name,intcol#,segcol#,type#,length,nvl(precision#,0),decode(type#,2,nvl(scale,-127/*MAXSB1MINAL*/),178,scale,179,scale,180,scale,181,scale,182,scale,183,scale,231,scale,0),null$,fixedstorage,nvl(deflength,0),default$,rowid,col#,property, nvl(charsetid,0),nvl(charsetform,0),spare1,spare2,nvl(spare3,0) from col$ where obj#=:1 order by intcol#
END OF STMT
PARSE #2:c=0,e=196,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,tim=1183056097
EXEC #2:c=0,e=354,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,tim=1183058676
FETCH #2:c=0,e=461,p=0,cr=3,cu=0,mis=0,r=1,dep=1,og=4,tim=1183059218
FETCH #2:c=0,e=12,p=0,cr=0,cu=0,mis=0,r=1,dep=1,og=4,tim=1183059299
FETCH #2:c=0,e=12,p=0,cr=0,cu=0,mis=0,r=1,dep=1,og=4,tim=1183059365
FETCH #2:c=0,e=17,p=0,cr=0,cu=0,mis=0,r=1,dep=1,og=4,tim=1183059435
FETCH #2:c=0,e=11,p=0,cr=0,cu=0,mis=0,r=1,dep=1,og=4,tim=1183059499
FETCH #2:c=0,e=10,p=0,cr=0,cu=0,mis=0,r=1,dep=1,og=4,tim=1183059577
FETCH #2:c=0,e=10,p=0,cr=0,cu=0,mis=0,r=1,dep=1,og=4,tim=1183059641
FETCH #2:c=0,e=11,p=0,cr=0,cu=0,mis=0,r=1,dep=1,og=4,tim=1183059706
FETCH #2:c=0,e=12,p=0,cr=0,cu=0,mis=0,r=1,dep=1,og=4,tim=1183059771
FETCH #2:c=0,e=10,p=0,cr=0,cu=0,mis=0,r=1,dep=1,og=4,tim=1183059850
FETCH #2:c=0,e=11,p=0,cr=0,cu=0,mis=0,r=1,dep=1,og=4,tim=1183059914
FETCH #2:c=0,e=11,p=0,cr=0,cu=0,mis=0,r=1,dep=1,og=4,tim=1183059979
FETCH #2:c=0,e=11,p=0,cr=0,cu=0,mis=0,r=1,dep=1,og=4,tim=1183060056
FETCH #2:c=0,e=40,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,tim=1183060149
STAT #2 id=1 cnt=13 pid=0 pos=1 obj=0 op='SORT ORDER BY (cr=3 pr=0 pw=0 time=487 us)'
STAT #2 id=2 cnt=13 pid=1 pos=1 obj=21 op='TABLE ACCESS CLUSTER COL$ (cr=3 pr=0 pw=0 time=459 us)'
STAT #2 id=3 cnt=1 pid=2 pos=1 obj=3 op='INDEX UNIQUE SCAN I_OBJ# (cr=2 pr=0 pw=0 time=132 us)'
=====================
PARSING IN CURSOR #2 len=37 dep=1 uid=0 oct=3 lid=0 tim=1183060701 hv=1398610540 ad='336d5c48'
select text from view$ where rowid=:1
END OF STMT
PARSE #2:c=0,e=150,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,tim=1183060692
EXEC #2:c=0,e=40,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,tim=1183060912
FETCH #2:c=0,e=88,p=0,cr=2,cu=0,mis=0,r=1,dep=1,og=4,tim=1183061053
STAT #2 id=1 cnt=1 pid=0 pos=1 obj=63 op='TABLE ACCESS BY USER ROWID VIEW$ (cr=1 pr=0 pw=0 time=61 us)'
=====================
PARSING IN CURSOR #2 len=789 dep=1 uid=0 oct=3 lid=0 tim=1183062979 hv=3159716790 ad='336d80c0'
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#
END OF STMT
PARSE #2:c=0,e=297,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,tim=1183062943
EXEC #2:c=10015,e=866,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,tim=1183064269
FETCH #2:c=0,e=3018,p=0,cr=11,cu=0,mis=0,r=1,dep=1,og=4,tim=1183067531
=====================
PARSING IN CURSOR #3 len=67 dep=1 uid=0 oct=3 lid=0 tim=1183068045 hv=2280069326 ad='336eaa70'
select pos#,intcol#,col#,spare1,bo#,spare2 from icol$ where obj#=:1
END OF STMT
PARSE #3:c=0,e=98,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,tim=1183068036
EXEC #3:c=0,e=113,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,tim=1183068857
FETCH #3:c=0,e=99,p=0,cr=2,cu=0,mis=0,r=0,dep=1,og=4,tim=1183069162
STAT #3 id=1 cnt=0 pid=0 pos=1 obj=20 op='TABLE ACCESS BY INDEX ROWID ICOL$ (cr=2 pr=0 pw=0 time=111 us)'
STAT #3 id=2 cnt=0 pid=1 pos=1 obj=40 op='INDEX RANGE SCAN I_ICOL1 (cr=2 pr=0 pw=0 time=69 us)'
FETCH #2:c=0,e=22,p=0,cr=0,cu=0,mis=0,r=1,dep=1,og=4,tim=1183069680
=====================
PARSING IN CURSOR #3 len=67 dep=1 uid=0 oct=3 lid=0 tim=1183069955 hv=2280069326 ad='336eaa70'
select pos#,intcol#,col#,spare1,bo#,spare2 from icol$ where obj#=:1
END OF STMT
EXEC #3:c=0,e=56,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,tim=1183069947
FETCH #3:c=0,e=53,p=0,cr=2,cu=0,mis=0,r=0,dep=1,og=4,tim=1183070674
FETCH #2:c=0,e=20,p=0,cr=0,cu=0,mis=0,r=1,dep=1,og=4,tim=1183070845
=====================
PARSING IN CURSOR #3 len=67 dep=1 uid=0 oct=3 lid=0 tim=1183071095 hv=2280069326 ad='336eaa70'
select pos#,intcol#,col#,spare1,bo#,spare2 from icol$ where obj#=:1
END OF STMT
EXEC #3:c=0,e=57,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,tim=1183071086
FETCH #3:c=0,e=79,p=0,cr=3,cu=0,mis=0,r=1,dep=1,og=4,tim=1183071825
FETCH #3:c=0,e=37,p=0,cr=1,cu=0,mis=0,r=0,dep=1,og=4,tim=1183072013
FETCH #2:c=0,e=13,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,tim=1183072197
STAT #2 id=1 cnt=3 pid=0 pos=1 obj=0 op='SORT ORDER BY (cr=11 pr=0 pw=0 time=3609 us)'
STAT #2 id=2 cnt=3 pid=1 pos=1 obj=0 op='HASH JOIN OUTER (cr=11 pr=0 pw=0 time=3062 us)'
STAT #2 id=3 cnt=3 pid=2 pos=1 obj=0 op='NESTED LOOPS OUTER (cr=8 pr=0 pw=0 time=735 us)'
STAT #2 id=4 cnt=3 pid=3 pos=1 obj=19 op='TABLE ACCESS CLUSTER IND$ (cr=6 pr=0 pw=0 time=375 us)'
STAT #2 id=5 cnt=1 pid=4 pos=1 obj=3 op='INDEX UNIQUE SCAN I_OBJ# (cr=2 pr=0 pw=0 time=130 us)'
STAT #2 id=6 cnt=0 pid=3 pos=2 obj=710 op='TABLE ACCESS BY INDEX ROWID IND_STATS$ (cr=2 pr=0 pw=0 time=230 us)'
STAT #2 id=7 cnt=0 pid=6 pos=1 obj=711 op='INDEX UNIQUE SCAN I_IND_STATS$_OBJ# (cr=2 pr=0 pw=0 time=105 us)'
STAT #2 id=8 cnt=0 pid=2 pos=2 obj=0 op='VIEW (cr=3 pr=0 pw=0 time=401 us)'
STAT #2 id=9 cnt=0 pid=8 pos=1 obj=0 op='SORT GROUP BY (cr=3 pr=0 pw=0 time=358 us)'
STAT #2 id=10 cnt=0 pid=9 pos=1 obj=31 op='TABLE ACCESS BY INDEX ROWID CDEF$ (cr=3 pr=0 pw=0 time=212 us)'
STAT #2 id=11 cnt=7 pid=10 pos=1 obj=51 op='INDEX RANGE SCAN I_CDEF2 (cr=2 pr=0 pw=0 time=165 us)'
=====================
PARSING IN CURSOR #3 len=348 dep=1 uid=0 oct=3 lid=0 tim=1183074471 hv=2512561537 ad='336ea480'
select name,intcol#,segcol#,type#,length,nvl(precision#,0),decode(type#,2,nvl(scale,-127/*MAXSB1MINAL*/),178,scale,179,scale,180,scale,181,scale,182,scale,183,scale,231,scale,0),null$,fixedstorage,nvl(deflength,0),default$,rowid,col#,property, nvl(charsetid,0),nvl(charsetform,0),spare1,spare2,nvl(spare3,0) from col$ where obj#=:1 order by intcol#
END OF STMT
EXEC #3:c=0,e=124,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,tim=1183074463
FETCH #3:c=0,e=247,p=0,cr=3,cu=0,mis=0,r=1,dep=1,og=4,tim=1183075379
FETCH #3:c=0,e=12,p=0,cr=0,cu=0,mis=0,r=1,dep=1,og=4,tim=1183075550
FETCH #3:c=0,e=11,p=0,cr=0,cu=0,mis=0,r=1,dep=1,og=4,tim=1183075733
FETCH #3:c=0,e=11,p=0,cr=0,cu=0,mis=0,r=1,dep=1,og=4,tim=1183075897
FETCH #3:c=0,e=11,p=0,cr=0,cu=0,mis=0,r=1,dep=1,og=4,tim=1183076055
FETCH #3:c=0,e=11,p=0,cr=0,cu=0,mis=0,r=1,dep=1,og=4,tim=1183076216
FETCH #3:c=0,e=11,p=0,cr=0,cu=0,mis=0,r=1,dep=1,og=4,tim=1183076386
FETCH #3:c=0,e=11,p=0,cr=0,cu=0,mis=0,r=1,dep=1,og=4,tim=1183076596
FETCH #3:c=0,e=11,p=0,cr=0,cu=0,mis=0,r=1,dep=1,og=4,tim=1183076685
FETCH #3:c=0,e=10,p=0,cr=0,cu=0,mis=0,r=1,dep=1,og=4,tim=1183076727
FETCH #3:c=0,e=11,p=0,cr=0,cu=0,mis=0,r=1,dep=1,og=4,tim=1183076770
FETCH #3:c=0,e=10,p=0,cr=0,cu=0,mis=0,r=1,dep=1,og=4,tim=1183076812
FETCH #3:c=0,e=11,p=0,cr=0,cu=0,mis=0,r=1,dep=1,og=4,tim=1183076855
FETCH #3:c=0,e=11,p=0,cr=0,cu=0,mis=0,r=1,dep=1,og=4,tim=1183076898
FETCH #3:c=0,e=10,p=0,cr=0,cu=0,mis=0,r=1,dep=1,og=4,tim=1183076940
FETCH #3:c=0,e=10,p=0,cr=0,cu=0,mis=0,r=1,dep=1,og=4,tim=1183076982
FETCH #3:c=0,e=10,p=0,cr=0,cu=0,mis=0,r=1,dep=1,og=4,tim=1183077024
FETCH #3:c=0,e=11,p=0,cr=0,cu=0,mis=0,r=1,dep=1,og=4,tim=1183077067
FETCH #3:c=0,e=11,p=0,cr=0,cu=0,mis=0,r=1,dep=1,og=4,tim=1183077109
FETCH #3:c=0,e=11,p=0,cr=0,cu=0,mis=0,r=1,dep=1,og=4,tim=1183077154
FETCH #3:c=0,e=11,p=0,cr=0,cu=0,mis=0,r=1,dep=1,og=4,tim=1183077196
FETCH #3:c=0,e=11,p=0,cr=0,cu=0,mis=0,r=1,dep=1,og=4,tim=1183077239
FETCH #3:c=0,e=10,p=0,cr=0,cu=0,mis=0,r=1,dep=1,og=4,tim=1183077281
FETCH #3:c=0,e=29,p=0,cr=0,cu=0,mis=0,r=1,dep=1,og=4,tim=1183077396
FETCH #3:c=0,e=11,p=0,cr=0,cu=0,mis=0,r=1,dep=1,og=4,tim=1183077481
FETCH #3:c=0,e=11,p=0,cr=0,cu=0,mis=0,r=1,dep=1,og=4,tim=1183077525
FETCH #3:c=0,e=12,p=0,cr=0,cu=0,mis=0,r=1,dep=1,og=4,tim=1183077569
FETCH #3:c=0,e=10,p=0,cr=0,cu=0,mis=0,r=1,dep=1,og=4,tim=1183077617
FETCH #3:c=0,e=11,p=0,cr=0,cu=0,mis=0,r=1,dep=1,og=4,tim=1183077660
FETCH #3:c=0,e=11,p=0,cr=0,cu=0,mis=0,r=1,dep=1,og=4,tim=1183077702
FETCH #3:c=0,e=11,p=0,cr=0,cu=0,mis=0,r=1,dep=1,og=4,tim=1183077745
FETCH #3:c=0,e=10,p=0,cr=0,cu=0,mis=0,r=1,dep=1,og=4,tim=1183077786
FETCH #3:c=0,e=10,p=0,cr=0,cu=0,mis=0,r=1,dep=1,og=4,tim=1183077828
FETCH #3:c=0,e=11,p=0,cr=0,cu=0,mis=0,r=1,dep=1,og=4,tim=1183077871
FETCH #3:c=0,e=11,p=0,cr=0,cu=0,mis=0,r=1,dep=1,og=4,tim=1183077913
FETCH #3:c=0,e=11,p=0,cr=0,cu=0,mis=0,r=1,dep=1,og=4,tim=1183077966
FETCH #3:c=0,e=17,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,tim=1183078014
=====================
PARSING IN CURSOR #2 len=169 dep=1 uid=0 oct=3 lid=0 tim=1183078209 hv=1173719687 ad='336ddebc'
select col#, grantee#, privilege#,max(mod(nvl(option$,0),2)) from objauth$ where obj#=:1 and col# is not null group by privilege#, col#, grantee# order by col#, grantee#
END OF STMT
PARSE #2:c=0,e=111,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,tim=1183078200
EXEC #2:c=0,e=109,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,tim=1183078387
FETCH #2:c=0,e=117,p=0,cr=2,cu=0,mis=0,r=0,dep=1,og=4,tim=1183078537
STAT #2 id=1 cnt=0 pid=0 pos=1 obj=0 op='SORT GROUP BY (cr=2 pr=0 pw=0 time=171 us)'
STAT #2 id=2 cnt=0 pid=1 pos=1 obj=57 op='TABLE ACCESS BY INDEX ROWID OBJAUTH$ (cr=2 pr=0 pw=0 time=117 us)'
STAT #2 id=3 cnt=0 pid=2 pos=1 obj=103 op='INDEX RANGE SCAN I_OBJAUTH1 (cr=2 pr=0 pw=0 time=73 us)'
=====================
PARSING IN CURSOR #3 len=151 dep=1 uid=0 oct=3 lid=0 tim=1183078666 hv=4139184264 ad='336dd594'
select grantee#,privilege#,nvl(col#,0),max(mod(nvl(option$,0),2))from objauth$ where obj#=:1 group by grantee#,privilege#,nvl(col#,0) order by grantee#
END OF STMT
PARSE #3:c=0,e=59,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,tim=1183078657
EXEC #3:c=0,e=109,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,tim=1183078817
FETCH #3:c=0,e=74,p=0,cr=2,cu=0,mis=0,r=0,dep=1,og=4,tim=1183078922
STAT #3 id=1 cnt=0 pid=0 pos=1 obj=0 op='SORT GROUP BY (cr=2 pr=0 pw=0 time=140 us)'
STAT #3 id=2 cnt=0 pid=1 pos=1 obj=57 op='TABLE ACCESS BY INDEX ROWID OBJAUTH$ (cr=2 pr=0 pw=0 time=73 us)'
STAT #3 id=3 cnt=0 pid=2 pos=1 obj=103 op='INDEX RANGE SCAN I_OBJAUTH1 (cr=2 pr=0 pw=0 time=31 us)'
=====================
PARSING IN CURSOR #2 len=141 dep=1 uid=0 oct=3 lid=0 tim=1183079112 hv=793605046 ad='336b5b14'
select col#,intcol#,toid,version#,packed,intcols,intcol#s,flags, synobj#, nvl(typidcol#, 0) from coltype$ where obj#=:1 order by intcol# desc
END OF STMT
PARSE #2:c=0,e=115,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,tim=1183079103
EXEC #2:c=0,e=106,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,tim=1183079267
FETCH #2:c=0,e=105,p=0,cr=3,cu=0,mis=0,r=0,dep=1,og=4,tim=1183079467
STAT #2 id=1 cnt=0 pid=0 pos=1 obj=0 op='SORT ORDER BY (cr=3 pr=0 pw=0 time=168 us)'
STAT #2 id=2 cnt=0 pid=1 pos=1 obj=168 op='TABLE ACCESS CLUSTER COLTYPE$ (cr=3 pr=0 pw=0 time=119 us)'
STAT #2 id=3 cnt=1 pid=2 pos=1 obj=3 op='INDEX UNIQUE SCAN I_OBJ# (cr=2 pr=0 pw=0 time=47 us)'
=====================
PARSING IN CURSOR #2 len=493 dep=2 uid=0 oct=3 lid=0 tim=1183079900 hv=2584065658 ad='336da3e0'
select t.ts#,t.file#,t.block#,nvl(t.bobj#,0),nvl(t.tab#,0),t.intcols,nvl(t.clucols,0),t.audit$,t.flags,t.pctfree$,t.pctused$,t.initrans,t.maxtrans,t.rowcnt,t.blkcnt,t.empcnt,t.avgspc,t.chncnt,t.avgrln,t.analyzetime,t.samplesize,t.cols,t.property,nvl(t.degree,1),nvl(t.instances,1),t.avgspc_flb,t.flbcnt,t.kernelcols,nvl(t.trigflag, 0),nvl(t.spare1,0),nvl(t.spare2,0),t.spare4,t.spare6,ts.cachedblk,ts.cachehit,ts.logicalread from tab$ t, tab_stats$ ts where t.obj#= :1 and t.obj# = ts.obj# (+)
END OF STMT
PARSE #2:c=0,e=153,p=0,cr=0,cu=0,mis=0,r=0,dep=2,og=4,tim=1183079891
EXEC #2:c=0,e=101,p=0,cr=0,cu=0,mis=0,r=0,dep=2,og=4,tim=1183080084
FETCH #2:c=0,e=311,p=0,cr=4,cu=0,mis=0,r=1,dep=2,og=4,tim=1183080428
STAT #2 id=1 cnt=1 pid=0 pos=1 obj=0 op='NESTED LOOPS OUTER (cr=4 pr=0 pw=0 time=343 us)'
STAT #2 id=2 cnt=1 pid=1 pos=1 obj=4 op='TABLE ACCESS CLUSTER TAB$ (cr=3 pr=0 pw=0 time=187 us)'
STAT #2 id=3 cnt=1 pid=2 pos=1 obj=3 op='INDEX UNIQUE SCAN I_OBJ# (cr=2 pr=0 pw=0 time=30 us)'
STAT #2 id=4 cnt=0 pid=1 pos=2 obj=708 op='TABLE ACCESS BY INDEX ROWID TAB_STATS$ (cr=1 pr=0 pw=0 time=83 us)'
STAT #2 id=5 cnt=0 pid=4 pos=1 obj=709 op='INDEX UNIQUE SCAN I_TAB_STATS$_OBJ# (cr=1 pr=0 pw=0 time=41 us)'
=====================
PARSING IN CURSOR #3 len=117 dep=1 uid=0 oct=3 lid=0 tim=1183080628 hv=3141366592 ad='336b4f48'
select intcol#, toid, version#, intcols, intcol#s, flags, synobj# from subcoltype$ where obj#=:1 order by intcol# asc
END OF STMT
PARSE #3:c=0,e=1086,p=0,cr=4,cu=0,mis=0,r=0,dep=1,og=4,tim=1183080619
EXEC #3:c=0,e=100,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,tim=1183080782
FETCH #3:c=0,e=99,p=0,cr=3,cu=0,mis=0,r=0,dep=1,og=4,tim=1183080913
STAT #3 id=1 cnt=0 pid=0 pos=1 obj=0 op='SORT ORDER BY (cr=3 pr=0 pw=0 time=144 us)'
STAT #3 id=2 cnt=0 pid=1 pos=1 obj=171 op='TABLE ACCESS CLUSTER SUBCOLTYPE$ (cr=3 pr=0 pw=0 time=95 us)'
STAT #3 id=3 cnt=1 pid=2 pos=1 obj=3 op='INDEX UNIQUE SCAN I_OBJ# (cr=2 pr=0 pw=0 time=45 us)'
=====================
PARSING IN CURSOR #2 len=71 dep=1 uid=0 oct=3 lid=0 tim=1183081068 hv=2470471216 ad='336b45f8'
select col#,intcol#,ntab# from ntab$ where obj#=:1 order by intcol# asc
END OF STMT
PARSE #2:c=0,e=92,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,tim=1183081060
EXEC #2:c=0,e=114,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,tim=1183081223
FETCH #2:c=0,e=86,p=0,cr=1,cu=0,mis=0,r=0,dep=1,og=4,tim=1183081341
STAT #2 id=1 cnt=0 pid=0 pos=1 obj=198 op='TABLE ACCESS BY INDEX ROWID NTAB$ (cr=1 pr=0 pw=0 time=146 us)'
STAT #2 id=2 cnt=0 pid=1 pos=1 obj=200 op='INDEX RANGE SCAN I_NTAB2 (cr=1 pr=0 pw=0 time=65 us)'
=====================
PARSING IN CURSOR #3 len=191 dep=1 uid=0 oct=3 lid=0 tim=1183081525 hv=1930451687 ad='336b3810'
select l.col#, l.intcol#, l.lobj#, l.ind#, l.ts#, l.file#, l.block#, l.chunk, l.pctversion$, l.flags, l.property, l.retention, l.freepools from lob$ l where l.obj# = :1 order by l.intcol# asc
END OF STMT
PARSE #3:c=0,e=105,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,tim=1183081517
EXEC #3:c=0,e=80,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,tim=1183081665
FETCH #3:c=0,e=124,p=0,cr=3,cu=0,mis=0,r=1,dep=1,og=4,tim=1183081820
FETCH #3:c=0,e=37,p=0,cr=2,cu=0,mis=0,r=1,dep=1,og=4,tim=1183081897
FETCH #3:c=0,e=12,p=0,cr=1,cu=0,mis=0,r=0,dep=1,og=4,tim=1183081943
STAT #3 id=1 cnt=2 pid=0 pos=1 obj=151 op='TABLE ACCESS BY INDEX ROWID LOB$ (cr=6 pr=0 pw=0 time=139 us)'
STAT #3 id=2 cnt=2 pid=1 pos=1 obj=152 op='INDEX RANGE SCAN I_LOB1 (cr=4 pr=0 pw=0 time=94 us)'
=====================
PARSING IN CURSOR #2 len=90 dep=1 uid=0 oct=3 lid=0 tim=1183082093 hv=673844243 ad='336b2f48'
select col#,intcol#,reftyp,stabid,expctoid from refcon$ where obj#=:1 order by intcol# asc
END OF STMT
PARSE #2:c=0,e=79,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,tim=1183082084
EXEC #2:c=0,e=75,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,tim=1183082443
FETCH #2:c=0,e=77,p=0,cr=1,cu=0,mis=0,r=0,dep=1,og=4,tim=1183082554
STAT #2 id=1 cnt=0 pid=0 pos=1 obj=202 op='TABLE ACCESS BY INDEX ROWID REFCON$ (cr=1 pr=0 pw=0 time=99 us)'
STAT #2 id=2 cnt=0 pid=1 pos=1 obj=204 op='INDEX RANGE SCAN I_REFCON2 (cr=1 pr=0 pw=0 time=57 us)'
=====================
PARSING IN CURSOR #3 len=86 dep=1 uid=0 oct=3 lid=0 tim=1183082730 hv=2195287067 ad='336b237c'
select col#,intcol#,charsetid,charsetform from col$ where obj#=:1 order by intcol# asc
END OF STMT
PARSE #3:c=0,e=98,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,tim=1183082722
EXEC #3:c=0,e=95,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,tim=1183082869
FETCH #3:c=0,e=187,p=0,cr=3,cu=0,mis=0,r=1,dep=1,og=4,tim=1183083087
FETCH #3:c=0,e=10,p=0,cr=0,cu=0,mis=0,r=1,dep=1,og=4,tim=1183083161
FETCH #3:c=0,e=8,p=0,cr=0,cu=0,mis=0,r=1,dep=1,og=4,tim=1183083201
FETCH #3:c=0,e=9,p=0,cr=0,cu=0,mis=0,r=1,dep=1,og=4,tim=1183083242
FETCH #3:c=0,e=9,p=0,cr=0,cu=0,mis=0,r=1,dep=1,og=4,tim=1183083283
FETCH #3:c=0,e=9,p=0,cr=0,cu=0,mis=0,r=1,dep=1,og=4,tim=1183083322
FETCH #3:c=0,e=8,p=0,cr=0,cu=0,mis=0,r=1,dep=1,og=4,tim=1183083361
FETCH #3:c=0,e=9,p=0,cr=0,cu=0,mis=0,r=1,dep=1,og=4,tim=1183083401
FETCH #3:c=0,e=8,p=0,cr=0,cu=0,mis=0,r=1,dep=1,og=4,tim=1183083440
FETCH #3:c=0,e=8,p=0,cr=0,cu=0,mis=0,r=1,dep=1,og=4,tim=1183083479
FETCH #3:c=0,e=9,p=0,cr=0,cu=0,mis=0,r=1,dep=1,og=4,tim=1183083519
FETCH #3:c=0,e=8,p=0,cr=0,cu=0,mis=0,r=1,dep=1,og=4,tim=1183083558
FETCH #3:c=0,e=8,p=0,cr=0,cu=0,mis=0,r=1,dep=1,og=4,tim=1183083597
FETCH #3:c=10015,e=88,p=0,cr=0,cu=0,mis=0,r=1,dep=1,og=4,tim=1183083716
FETCH #3:c=0,e=8,p=0,cr=0,cu=0,mis=0,r=1,dep=1,og=4,tim=1183083756
FETCH #3:c=0,e=9,p=0,cr=0,cu=0,mis=0,r=1,dep=1,og=4,tim=1183083796
FETCH #3:c=0,e=8,p=0,cr=0,cu=0,mis=0,r=1,dep=1,og=4,tim=1183083835
FETCH #3:c=0,e=8,p=0,cr=0,cu=0,mis=0,r=1,dep=1,og=4,tim=1183083874
FETCH #3:c=0,e=8,p=0,cr=0,cu=0,mis=0,r=1,dep=1,og=4,tim=1183083913
FETCH #3:c=0,e=9,p=0,cr=0,cu=0,mis=0,r=1,dep=1,og=4,tim=1183083953
FETCH #3:c=0,e=8,p=0,cr=0,cu=0,mis=0,r=1,dep=1,og=4,tim=1183083991
FETCH #3:c=0,e=8,p=0,cr=0,cu=0,mis=0,r=1,dep=1,og=4,tim=1183084030
FETCH #3:c=0,e=13,p=0,cr=0,cu=0,mis=0,r=1,dep=1,og=4,tim=1183084074
FETCH #3:c=0,e=12,p=0,cr=0,cu=0,mis=0,r=1,dep=1,og=4,tim=1183084263
FETCH #3:c=0,e=9,p=0,cr=0,cu=0,mis=0,r=1,dep=1,og=4,tim=1183084305
FETCH #3:c=0,e=48,p=0,cr=0,cu=0,mis=0,r=1,dep=1,og=4,tim=1183084384
FETCH #3:c=0,e=9,p=0,cr=0,cu=0,mis=0,r=1,dep=1,og=4,tim=1183084426
FETCH #3:c=0,e=9,p=0,cr=0,cu=0,mis=0,r=1,dep=1,og=4,tim=1183084466
FETCH #3:c=0,e=9,p=0,cr=0,cu=0,mis=0,r=1,dep=1,og=4,tim=1183084506
FETCH #3:c=0,e=8,p=0,cr=0,cu=0,mis=0,r=1,dep=1,og=4,tim=1183084546
FETCH #3:c=0,e=9,p=0,cr=0,cu=0,mis=0,r=1,dep=1,og=4,tim=1183084586
FETCH #3:c=0,e=8,p=0,cr=0,cu=0,mis=0,r=1,dep=1,og=4,tim=1183084625
FETCH #3:c=0,e=8,p=0,cr=0,cu=0,mis=0,r=1,dep=1,og=4,tim=1183084664
FETCH #3:c=0,e=8,p=0,cr=0,cu=0,mis=0,r=1,dep=1,og=4,tim=1183084703
FETCH #3:c=0,e=9,p=0,cr=0,cu=0,mis=0,r=1,dep=1,og=4,tim=1183084743
FETCH #3:c=0,e=8,p=0,cr=0,cu=0,mis=0,r=1,dep=1,og=4,tim=1183084782
FETCH #3:c=0,e=14,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,tim=1183084827
STAT #3 id=1 cnt=36 pid=0 pos=1 obj=0 op='SORT ORDER BY (cr=3 pr=0 pw=0 time=224 us)'
STAT #3 id=2 cnt=36 pid=1 pos=1 obj=21 op='TABLE ACCESS CLUSTER COL$ (cr=3 pr=0 pw=0 time=538 us)'
STAT #3 id=3 cnt=1 pid=2 pos=1 obj=3 op='INDEX UNIQUE SCAN I_OBJ# (cr=2 pr=0 pw=0 time=46 us)'
=====================
PARSING IN CURSOR #3 len=493 dep=2 uid=0 oct=3 lid=0 tim=1183085245 hv=2584065658 ad='336da3e0'
select t.ts#,t.file#,t.block#,nvl(t.bobj#,0),nvl(t.tab#,0),t.intcols,nvl(t.clucols,0),t.audit$,t.flags,t.pctfree$,t.pctused$,t.initrans,t.maxtrans,t.rowcnt,t.blkcnt,t.empcnt,t.avgspc,t.chncnt,t.avgrln,t.analyzetime,t.samplesize,t.cols,t.property,nvl(t.degree,1),nvl(t.instances,1),t.avgspc_flb,t.flbcnt,t.kernelcols,nvl(t.trigflag, 0),nvl(t.spare1,0),nvl(t.spare2,0),t.spare4,t.spare6,ts.cachedblk,ts.cachehit,ts.logicalread from tab$ t, tab_stats$ ts where t.obj#= :1 and t.obj# = ts.obj# (+)
END OF STMT
EXEC #3:c=0,e=120,p=0,cr=0,cu=0,mis=0,r=0,dep=2,og=4,tim=1183085235
FETCH #3:c=0,e=288,p=0,cr=4,cu=0,mis=0,r=1,dep=2,og=4,tim=1183085613
STAT #3 id=1 cnt=2 pid=0 pos=1 obj=0 op='NESTED LOOPS OUTER (cr=8 pr=0 pw=0 time=660 us)'
STAT #3 id=2 cnt=2 pid=1 pos=1 obj=4 op='TABLE ACCESS CLUSTER TAB$ (cr=6 pr=0 pw=0 time=346 us)'
STAT #3 id=3 cnt=2 pid=2 pos=1 obj=3 op='INDEX UNIQUE SCAN I_OBJ# (cr=4 pr=0 pw=0 time=68 us)'
STAT #3 id=4 cnt=0 pid=1 pos=2 obj=708 op='TABLE ACCESS BY INDEX ROWID TAB_STATS$ (cr=2 pr=0 pw=0 time=169 us)'
STAT #3 id=5 cnt=0 pid=4 pos=1 obj=709 op='INDEX UNIQUE SCAN I_TAB_STATS$_OBJ# (cr=2 pr=0 pw=0 time=76 us)'
=====================
PARSING IN CURSOR #2 len=119 dep=1 uid=0 oct=3 lid=0 tim=1183085821 hv=166324347 ad='336b201c'
select intcol#,type,flags,lobcol,objcol,extracol,schemaoid, elemnum from opqtype$ where obj# = :1 order by intcol# asc
END OF STMT
PARSE #2:c=0,e=921,p=0,cr=4,cu=0,mis=0,r=0,dep=1,og=4,tim=1183085813
EXEC #2:c=0,e=87,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,tim=1183085969
FETCH #2:c=0,e=74,p=0,cr=1,cu=0,mis=0,r=0,dep=1,og=4,tim=1183086091
STAT #2 id=1 cnt=0 pid=0 pos=1 obj=205 op='TABLE ACCESS BY INDEX ROWID OPQTYPE$ (cr=1 pr=0 pw=0 time=90 us)'
STAT #2 id=2 cnt=0 pid=1 pos=1 obj=206 op='INDEX RANGE SCAN I_OPQTYPE1 (cr=1 pr=0 pw=0 time=47 us)'
=====================
PARSING IN CURSOR #3 len=789 dep=1 uid=0 oct=3 lid=0 tim=1183086737 hv=3159716790 ad='336d80c0'
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#
END OF STMT
EXEC #3:c=0,e=187,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,tim=1183086728
FETCH #3:c=0,e=1888,p=0,cr=8,cu=0,mis=0,r=1,dep=1,og=4,tim=1183088666
=====================
PARSING IN CURSOR #2 len=67 dep=1 uid=0 oct=3 lid=0 tim=1183088955 hv=2280069326 ad='336eaa70'
select pos#,intcol#,col#,spare1,bo#,spare2 from icol$ where obj#=:1
END OF STMT
EXEC #2:c=0,e=123,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,tim=1183088946
FETCH #2:c=0,e=86,p=0,cr=3,cu=0,mis=0,r=1,dep=1,og=4,tim=1183089083
FETCH #2:c=0,e=39,p=0,cr=2,cu=0,mis=0,r=1,dep=1,og=4,tim=1183089154
FETCH #2:c=0,e=11,p=0,cr=1,cu=0,mis=0,r=0,dep=1,og=4,tim=1183089197
FETCH #3:c=0,e=11,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,tim=1183089256
=====================
PARSING IN CURSOR #2 len=348 dep=1 uid=0 oct=3 lid=0 tim=1183089453 hv=2512561537 ad='336ea480'
select name,intcol#,segcol#,type#,length,nvl(precision#,0),decode(type#,2,nvl(scale,-127/*MAXSB1MINAL*/),178,scale,179,scale,180,scale,181,scale,182,scale,183,scale,231,scale,0),null$,fixedstorage,nvl(deflength,0),default$,rowid,col#,property, nvl(charsetid,0),nvl(charsetform,0),spare1,spare2,nvl(spare3,0) from col$ where obj#=:1 order by intcol#
END OF STMT
EXEC #2:c=0,e=92,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,tim=1183089445
FETCH #2:c=0,e=188,p=0,cr=3,cu=0,mis=0,r=1,dep=1,og=4,tim=1183089686
FETCH #2:c=0,e=11,p=0,cr=0,cu=0,mis=0,r=1,dep=1,og=4,tim=1183089731
FETCH #2:c=0,e=11,p=0,cr=0,cu=0,mis=0,r=1,dep=1,og=4,tim=1183089773
FETCH #2:c=0,e=11,p=0,cr=0,cu=0,mis=0,r=1,dep=1,og=4,tim=1183089816
FETCH #2:c=0,e=10,p=0,cr=0,cu=0,mis=0,r=1,dep=1,og=4,tim=1183089858
FETCH #2:c=0,e=11,p=0,cr=0,cu=0,mis=0,r=1,dep=1,og=4,tim=1183089912
FETCH #2:c=0,e=11,p=0,cr=0,cu=0,mis=0,r=1,dep=1,og=4,tim=1183090019
FETCH #2:c=0,e=11,p=0,cr=0,cu=0,mis=0,r=1,dep=1,og=4,tim=1183090063
FETCH #2:c=0,e=10,p=0,cr=0,cu=0,mis=0,r=1,dep=1,og=4,tim=1183090105
FETCH #2:c=0,e=11,p=0,cr=0,cu=0,mis=0,r=1,dep=1,og=4,tim=1183090148
FETCH #2:c=0,e=11,p=0,cr=0,cu=0,mis=0,r=1,dep=1,og=4,tim=1183090191
FETCH #2:c=0,e=10,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,tim=1183090234
=====================
PARSING IN CURSOR #1 len=42 dep=0 uid=0 oct=3 lid=0 tim=1183097881 hv=1028507401 ad='2f5a389c'
select *
from
dba_objects where rownum<10
END OF STMT
PARSE #1:c=40058,e=43182,p=0,cr=74,cu=0,mis=1,r=0,dep=0,og=1,tim=1183097856
EXEC #1:c=0,e=616,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,tim=1183098699
FETCH #1:c=0,e=3892,p=0,cr=9,cu=0,mis=0,r=1,dep=0,og=1,tim=1183102759
FETCH #1:c=0,e=1134,p=0,cr=11,cu=0,mis=0,r=8,dep=0,og=1,tim=1183106012
STAT #1 id=1 cnt=9 pid=0 pos=1 obj=0 op='COUNT STOPKEY (cr=20 pr=0 pw=0 time=4370 us)'
STAT #1 id=2 cnt=9 pid=1 pos=1 obj=2371 op='VIEW DBA_OBJECTS (cr=20 pr=0 pw=0 time=4158 us)'
STAT #1 id=3 cnt=9 pid=2 pos=1 obj=0 op='UNION-ALL (cr=20 pr=0 pw=0 time=4093 us)'
STAT #1 id=4 cnt=9 pid=3 pos=1 obj=0 op='FILTER (cr=20 pr=0 pw=0 time=3700 us)'
STAT #1 id=5 cnt=9 pid=4 pos=1 obj=0 op='HASH JOIN (cr=10 pr=0 pw=0 time=4181 us)'
STAT #1 id=6 cnt=62 pid=5 pos=1 obj=22 op='TABLE ACCESS FULL USER$ (cr=5 pr=0 pw=0 time=1015 us)'
STAT #1 id=7 cnt=9 pid=5 pos=2 obj=18 op='TABLE ACCESS FULL OBJ$ (cr=5 pr=0 pw=0 time=127 us)'
STAT #1 id=8 cnt=4 pid=4 pos=2 obj=19 op='TABLE ACCESS BY INDEX ROWID IND$ (cr=10 pr=0 pw=0 time=669 us)'
STAT #1 id=9 cnt=4 pid=8 pos=1 obj=39 op='INDEX UNIQUE SCAN I_IND1 (cr=6 pr=0 pw=0 time=284 us)'
STAT #1 id=10 cnt=0 pid=3 pos=2 obj=94 op='TABLE ACCESS BY INDEX ROWID LINK$ (cr=0 pr=0 pw=0 time=0 us)'
STAT #1 id=11 cnt=0 pid=10 pos=1 obj=0 op='NESTED LOOPS (cr=0 pr=0 pw=0 time=0 us)'
STAT #1 id=12 cnt=0 pid=11 pos=1 obj=22 op='TABLE ACCESS FULL USER$ (cr=0 pr=0 pw=0 time=0 us)'
STAT #1 id=13 cnt=0 pid=11 pos=2 obj=107 op='INDEX RANGE SCAN I_LINK1 (cr=0 pr=0 pw=0 time=0 us)'
=====================
PARSING IN CURSOR #3 len=33 dep=0 uid=0 oct=42 lid=0 tim=1190208072 hv=525901419 ad='2e8e6078'
alter session set sql_trace=false
END OF STMT
PARSE #3:c=0,e=188,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,tim=1190208058
EXEC #3:c=0,e=624,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,tim=1190208827
TKPROF
大家看到刚才生成的TRACE文件了吧，很明显它比较乱不太方便阅读，所以我们需要通过TKPROF来对以上的TRACE文件进行整理。
如何使用TKPROF
TKPROF tracefile outputfile
完整命令行：
tkprof tracefile outputfile [explain= ] [table= ] [print= ] [insert= ] [sys= ] [sort= ]
* table=schema.tablename Use 'schema.tablename'
-
Explain = user/password 在trace文件中输入 SQL的执行计划。如果不使用这个参数，在生成的TRACE文件中到的是SQL的实际 的执行路径。
-
Print=integer 只列出输出文件中的第一个INTEGER的SQL语句，若忽略，则TKPROF将列出所有跟踪的SQL语句
-
aggregate=yes/no 默认情况 下，tkprof工具将所有相同的SQL在输入 文件中做合并，如果设置为NO，TKPROF将不会对相同SQL文本的多个用户进行汇总。
-
insert=filename SQL脚本的一种，用于将跟踪文件的动机信息存储到数据库中。
-
sys=yes/no 于启动或禁止将用户SYS所发布的SQL语句列表到输出文件之中，也包括递归SQL(为执行用户的SQL语句，ORACLE还必须执行一些附加语句)语句在内。默认为YES。
-
record=filename 对于跟踪文件中的所用非递归SQL语句，TKPROF 将以指定的名称来创建某个SQL脚本。用于对跟踪文件中的用户时间进行重放。
-
waits=yes/no Record summary for any wait events found in the trace file.
-
sort=option 在将被跟踪的SQL语句列表输出到跟踪文件之前，先将其按照指定排序选项的降序关系对其进行排序；若指定了多种排序选项，那么根据排序选项所指定值的和的降序关系对其进行排序；若忽略此参数，那么TKPROF将按照使用次序把语句列表到输出文件中
- prscnt number of times parse was called 语句解析的数目。
- prscpu cpu time parsing 语句解析所占用的CPU时间。
- prsela elapsed time parsing 语句解析所占用的时间（总是大于或等于CPU时间）；
- prsdsk number of disk reads during parse 语句解析期间，从磁盘进行物理读取的数目。
- prsqry number of buffers for consistent read during parse 语句解析期间，一致模式块读取（CONSISTENT MODE BLOCK READ）的数目。
- prscu number of buffers for current read during parse 语句解析期间，当前模式读取（CURRENT MODE BLOCK READ）的数目。
- prsmis number of misses in library cache during parse 语句解析期间，库缓存失败的数目。
- execnt number of execute was called 语句执行的数目。
- execpu cpu time spent executing 语句执行所占用的CPU时间。
- exeela elapsed time executing 语句执行所占用的时间（总是大于或等于CPU时间）。
- exedsk number of disk reads during execute 语句执行期间，从磁盘进行物理读取的数目。
- exeqry number of buffers for consistent read during execute 语句执行期间，一致模式块读取（CONSISTENT MODE BLOCK READ）的数目。
- execu number of buffers for current read during execute 语句执行期间，当前模式读取（CURRENT MODE BLOCK READ）的数目。
- 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 取数据所占用的CPU时间。
- fchela elapsed time fetching 取数据所占用的时间（总是大于或等于CPU时间）。
- fchdsk number of disk reads during fetch 取数据期间，从磁盘进行物理读取的数目。
- fchqry number of buffers for consistent read during fetch 取数据期间，一致模式块读取（CONSISTENT MODE BLOCK READ）的数目。
- fchcu number of buffers for current read during fetch 取数据期间，当前模式读取（CURRENT MODE BLOCK READ）的数目。
- fchrow number of rows fetched 所获取的行数。
SAMPLE
TKPROF: Release 10.2.0.1.0 - Production on 星期日 9月 18 20:36:42 2011
Copyright (c) 1982, 2005, Oracle. All rights reserved.
Trace file: D:\oracle\product\10.2.0\admin\orcl\udump\orcl_ora_2508_oracle_test.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
********************************************************************************
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
********************************************************************************
select name,intcol#,segcol#,type#,length,nvl(precision#,0),decode(type#,2,
nvl(scale,-127/*MAXSB1MINAL*/),178,scale,179,scale,180,scale,181,scale,182,
scale,183,scale,231,scale,0),null$,fixedstorage,nvl(deflength,0),default$,
rowid,col#,property, nvl(charsetid,0),nvl(charsetform,0),spare1,spare2,
nvl(spare3,0)
from
col$ where obj#=:1 order by intcol#
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.00 0.00 0 0 0 0
Execute 3 0.00 0.00 0 0 0 0
Fetch 63 0.00 0.00 0 9 0 60
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 67 0.00 0.00 0 9 0 60
Misses in library cache during parse: 0
Optimizer mode: CHOOSE
Parsing user id: SYS (recursive depth: 1)
Rows Row Source Operation
------- ---------------------------------------------------
13 SORT ORDER BY (cr=3 pr=0 pw=0 time=487 us)
13 TABLE ACCESS CLUSTER COL$ (cr=3 pr=0 pw=0 time=459 us)
1 INDEX UNIQUE SCAN I_OBJ# (cr=2 pr=0 pw=0 time=132 us)(object id 3)
********************************************************************************
select text
from
view$ where rowid=:1
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.00 0 2 0 1
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 3 0.00 0.00 0 2 0 1
Misses in library cache during parse: 0
Optimizer mode: CHOOSE
Parsing user id: SYS (recursive depth: 1)
Rows Row Source Operation
------- ---------------------------------------------------
1 TABLE ACCESS BY USER ROWID VIEW$ (cr=1 pr=0 pw=0 time=61 us)
********************************************************************************
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 2 0.01 0.00 0 0 0 0
Fetch 6 0.00 0.00 0 19 0 4
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 9 0.01 0.00 0 19 0 4
Misses in library cache during parse: 0
Optimizer mode: CHOOSE
Parsing user id: SYS (recursive depth: 1)
Rows Row Source Operation
------- ---------------------------------------------------
3 SORT ORDER BY (cr=11 pr=0 pw=0 time=3609 us)
3 HASH JOIN OUTER (cr=11 pr=0 pw=0 time=3062 us)
3 NESTED LOOPS OUTER (cr=8 pr=0 pw=0 time=735 us)
3 TABLE ACCESS CLUSTER IND$ (cr=6 pr=0 pw=0 time=375 us)
1 INDEX UNIQUE SCAN I_OBJ# (cr=2 pr=0 pw=0 time=130 us)(object id 3)
0 TABLE ACCESS BY INDEX ROWID IND_STATS$ (cr=2 pr=0 pw=0 time=230 us)
0 INDEX UNIQUE SCAN I_IND_STATS$_OBJ# (cr=2 pr=0 pw=0 time=105 us)(object id 711)
0 VIEW (cr=3 pr=0 pw=0 time=401 us)
0 SORT GROUP BY (cr=3 pr=0 pw=0 time=358 us)
0 TABLE ACCESS BY INDEX ROWID CDEF$ (cr=3 pr=0 pw=0 time=212 us)
7 INDEX RANGE SCAN I_CDEF2 (cr=2 pr=0 pw=0 time=165 us)(object id 51)
********************************************************************************
select pos#,intcol#,col#,spare1,bo#,spare2
from
icol$ where obj#=:1
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.00 0.00 0 0 0 0
Execute 4 0.00 0.00 0 0 0 0
Fetch 7 0.00 0.00 0 14 0 3
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 12 0.00 0.00 0 14 0 3
Misses in library cache during parse: 0
Optimizer mode: CHOOSE
Parsing user id: SYS (recursive depth: 1)
Rows Row Source Operation
------- ---------------------------------------------------
0 TABLE ACCESS BY INDEX ROWID ICOL$ (cr=2 pr=0 pw=0 time=111 us)
0 INDEX RANGE SCAN I_ICOL1 (cr=2 pr=0 pw=0 time=69 us)(object id 40)
********************************************************************************
select col#, grantee#, privilege#,max(mod(nvl(option$,0),2))
from
objauth$ where obj#=:1 and col# is not null group by privilege#, col#,
grantee# order by col#, grantee#
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.00 0 2 0 0
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 3 0.00 0.00 0 2 0 0
Misses in library cache during parse: 0
Optimizer mode: CHOOSE
Parsing user id: SYS (recursive depth: 1)
Rows Row Source Operation
------- ---------------------------------------------------
0 SORT GROUP BY (cr=2 pr=0 pw=0 time=171 us)
0 TABLE ACCESS BY INDEX ROWID OBJAUTH$ (cr=2 pr=0 pw=0 time=117 us)
0 INDEX RANGE SCAN I_OBJAUTH1 (cr=2 pr=0 pw=0 time=73 us)(object id 103)
********************************************************************************
select grantee#,privilege#,nvl(col#,0),max(mod(nvl(option$,0),2))
from
objauth$ where obj#=:1 group by grantee#,privilege#,nvl(col#,0) order by
grantee#
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.00 0 2 0 0
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 3 0.00 0.00 0 2 0 0
Misses in library cache during parse: 0
Optimizer mode: CHOOSE
Parsing user id: SYS (recursive depth: 1)
Rows Row Source Operation
------- ---------------------------------------------------
0 SORT GROUP BY (cr=2 pr=0 pw=0 time=140 us)
0 TABLE ACCESS BY INDEX ROWID OBJAUTH$ (cr=2 pr=0 pw=0 time=73 us)
0 INDEX RANGE SCAN I_OBJAUTH1 (cr=2 pr=0 pw=0 time=31 us)(object id 103)
********************************************************************************
select col#,intcol#,toid,version#,packed,intcols,intcol#s,flags, synobj#,
nvl(typidcol#, 0)
from
coltype$ where obj#=:1 order by intcol# desc
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.00 0 3 0 0
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 3 0.00 0.00 0 3 0 0
Misses in library cache during parse: 0
Optimizer mode: CHOOSE
Parsing user id: SYS (recursive depth: 1)
Rows Row Source Operation
------- ---------------------------------------------------
0 SORT ORDER BY (cr=3 pr=0 pw=0 time=168 us)
0 TABLE ACCESS CLUSTER COLTYPE$ (cr=3 pr=0 pw=0 time=119 us)
1 INDEX UNIQUE SCAN I_OBJ# (cr=2 pr=0 pw=0 time=47 us)(object id 3)
********************************************************************************
select t.ts#,t.file#,t.block#,nvl(t.bobj#,0),nvl(t.tab#,0),t.intcols,
nvl(t.clucols,0),t.audit$,t.flags,t.pctfree$,t.pctused$,t.initrans,
t.maxtrans,t.rowcnt,t.blkcnt,t.empcnt,t.avgspc,t.chncnt,t.avgrln,
t.analyzetime,t.samplesize,t.cols,t.property,nvl(t.degree,1),
nvl(t.instances,1),t.avgspc_flb,t.flbcnt,t.kernelcols,nvl(t.trigflag, 0),
nvl(t.spare1,0),nvl(t.spare2,0),t.spare4,t.spare6,ts.cachedblk,ts.cachehit,
ts.logicalread
from
tab$ t, tab_stats$ ts where t.obj#= :1 and t.obj# = ts.obj# (+)
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.00 0.00 0 0 0 0
Execute 2 0.00 0.00 0 0 0 0
Fetch 2 0.00 0.00 0 8 0 2
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 5 0.00 0.00 0 8 0 2
Misses in library cache during parse: 0
Optimizer mode: CHOOSE
Parsing user id: SYS (recursive depth: 2)
Rows Row Source Operation
------- ---------------------------------------------------
1 NESTED LOOPS OUTER (cr=4 pr=0 pw=0 time=343 us)
1 TABLE ACCESS CLUSTER TAB$ (cr=3 pr=0 pw=0 time=187 us)
1 INDEX UNIQUE SCAN I_OBJ# (cr=2 pr=0 pw=0 time=30 us)(object id 3)
0 TABLE ACCESS BY INDEX ROWID TAB_STATS$ (cr=1 pr=0 pw=0 time=83 us)
0 INDEX UNIQUE SCAN I_TAB_STATS$_OBJ# (cr=1 pr=0 pw=0 time=41 us)(object id 709)
********************************************************************************
select intcol#, toid, version#, intcols, intcol#s, flags, synobj#
from
subcoltype$ where obj#=:1 order by intcol# asc
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.00 0 3 0 0
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 3 0.00 0.00 0 3 0 0
Misses in library cache during parse: 0
Optimizer mode: CHOOSE
Parsing user id: SYS (recursive depth: 1)
Rows Row Source Operation
------- ---------------------------------------------------
0 SORT ORDER BY (cr=3 pr=0 pw=0 time=144 us)
0 TABLE ACCESS CLUSTER SUBCOLTYPE$ (cr=3 pr=0 pw=0 time=95 us)
1 INDEX UNIQUE SCAN I_OBJ# (cr=2 pr=0 pw=0 time=45 us)(object id 3)
********************************************************************************
select col#,intcol#,ntab#
from
ntab$ where obj#=:1 order by intcol# asc
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.00 0 1 0 0
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 3 0.00 0.00 0 1 0 0
Misses in library cache during parse: 0
Optimizer mode: CHOOSE
Parsing user id: SYS (recursive depth: 1)
Rows Row Source Operation
------- ---------------------------------------------------
0 TABLE ACCESS BY INDEX ROWID NTAB$ (cr=1 pr=0 pw=0 time=146 us)
0 INDEX RANGE SCAN I_NTAB2 (cr=1 pr=0 pw=0 time=65 us)(object id 200)
********************************************************************************
select l.col#, l.intcol#, l.lobj#, l.ind#, l.ts#, l.file#, l.block#, l.chunk,
l.pctversion$, l.flags, l.property, l.retention, l.freepools
from
lob$ l where l.obj# = :1 order by l.intcol# asc
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 3 0.00 0.00 0 6 0 2
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 5 0.00 0.00 0 6 0 2
Misses in library cache during parse: 0
Optimizer mode: CHOOSE
Parsing user id: SYS (recursive depth: 1)
Rows Row Source Operation
------- ---------------------------------------------------
2 TABLE ACCESS BY INDEX ROWID LOB$ (cr=6 pr=0 pw=0 time=139 us)
2 INDEX RANGE SCAN I_LOB1 (cr=4 pr=0 pw=0 time=94 us)(object id 152)
********************************************************************************
select col#,intcol#,reftyp,stabid,expctoid
from
refcon$ where obj#=:1 order by intcol# asc
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.00 0 1 0 0
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 3 0.00 0.00 0 1 0 0
Misses in library cache during parse: 0
Optimizer mode: CHOOSE
Parsing user id: SYS (recursive depth: 1)
Rows Row Source Operation
------- ---------------------------------------------------
0 TABLE ACCESS BY INDEX ROWID REFCON$ (cr=1 pr=0 pw=0 time=99 us)
0 INDEX RANGE SCAN I_REFCON2 (cr=1 pr=0 pw=0 time=57 us)(object id 204)
********************************************************************************
select col#,intcol#,charsetid,charsetform
from
col$ where obj#=:1 order by intcol# asc
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 37 0.01 0.00 0 3 0 36
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 39 0.01 0.00 0 3 0 36
Misses in library cache during parse: 0
Optimizer mode: CHOOSE
Parsing user id: SYS (recursive depth: 1)
Rows Row Source Operation
------- ---------------------------------------------------
36 SORT ORDER BY (cr=3 pr=0 pw=0 time=224 us)
36 TABLE ACCESS CLUSTER COL$ (cr=3 pr=0 pw=0 time=538 us)
1 INDEX UNIQUE SCAN I_OBJ# (cr=2 pr=0 pw=0 time=46 us)(object id 3)
********************************************************************************
select intcol#,type,flags,lobcol,objcol,extracol,schemaoid, elemnum
from
opqtype$ where obj# = :1 order by intcol# asc
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.00 0 1 0 0
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 3 0.00 0.00 0 1 0 0
Misses in library cache during parse: 0
Optimizer mode: CHOOSE
Parsing user id: SYS (recursive depth: 1)
Rows Row Source Operation
------- ---------------------------------------------------
0 TABLE ACCESS BY INDEX ROWID OPQTYPE$ (cr=1 pr=0 pw=0 time=90 us)
0 INDEX RANGE SCAN I_OPQTYPE1 (cr=1 pr=0 pw=0 time=47 us)(object id 206)
********************************************************************************
select *
from
dba_objects where rownum<10
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.02 0.02 0 0 0 0
Execute 1 0.00 0.00 0 0 0 0
Fetch 2 0.00 0.00 0 20 0 9
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 4 0.02 0.03 0 20 0 9
Misses in library cache during parse: 1
Optimizer mode: ALL_ROWS
Parsing user id: SYS
Rows Row Source Operation
------- ---------------------------------------------------
9 COUNT STOPKEY (cr=20 pr=0 pw=0 time=4370 us)
9 VIEW DBA_OBJECTS (cr=20 pr=0 pw=0 time=4158 us)
9 UNION-ALL (cr=20 pr=0 pw=0 time=4093 us)
9 FILTER (cr=20 pr=0 pw=0 time=3700 us)
9 HASH JOIN (cr=10 pr=0 pw=0 time=4181 us)
62 TABLE ACCESS FULL USER$ (cr=5 pr=0 pw=0 time=1015 us)
9 TABLE ACCESS FULL OBJ$ (cr=5 pr=0 pw=0 time=127 us)
4 TABLE ACCESS BY INDEX ROWID IND$ (cr=10 pr=0 pw=0 time=669 us)
4 INDEX UNIQUE SCAN I_IND1 (cr=6 pr=0 pw=0 time=284 us)(object id 39)
0 TABLE ACCESS BY INDEX ROWID LINK$ (cr=0 pr=0 pw=0 time=0 us)
0 NESTED LOOPS (cr=0 pr=0 pw=0 time=0 us)
0 TABLE ACCESS FULL USER$ (cr=0 pr=0 pw=0 time=0 us)
0 INDEX RANGE SCAN I_LINK1 (cr=0 pr=0 pw=0 time=0 us)(object id 107)
********************************************************************************
alter session set sql_trace=false
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 0 0.00 0.00 0 0 0 0
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 2 0.00 0.00 0 0 0 0
Misses in library cache during parse: 0
Optimizer mode: ALL_ROWS
Parsing user id: SYS
********************************************************************************
OVERALL TOTALS FOR ALL NON-RECURSIVE STATEMENTS
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 2 0.02 0.02 0 0 0 0
Execute 3 0.00 0.00 0 0 0 0
Fetch 2 0.00 0.00 0 20 0 9
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 7 0.02 0.03 0 20 0 9
Misses in library cache during parse: 1
Misses in library cache during execute: 1
OVERALL TOTALS FOR ALL RECURSIVE STATEMENTS
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 14 0.00 0.00 0 0 0 0
Execute 21 0.01 0.00 0 0 0 0
Fetch 126 0.01 0.00 0 74 0 108
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 161 0.02 0.01 0 74 0 108
Misses in library cache during parse: 0
3 user SQL statements in session.
21 internal SQL statements in session.
24 SQL statements in session.
********************************************************************************
Trace file: D:\oracle\product\10.2.0\admin\orcl\udump\orcl_ora_2508_oracle_test.trc
Trace file compatibility: 10.01.00
Sort options: default
1 session in tracefile.
3 user SQL statements in trace file.
21 internal SQL statements in trace file.
24 SQL statements in trace file.
17 unique SQL statements in trace file.
356 lines in trace file.
39 elapsed seconds in trace file.