上海腾科技术文献Oracle SQL Trace 和 10046 事件.docx

1、上海腾科技术文献Oracle SQL Trace 和 10046 事件上海腾科【技术文献】Oracle SQL Trace 和 10046 事件一. SQL_TRACE当SQL语句出现性能问题时，我们可以用SQL_TRACE来跟踪SQL的执行情况，通过跟踪，我们可以了解一条SQL或者PL/SQL包的运行情况，SQL_TRACE命令会将SQL执行的整个过程输出到一个trace文件中，我们可以读这个trace 文件来了解在这个SQL执行过程中Oracle 都做了哪些操作。可以通过sql命令启动SQL_TRACE，或者在初始化参数里面。SQLalter session set sql_trace=t

2、rue;或者SQL alter database set sql_trace=true;这两条命令的区别：在session级别设置，只对当前session进行跟踪，在实例级别，会对实例上所有的SQL做跟踪，这种方式跟踪的SQL太多，代价是非常大的，所有很少用。如果是在初始化文件里面设置，只需要在参数文件里添加一个sql_trace 参数即可。示例：1. 确定当前的trace文件。1.1 通过设置trace 文件标识SQL alter session set tracefile_identifier=安庆怀宁;会话已更改。设置标识的目的就是方便我们查找生成的trace文件。我们只需要在trace

