Maclean教你读SQL TRACE TKProf报告.docx
《Maclean教你读SQL TRACE TKProf报告.docx》由会员分享，可在线阅读，更多相关《Maclean教你读SQL TRACE TKProf报告.docx（18页珍藏版）》请在冰点文库上搜索。
Maclean教你读SQLTRACETKProf报告
在《Maclean教你读Oracle10046SQLTRACE》中我介绍了10046TRACE的阅读以及其中个字段的含义，接着我们介绍10046sqltrace的搭档工具TKPROF。
TKPROF是一个可执行文件，自带在OracleServer软件中，无需额外的安装。
该工具文件可以用来解析ORACLE的SQLTRACE（10046）以便生成更可读的内容。
实际上tkprof是对10046SQLtrace的内容作了汇总，例如一个语句遇到过的waitevent、其在PARSE、Execute、Fetch三阶段的耗时、CPU_TIME等等。
由于tkprof是对10046SQLTRACE的汇总，所以tkprof中的信息完全可以从10046中获得，10046的问题是由于巨细靡遗所以TRACE内容可能过多，内容多则难以快速分析，TKPROF将10046 trace解析过后更适合调优者阅读。
TKPROF的语法如下：
tkproftracefileoutfile[explain=user/password][options...]
几个选项
print=integer 只列出前几个SQL语句，integer 为指定的数量，例如print=10
sys=no 不列出以SYS用户运行的语句
sort=option 排序选项，选项列表如下：
▪prscntnumberoftimesparsewascalled
▪prscpucputimeparsing
▪prselaelapsedtimeparsing
▪prsdsknumberofdiskreadsduringparse
▪prsqrynumberofbuffersforconsistentreadduringparse
▪prscunumberofbuffersforcurrentreadduringparse
▪prsmisnumberofmissesinlibrarycacheduringparse
▪execntnumberofexecutewascalled
▪execpucputimespentexecuting
▪exeelaelapsedtimeexecuting
▪exedsknumberofdiskreadsduringexecute
▪exeqrynumberofbuffersforconsistentreadduringexecute
▪execunumberofbuffersforcurrentreadduringexecute
▪exerownumberofrowsprocessedduringexecute
▪exemisnumberoflibrarycachemissesduringexecute
▪fchcntnumberoftimesfetchwascalled
▪fchcpucputimespentfetching
▪fchelaelapsedtimefetching
▪fchdsknumberofdiskreadsduringfetch
▪fchqrynumberofbuffersforconsistentreadduringfetch
▪fchcunumberofbuffersforcurrentreadduringfetch
▪fchrownumberofrowsfetched
▪useriduseridofuserthatparsedthecursor
接下来看一个最简单的TKPROF的例子：
droptablefullscan;
createtablefullscanasselect*fromdba_objects;
execdbms_stats.gather_table_stats（user,'FULLSCAN'）;
altersystemflushshared_pool;
altersystemflushbuffer_cache;
altersessionsetevents'10046tracenamecontextforever,level12';
selectcount（*）fromfullscan;
oradebugsetmypid
oradebugtracefile_name;
/s01/admin/G10R25/udump/g10r25_ora_30334.trc
[oracle@vrh8udump]$tkprof/s01/admin/G10R25/udump/g10r25_ora_30334.trc30334.tkf
TKPROF:
Release10.2.0.5.0-ProductiononSunAug2502:
21:
272013
Copyright（c）1982,2007,Oracle. Allrightsreserved.
vi 30334.tkf
Tracefile:
/s01/admin/G10R25/udump/g10r25_ora_30334.trc
Sortoptions:
default
********************************************************************************
count =numberoftimesOCIprocedurewasexecuted
cpu =cputimeinsecondsexecuting
elapsed =elapsedtimeinsecondsexecuting
disk =numberofphysicalreadsofbuffersfromdisk
query =numberofbuffersgottenforconsistentread
current =numberofbuffersgottenincurrentmode（usuallyforupdate）
rows =numberofrowsprocessedbythefetchorexecutecall
********************************************************************************
selectobj#,type#,ctime,mtime,stime,status,dataobj#,flags,oid$,spare1,
spare2
from
obj$whereowner#=:
1andname=:
2andnamespace=:
3andremoteownerisnull
andlinknameisnullandsubnameisnull
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 2 4 0 1
------------- ------------------------------------------------ ----------
total 3 0.00 0.00 2 4 0 1
Missesinlibrarycacheduringparse:
1
Missesinlibrarycacheduringexecute:
1
Optimizermode:
CHOOSE
Parsinguserid:
SYS （recursivedepth:
1）
Rows RowSourceOperation
------- ---------------------------------------------------
1 TABLEACCESSBYINDEXROWIDOBJ$（cr=4pr=2pw=0time=133us）
1 INDEXRANGESCANI_OBJ2（cr=3pr=1pw=0time=74us）（objectid37）
Elapsedtimesincludewaitingonfollowingevents:
Eventwaitedon Times Max.Wait TotalWaited
---------------------------------------- Waited ---------- ------------
SQL*Netmessagetoclient 1 0.00 0.00
SQL*Netmessagefromclient 1 0.01 0.01
dbfilesequentialread 2 0.00 0.00
********************************************************************************
selectcount（*）
from
fullscan
call count cpu elapsed disk query current rows
------------- ------------------------------------------------ ----------
Parse 1 0.00 0.00 4 15 0 0
Execute 1 0.00 0.00 0 0 0 0
Fetch 2 0.01 0.01 1139 1143 0 1
------------- ------------------------------------------------ ----------
total 4 0.02 0.02 1143 1158 0 1
Missesinlibrarycacheduringparse:
1
Optimizermode:
ALL_ROWS
Parsinguserid:
SYS
Rows RowSourceOperation
------- ---------------------------------------------------
1 SORTAGGREGATE（cr=1143pr=1139pw=0time=15759us）
77268 TABLEACCESSFULLFULLSCAN（cr=1143pr=1139pw=0time=463719us）
Elapsedtimesincludewaitingonfollowingevents:
Eventwaitedon Times Max.Wait TotalWaited
---------------------------------------- Waited ---------- ------------
SQL*Netmessagetoclient 2 0.00 0.00
dbfilesequentialread 1 0.00 0.00
dbfilescatteredread 80 0.00 0.00
SQL*Netmessagefromclient 2 0.00 0.00
在上述例子中我们可以看到TKPROF将一个SQLStatement的运行划分为几个部分的信息：
1.SQL语句的parse、execute、fetch阶段的耗时：
selectcount（*）
from
fullscan
call count cpu elapsed disk query current rows
------------- ------------------------------------------------ ----------
Parse 1 0.00 0.00 4 15 0 0
Execute 1 0.00 0.00 0 0 0 0
Fetch 2 0.01 0.01 1139 1143 0 1
------------- ------------------------------------------------ ----------
total 4 0.02 0.02 1143 1158 0 1
call:
每一个游标的行为被分成三个步骤：
▪Parse:
解析该游标并生成执行计划的统计信息
▪Execute:
执行该游标阶段的统计信息
▪Fetch:
Fetch取得数据行阶段的统计信息
▪count 指的是该游标的相关操作的次数，例如parsecount:
2，即该游标解析了2次
▪CPU:
相关栏目所消耗的CPU时间，单位为s
▪elapsed:
相关栏目所消耗的时间，单位为s
▪disk:
相关栏目所消耗的物理读
▪query:
相关栏目所消耗的一致性逻辑读consistentlogicalread ==>一般对于SELECT查询而言只有query没有current
▪current:
相关栏目当前逻辑读currentlogicalread
▪rows该步骤取回的行数==》在本例中由于是 count（*）所以只有一行
▪Missesinlibrarycacheduringparse:
1 在解析阶段librarycache发生了miss，则说明本次解析是硬解析
几点释疑：
1、对于PL/SQL而言匿名块/存储过程以及其中包含的SQL语句会同时体现在TKPROF中，即存在重叠；且SQL将以递归SQL的形式出现：
PARSINGINCURSOR#4len=56 dep=1 uid=0oct=6lid=0tim=1345130672819745hv=3509762282ad=’a7525f30′
UPDATEFULLSCANSETOWNER=’MACLEAN’WHEREOBJECT_ID=:
B1
COMMIT也是这样：
PARSINGINCURSOR#2len=6 dep=1 uid=0oct=44lid=0tim=1345130672822889hv=255718823ad=’0′
COMMIT
我们来看一个实际的例子：
altersystemflushshared_pool;
altersystemflushbuffer_cache;
settimingon;
altersessionsetevents'10046tracenamecontextforever,level12';
createindexind_objdonfullscan（object_id）;
begin
foriin1..10000loop
updatefullscansetowner='MACLEAN'whereobject_id=i;
commit;
endloop;
end;
/
PL/SQLproceduresuccessfullycompleted.
Elapsed:
00:
00:
04.00
begin
foriin1..10000loop
updatefullscansetowner='MACLEAN'whereobject_id=i;
commit;
endloop;
end;
call count cpu elapsed disk query current rows
------------- ------------------------------------------------ ----------
Parse 1 0.00 0.00 0 0 0 0
Execute 1 0.62 0.68 178 20037 0 1
Fetch 0 0.00 0.00 0 0 0 0
------------- ------------------------------------------------ ----------
total 2 0.62 0.68 178 20037 0 1
Missesinlibrarycacheduringparse:
1
Optimizermode:
ALL_ROWS
Parsinguserid:
SYS
Elapsedtimesincludewaitingonfollowingevents:
Eventwaitedon Times Max.Wait TotalWaited
---------------------------------------- Waited ---------- ------------
logfilesync 1 0.00 0.00
SQL*Netmessagetoclient 1 0.00 0.00
********************************************************************************
UPDATEFULLSCANSETOWNER='MACLEAN'
WHERE
OBJECT_ID=:
B1
call count cpu elapsed disk query current rows
------------- ------------------------------------------------ ----------
Parse 1 0.00 0.00 0 0 0 0
Execute 10000 2.90 2.69 178 20037 19364 9564
Fetch 0 0.00 0.00 0 0 0 0
------------- ------------------------------------------------
升级会员 