上海腾科技术文献Oracle SQL Trace 和 10046 事件.docx
《上海腾科技术文献Oracle SQL Trace 和 10046 事件.docx》由会员分享，可在线阅读，更多相关《上海腾科技术文献Oracle SQL Trace 和 10046 事件.docx（11页珍藏版）》请在冰豆网上搜索。
上海腾科技术文献OracleSQLTrace和10046事件
上海腾科【技术文献】OracleSQLTrace和10046事件
一.SQL_TRACE
当SQL语句出现性能问题时，我们可以用SQL_TRACE来跟踪SQL的执行情况，通过跟踪，我们可以了解一条SQL或者PL/SQL包的运行情况，SQL_TRACE命令会将SQL执行的整个过程输出到一个trace文件中，我们可以读这个trace文件来了解在这个SQL执行过程中Oracle都做了哪些操作。
可以通过sql命令启动SQL_TRACE，或者在初始化参数里面。
SQL>altersessionsetsql_trace=true;
或者
SQL>alterdatabasesetsql_trace=true;
这两条命令的区别：
在session级别设置，只对当前session进行跟踪，在实例级别，会对实例上所有的SQL做跟踪，这种方式跟踪的SQL太多，代价是非常大的，所有很少用。
如果是在初始化文件里面设置，只需要在参数文件里添加一个sql_trace参数即可。
示例：
1.确定当前的trace文件。
1.1通过设置trace文件标识
SQL>altersessionsettracefile_identifier='安庆怀宁';
会话已更改。
设置标识的目的就是方便我们查找生成的trace文件。
我们只需要在trace目录查找文件名里带有标识的文件即可。
在Oracle10g中，SQL_TRACE生成的trace文件默认路劲是$ORACLE_BASE/admin/SID/udump.
到了11g，trace默认路径在：
$ORACLE_BASE/diag/rdbms/orcl/orcl/trace目录下.
1.2直接用如下SQL直接查出，当前的trace文件名。
/*Formattedon2010/9/123:
56:
24（QP5v5.115.810.9015）*/
SELECTd.VALUE
||'/'
||LOWER（RTRIM（i.INSTANCE,CHR（0）））
||'_ora_'
||p.spid
||'.trc'
AS"trace_file_name"
FROM（SELECTp.spid
FROMv$mystatm,v$sessions,v$processp
WHEREm.statistic#=1ANDs.SID=m.SIDANDp.addr=s.paddr）p,
（SELECTt.INSTANCE
FROMv$threadt,v$parameterv
WHEREv.NAME='thread'
AND（v.VALUE=0ORt.thread#=TO_NUMBER（v.VALUE）））i,
（SELECTVALUE
FROMv$parameter
WHERENAME='user_dump_dest'）d;
SQL>SELECTd.VALUE
2||'/'
3||LOWER（RTRIM（i.INSTANCE,CHR（0）））
4||'_ora_'
5||p.spid
6||'.trc'as"trace_file_name"
7FROM（SELECTp.spid
8FROMv$mystatm,v$sessions,v$processp
9WHEREm.statistic#=1ANDs.SID=m.SIDANDp.addr=s.paddr）p,
10（SELECTt.INSTANCE
11FROMv$threadt,v$parameterv
12WHEREv.NAME='thread'
13AND（v.VALUE=0ORt.thread#=TO_NUMBER（v.VALUE）））i,
14（SELECTVALUE
15FROMv$parameter
16WHERENAME='user_dump_dest'）d;
trace_file_name
---------------------------------------------------------------------
d:
/app/administrator/diag/rdbms/orcl/orcl/trace/orcl_ora_3048.trc
2.启动SQL_TRACE
SQL>altersessionsetsql_trace=true;
会话已更改。
3.进行相关事务操作
SQL>select*fromt;
4.关闭SQL_TRACE
SQL>altersessionsetsql_trace=false;
会话已更改。
注意，这里是显示的关闭SQL_TRACE，在session级别，也可以直接退出SQLPLUS来终止SQL_TRACE。
二．TKPROF工具
SQL_TRACE生成最原始的trace文件的可读性比较差，所以通常我们使用tkprof工具来处理trace文件。
Tkprof工具是Oracle自带的一个工具，用于处理原始的trace文件，它的作用主要是合并汇总trace文件中的一些项，规范化文件的格式，使文件更具有可读性。
注意：
tkprof工具只能用在处理SQL_TRACE和10046事件产生的trace，其他事件如10053不能处理。
刚才看了一些，也是比较粗糙，不详细，重新在整理一下。
Tkprof是系统级别的，直接在系统下执行即可。
先看一下tkprof的帮助文档：
C:
/Users/Administrator.DavidDai>tkprof
Usage:
tkproftracefileoutputfile[explain=][table=]
[print=][insert=][sys=][sort=]
table=schema.tablenameUse'schema.tablename'with'explain='option.
explain=user/passwordConnecttoORACLEandissueEXPLAINPLAN.
print=integerListonlythefirst'integer'SQLstatements.
aggregate=yes|no
insert=filenameListSQLstatementsanddatainsideINSERTstatements.
sys=noTKPROFdoesnotlistSQLstatementsrunasuserSYS.
record=filenameRecordnon-recursivestatementsfoundinthetracefile.
waits=yes|noRecordsummaryforanywaiteventsfoundinthetracefile.
sort=optionSetofzeroormoreofthefollowingsortoptions:
prscntnumberoftimesparsewascalled
prscpucputimeparsing
prselaelapsedtimeparsing
prsdsknumberofdiskreadsduringparse
prsqrynumberofbuffersforconsistentreadduringparse
prscunumberofbuffersforcurrentreadduringparse
prsmisnumberofmissesinlibrarycacheduringparse
execntnumberofexecutewascalled
execpucputimespentexecuting
exeelaelapsedtimeexecuting
exedsknumberofdiskreadsduringexecute
exeqrynumberofbuffersforconsistentreadduringexecute
execunumberofbuffersforcurrentreadduringexecute
exerownumberofrowsprocessedduringexecute
exemisnumberoflibrarycachemissesduringexecute
fchcntnumberoftimesfetchwascalled
fchcpucputimespentfetching
fchelaelapsedtimefetching
fchdsknumberofdiskreadsduringfetch
fchqrynumberofbuffersforconsistentreadduringfetch
fchcunumberofbuffersforcurrentreadduringfetch
fchrownumberofrowsfetched
useriduseridofuserthatparsedthecursor
这个帮助对tkprof工具的参数做了说明。
2.1explain=user/password
在trace文件中输入SQL的执行计划，需要注意的是，如果不使用explain，在trace文件中我们看到的是SQL实际的执行路劲。
如果使用了explain，tkprof在trace文件中不但输入SQL的实际执行路径，还会生成该SQL的执行计划。
2.2sys=no
如果设置为yes，在trace文件中将输入所有的SYS用户的操作，也包含用户SQL语句引发的递归SQL。
如果为no，则不输出这些信息。
不过默认情况下是yes，实际上设置为no后，trace文件具有更佳的可读性，因此一般在用tkprof工具时都手工的把该参数设置为no。
2.3aggregate=yes|no
默认情况下，tkprof工具将所有相同的SQL在输入文件中做合并，如果设置为no，则分别列出每个SQL的信息。
一般合并后看起来比较简洁，如果需要查看每一个SQL单独的信息，可以把aggregate设置为no。
2.4查看第一节中生成的trace文件
C:
/Users/Administrator.DavidDai>cdd:
/app/administrator/diag/rdbms/orcl/orcl/trace
C:
/Users/Administrator.DavidDai>D:
d:
/app/Administrator/diag/rdbms/orcl/orcl/trace>tkproforcl_ora_3048_安庆怀宁.trc安徽安庆怀宁.txtsys=no
TKPROF:
Release11.2.0.1.0-Developmenton星期四9月200:
22:
032010
Copyright（c）1982,2009,Oracleand/oritsaffiliates.Allrightsreserved.
d:
/app/Administrator/diag/rdbms/orcl/orcl/trace>
生成的安徽安庆怀宁.txt文件内容如下：
TKPROF:
Release11.2.0.1.0-Developmenton星期四9月200:
22:
032010
Copyright（c）1982,2009,Oracleand/oritsaffiliates.Allrightsreserved.
Tracefile:
orcl_ora_3048_安庆怀宁.trc
Sortoptions:
default
**********************************************************************
count=numberoftimesOCIprocedurewasexecuted
cpu=cputimeinsecondsexecuting
elapsed=elapsedtimeinsecondsexecuting
disk=numberofphysicalreadsofbuffersfromdisk
query=numberofbuffersgottenforconsistentread
current=numberofbuffersgottenincurrentmode（usuallyforupdate）
rows=numberofrowsprocessedbythefetchorexecutecall
***********************************************************************
#以上文件头信息描述了tkprof的版本信息，以及报告中一些列的含义
OVERALLTOTALSFORALLNON-RECURSIVESTATEMENTS#非递归SQL语句
callcountcpuelapseddiskquerycurrentrows
-------------------------------------------------------------
Parse40.010.030000
Execute50.000.000002
Fetch670.000.0001400980
-------------------------------------------------------------
total760.010.0301400982
Missesinlibrarycacheduringparse:
2#sharedpool中没有命令，说明做了2次硬解析，软解析此处为0
OVERALLTOTALSFORALLRECURSIVESTATEMENTS#递归SQL语句
callcountcpuelapseddiskquerycurrentrows
-------------------------------------------------------------
Parse50.000.000000
Execute570.000.000000
Fetch1130.000.0001760110
-------------------------------------------------------------
total1750.000.0001760110
Missesinlibrarycacheduringparse:
0
5userSQLstatementsinsession.
57internalSQLstatementsinsession.
62SQLstatementsinsession.
***********************************************************************
Tracefile:
orcl_ora_3048_安庆怀宁.trc
Tracefilecompatibility:
11.1.0.7
Sortoptions:
default
3sessionsintracefile.
10userSQLstatementsintracefile.
114internalSQLstatementsintracefile.
62SQLstatementsintracefile.
9uniqueSQLstatementsintracefile.
613linesintracefile.
27elapsedsecondsintracefile.
2.5查看trace文件
在2.4中，我们看到了tkprof生成的报告，这个报告是一个汇总的结果集，如果想确切的知道SQL语句的每一步执行是如果操作的，就需要分析原始的trace文件。
这个trace虽然没有tkprof工具处理之后易读，但是却能够清楚的知道SQL在那个点做了什么，以及SQL是如何工作的，这对与理解SQL语句的执行过程非常有用。
直接打开orcl_ora_3048_安庆怀宁.trc文件：
Tracefiled:
/app/administrator/diag/rdbms/orcl/orcl/trace/orcl_ora_3048_安庆怀宁.trc
OracleDatabase11gEnterpriseEditionRelease11.2.0.1.0-Production
WiththePartitioning,OLAP,DataMiningandRealApplicationTestingoptions
WindowsNTVersionV6.1
CPU:
2-type586,2PhysicalCores
ProcessAffinity:
0x0x00000000
Memory（Avail/Total）:
Ph:
1559M/4095M,Ph+PgF:
4170M/8188M,VA:
2881M/4095M
Instancename:
orcl
Redothreadmountedbythisinstance:
1
Oracleprocessnumber:
29
Windowsthreadid:
3048,image:
ORACLE.EXE（SHAD）
***2010-09-0123:
45:
51.877
***SESSIONID:
（267.996）2010-09-0123:
45:
51.877
***CLIENTID:
（）2010-09-0123:
45:
51.877
***SERVICENAME:
（SYS$USERS）2010-09-0123:
45:
51.877
***MODULENAME:
（sqlplus.exe）2010-09-0123:
45:
51.877
***ACTIONNAME:
（）2010-09-0123:
45:
51.877
……..
=====================
PARSINGINCURSOR#12len=493dep=1uid=0oct=3lid=0tim=488541717777hv=2584065658ad='b1dad758'sqlid='1gu8t96d0bdmu'
selectt.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.logicalreadfromtab$t,tab_stats$tswheret.obj#=:
1andt.obj#=ts.obj#（+）
ENDOFSTMT
PARSE#12:
c=0,e=59,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,plh=2035254952,tim=488541717773
EXEC#12:
c=0,e=80,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,plh=2035254952,tim=488541718176
FETCH#12:
c=0,e=127,p=0,cr=4,cu=0,mis=0,r=1,dep=1,og=4,plh=2035254952,tim=488541718359
STAT#12id=1cnt=1pid=0pos=1obj=0op='MERGEJOINOUTER（cr=4pr=0pw=0time=0uscost=2size=189card=1）'
STAT#12id=2cnt=1pid=1pos=1obj=4op='TABLEACCESSCLUSTERTAB$（cr=3pr=0pw=0time=0uscost=2size=137card=1）'
STAT#12id=3cnt=1pid=2pos=1obj=3op='INDEXUNIQUESCANI_OBJ#（cr=2pr=0pw=0time=0uscost=1size=0card=1）'
STAT#12id=4cnt=0pid=1pos=2obj=0op='BUFFERSORT（cr=1pr=0pw=0time=0uscost=0size=52card=1）'
STAT#12id=5cnt=0pid=4pos=1obj=429op='TABLEACCESSBYINDEXROWIDTAB_STATS$（cr=1pr=0pw=0time=0uscost=0size=52card=1）'
STAT#12id=6cnt=0pid=5pos=1obj=430op='INDEXUNIQUESCANI_TAB_STATS$_OBJ#（cr=1pr=0pw=0time=0uscost=0size=0card=1）'
CLOSE#12:
c=0,e=11607,dep=1,type=3,tim=488541730026
…………
这个文件的可读性要差很多。
对这里面的一些参数做些说
升级会员 