3、目录查找文件名里带有标识的文件即可。 在Oracle 10g中，SQL_TRACE生成的trace文件默认路劲是$ORACLE_BASE/admin/SID/udump.到了11g，trace 默认路径在：$ORACLE_BASE/diag/rdbms/orcl/orcl/trace目录下.1.2直接用如下SQL直接查出，当前的trace文件名。/* Formatted on 2010/9/1 23:56:24 (QP5 v5.115.810.9015) */SELECT d.VALUE| /| LOWER (RTRIM (i.INSTANCE, CHR (0)| _ora_| p.spid|

4、 .trcAS trace_file_nameFROM (SELECT p.spidFROM v$mystat m, v$session s, v$process pWHERE m.statistic# = 1 AND s.SID = m.SID AND p.addr = s.paddr) p,(SELECT t.INSTANCEFROM v$thread t, v$parameter vWHERE v.NAME = threadAND (v.VALUE = 0 OR t.thread# = TO_NUMBER (v.VALUE) i,(SELECT VALUEFROM v$parameter

5、WHERE NAME = user_dump_dest) d;SQL SELECT d.VALUE2 | /3 | LOWER (RTRIM (i.INSTANCE, CHR (0)4 | _ora_5 | p.spid6 | .trc as trace_file_name7 FROM (SELECT p.spid8 FROM v$mystat m, v$session s, v$process p9 WHERE m.statistic# = 1 AND s.SID = m.SID AND p.addr = s.paddr) p,10 (SELECT t.INSTANCE11 FROM v$t

6、hread t, v$parameter v12 WHERE v.NAME = thread13 AND (v.VALUE = 0 OR t.thread# = TO_NUMBER (v.VALUE) i,14 (SELECT VALUE15 FROM v$parameter16 WHERE NAME = user_dump_dest) d;trace_file_name-d:/app/administrator/diag/rdbms/orcl/orcl/trace/orcl_ora_3048.trc2. 启动SQL_TRACESQL alter session set sql_trace=t

7、rue;会话已更改。3. 进行相关事务操作SQL select * from t;4. 关闭SQL_TRACESQL alter session set sql_trace=false;会话已更改。注意，这里是显示的关闭SQL_TRACE，在session级别，也可以直接退出SQLPLUS来终止SQL_TRACE。二 TKPROF 工具SQL_TRACE 生成最原始的trace文件的可读性比较差，所以通常我们使用tkprof 工具来处理trace文件。 Tkprof 工具是Oracle 自带的一个工具，用于处理原始的trace文件，它的作用主要是合并汇总trace文件中的一些项，规范化文件的格

8、式，使文件更具有可读性。注意：tkprof 工具只能用在处理SQL_TRACE和10046事件产生的trace，其他事件如10053不能处理。刚才看了一些，也是比较粗糙，不详细，重新在整理一下。 Tkprof 是系统级别的，直接在系统下执行即可。先看一下tkprof的帮助文档：C:/Users/Administrator.DavidDaitkprofUsage: tkprof tracefile outputfile explain= table= print= insert= sys= sort= table=schema.tablename Use schema.tablename wit

9、h explain= option.explain=user/password Connect to ORACLE and issue EXPLAIN PLAN.print=integer List only the first integer SQL statements.aggregate=yes|noinsert=filename List SQL statements and data inside INSERT statements.sys=no TKPROF does not list SQL statements run as user SYS.record=filename R

10、ecord non-recursive statements found in the trace file.waits=yes|no Record summary for any wait events found in the trace file.sort=option Set of zero or more of the following sort options:prscnt number of times parse was calledprscpu cpu time parsingprsela elapsed time parsingprsdsk number of disk

11、reads during parseprsqry number of buffers for consistent read during parseprscu number of buffers for current read during parseprsmis number of misses in library cache during parseexecnt number of execute was calledexecpu cpu time spent executingexeela elapsed time executingexedsk number of disk re

12、ads during executeexeqry number of buffers for consistent read during executeexecu number of buffers for current read during executeexerow number of rows processed during executeexemis number of library cache misses during executefchcnt number of times fetch was calledfchcpu cpu time spent fetchingf

13、chela elapsed time fetchingfchdsk number of disk reads during fetchfchqry number of buffers for consistent read during fetchfchcu number of buffers for current read during fetchfchrow number of rows fetcheduserid userid of user that parsed the cursor这个帮助对tkprof工具的参数做了说明。2.1 explain=user/password在tra

14、ce文件中输入SQL的执行计划，需要注意的是，如果不使用explain，在trace 文件中我们看到的是SQL实际的执行路劲。 如果使用了explain，tkprof在trace文件中不但输入SQL的实际执行路径，还会生成该SQL的执行计划。2.2 sys=no如果设置为yes，在trace 文件中将输入所有的SYS用户的操作，也包含用户SQL语句引发的递归SQL。如果为no，则不输出这些信息。不过默认情况下是yes，实际上设置为no后，trace文件具有更佳的可读性，因此一般在用tkprof工具时都手工的把该参数设置为no。2.3 aggregate=yes|no默认情况下，tkprof工具

15、将所有相同的SQL在输入文件中做合并，如果设置为no，则分别列出每个SQL的信息。一般合并后看起来比较简洁，如果需要查看每一个SQL单独的信息，可以把aggregate设置为no。2.4 查看第一节中生成的trace文件C:/Users/Administrator.DavidDaicd d:/app/administrator/diag/rdbms/orcl/orcl/traceC:/Users/Administrator.DavidDaiD:d:/app/Administrator/diag/rdbms/orcl/orcl/tracetkprof orcl_ora_3048_安庆怀宁.trc

16、 安徽安庆怀宁.txt sys=noTKPROF: Release 11.2.0.1.0 - Development on 星期四 9月 2 00:22:03 2010Copyright (c) 1982, 2009, Oracle and/or its affiliates. All rights reserved.d:/app/Administrator/diag/rdbms/orcl/orcl/trace生成的 安徽安庆怀宁.txt文件内容如下：TKPROF: Release 11.2.0.1.0 - Development on 星期四 9月 2 00:22:03 2010Copyri

17、ght (c) 1982, 2009, Oracle and/or its affiliates. All rights reserved.Trace file: orcl_ora_3048_安庆怀宁.trcSort options: default*count = number of times OCI procedure was executedcpu = cpu time in seconds executingelapsed = elapsed time in seconds executingdisk = number of physical reads of buffers fro

18、m diskquery = number of buffers gotten for consistent readcurrent = number of buffers gotten in current mode (usually for update)rows = number of rows processed by the fetch or execute call*# 以上文件头信息描述了tkprof的版本信息，以及报告中一些列的含义OVERALL TOTALS FOR ALL NON-RECURSIVE STATEMENTS #非递归SQL语句call count cpu ela

19、psed disk query current rows- - - - - - -Parse 4 0.01 0.03 0 0 0 0Execute 5 0.00 0.00 0 0 0 2Fetch 67 0.00 0.00 0 140 0 980- - - - - - -total 76 0.01 0.03 0 140 0 982Misses in library cache during parse: 2 #shared pool 中没有命令，说明做了2次硬解析，软解析此处为0OVERALL TOTALS FOR ALL RECURSIVE STATEMENTS #递归SQL语句call c

20、ount cpu elapsed disk query current rows- - - - - - -Parse 5 0.00 0.00 0 0 0 0Execute 57 0.00 0.00 0 0 0 0Fetch 113 0.00 0.00 0 176 0 110- - - - - - -total 175 0.00 0.00 0 176 0 110Misses in library cache during parse: 05 user SQL statements in session.57 internal SQL statements in session.62 SQL st

21、atements in session.*Trace file: orcl_ora_3048_安庆怀宁.trcTrace file compatibility: 11.1.0.7Sort options: default3 sessions in tracefile.10 user SQL statements in trace file.114 internal SQL statements in trace file.62 SQL statements in trace file.9 unique SQL statements in trace file.613 lines in trac

22、e file.27 elapsed seconds in trace file.2.5 查看trace 文件在2.4中，我们看到了tkprof生成的报告，这个报告是一个汇总的结果集，如果想确切的知道SQL 语句的每一步执行是如果操作的，就需要分析原始的trace文件。 这个trace 虽然没有tkprof工具处理之后易读，但是却能够清楚的知道SQL在那个点做了什么，以及SQL是如何工作的，这对与理解SQL语句的执行过程非常有用。直接打开 orcl_ora_3048_安庆怀宁.trc 文件：Trace file d:/app/administrator/diag/rdbms/orcl/orcl/

23、trace/orcl_ora_3048_安庆怀宁.trcOracle Database 11g Enterprise Edition Release 11.2.0.1.0 - ProductionWith the Partitioning, OLAP, Data Mining and Real Application Testing optionsWindows NT Version V6.1CPU : 2 - type 586, 2 Physical CoresProcess Affinity : 0x0x00000000Memory (Avail/Total): Ph:1559M/4095

24、M, Ph+PgF:4170M/8188M, VA:2881M/4095MInstance name: orclRedo thread mounted by this instance: 1Oracle process number: 29Windows thread id: 3048, image: ORACLE.EXE (SHAD)* 2010-09-01 23:45:51.877* SESSION ID:(267.996) 2010-09-01 23:45:51.877* CLIENT ID:() 2010-09-01 23:45:51.877* SERVICE NAME:(SYS$US

25、ERS) 2010-09-01 23:45:51.877* MODULE NAME:(sqlplus.exe) 2010-09-01 23:45:51.877* ACTION NAME:() 2010-09-01 23:45:51.877.=PARSING IN CURSOR #12 len=493 dep=1 uid=0 oct=3 lid=0 tim=488541717777 hv=2584065658 ad=b1dad758 sqlid=1gu8t96d0bdmuselect t.ts#,t.file#,t.block#,nvl(t.bobj#,0),nvl(t.tab#,0),t.in

26、tcols,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

27、,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 STMTPARSE #12:c=0,e=59,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,plh=2035254952,tim=488541717773EXEC #12:c=0,e=80,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,plh=2035254952,tim=48

28、8541718176FETCH #12:c=0,e=127,p=0,cr=4,cu=0,mis=0,r=1,dep=1,og=4,plh=2035254952,tim=488541718359STAT #12 id=1 cnt=1 pid=0 pos=1 obj=0 op=MERGE JOIN OUTER (cr=4 pr=0 pw=0 time=0 us cost=2 size=189 card=1)STAT #12 id=2 cnt=1 pid=1 pos=1 obj=4 op=TABLE ACCESS CLUSTER TAB$ (cr=3 pr=0 pw=0 time=0 us cost

29、=2 size=137 card=1)STAT #12 id=3 cnt=1 pid=2 pos=1 obj=3 op=INDEX UNIQUE SCAN I_OBJ# (cr=2 pr=0 pw=0 time=0 us cost=1 size=0 card=1)STAT #12 id=4 cnt=0 pid=1 pos=2 obj=0 op=BUFFER SORT (cr=1 pr=0 pw=0 time=0 us cost=0 size=52 card=1)STAT #12 id=5 cnt=0 pid=4 pos=1 obj=429 op=TABLE ACCESS BY INDEX ROWID TAB_STATS$ (cr=1 pr=0 pw=0 time=0 us cost=0 size=52 card=1)STAT #12 id=6 cnt=0 pid=5 pos=1 obj=430 op=INDEX UNIQUE SCAN I_TAB_STATS$_OBJ# (cr=1 pr=0 pw=0 time=0 us cost=0 size=0 card=1)CLOSE #12:c=0,e=11607,dep=1,type=3,tim=488541730026这个文件的可读性要差很多。 对这里面的一些参数做些说