oracle 10046 trace



为什么我们要使用10046 trace?

 

10046 trace帮助我们解析一条/多条SQL、PL/SQL语句的运行状态，这些状态包括：Parse/Fetch/Execute三个阶段中遇到的等待事件、消耗的物理和逻辑读、CPU时间、执行计划等等。

即10046为我们揭示了一条/多条SQL的运行情况,对于  以点入手的 SQL调优是很好的辅助工具，特别是在 10g之前没有ASH的情况下.但整体系统调优不是10046所擅长的,10046是性能调优的起钉器,AWR是性能调优的锤子。

 

10046还能帮助我们分析一些 DDL维护命令的内部工作原理， RMAN、Data PumpExpdp/Impdp等工具的缓慢问题等，是研究 oracle数据库原理的居家旅行必备良品。

 

10046和SQL TRACE的区别？

 

10046比 SQL_TRACE参数提供更多的控制选项，更详细的内容输出，一般只用10046而不用sql_trace

 

10046和10053的区别？

 

10053是最常用的Oracle优化器optimizer跟踪trace， 10053可以作为我们解析优化器为什么选择某个执行计划，其中的理由的辅助工具，但并不告诉我们这个执行计划到底运行地如何。

而10046并不解释 optimizer优化器的工作，但它同样说明了在SQL解析parse阶段所遇到的等待事件和所消耗的CPU等资源，以及Execute执行和Fetch阶段的各项指标。

 

简而言之10046告诉我们SQL(执行计划)运行地如何， 10053告诉我们优化器为什么为这个SQL选择某个执行计划。

 

 10046 TRACE的LEVEL:

 

不同的Level对应不同的跟踪级别

• 1  启用标准的SQL_TRACE功能 (默认)  包含了 SQL语句、响应时间、服务时间、处理的行数，物理读和写的数目、执行计划以及其他一些额外信息。  到版本10.2中执行计划写入到 trace的条件是仅当相关游标已经关闭时，且与之相关的执行统计信息是所有执行次数的总和数据。  到版本11.1中仅在每次游标的第一次执行后将执行计划写入到trace，执行统计信息仅仅和这第一次执行相关

• 4比level 1时多出绑定变量的 trace

• 8  比level 1多出等待事件，特别对于9i中指出 latch free等待事件很有用，对于分析全表扫描和索引扫描也很有用

• 12  比level 1多出绑定变量和等待事件

• 16  在11g中为每一次执行生成STAT信息，仅在11.1之后可用

• 32  比level 1少执行计划

•  64  和level 1相比在第一次执行后还可能生成执行计划信息；条件是某个游标在前一次执行的前提下运行耗时变长了一分钟。仅在 11.2.0.2中可用

• Level 28 (4 + 8 + 16)代表同时启用 level 4、level 8、level 16

• level 68 ( 64 + 4 )  代表同时启用 level 64、level 4

   

   

  与SQL Trace相关的参数

  在打开10046时间的SQL Trace之前，要先设置好下面几个参数。

  timed_statistics

  这个参数决定了是否收集与时间相关的统计信息，如果这个参数为FALSE的话，那么SQL Trace的结果基本没有多大的用处，默认情况下这个参数设置为TRUE。

  max_dump_file_size

  dump文件的大小，也就是决定是否限制SQL Trace文件的大小，在一个很忙的系统上面做SQL Trace的话可能会生成很多的信息，因此最好在会话级别将这个参数设置成unlimited。

  tracefile_identifier

  给Trace文件设置识别字符串，这是个非常有用的参数，设置一个易读的字串能更快的找到Trace文件。

   

  要在当前会话修改上述参数很简单，只要使用下面的命令即可：

  ALTERSESSION SETtimed_statistics=true；

  ALTERSESSION SETmax_dump_file_size=unlimited；

  ALTERSESSION SETtracefile_identifier='my_trace_session；

   

   

   

  要是在系统运行时动态的修改别的会话的这些参数就需要借助DBMS_SYSTEM这个包了，设置方法如下：

   

  SYS.DBMS_SYSTEM.SET_BOOL_PARAM_IN_SESSION(:sid,:serial,'timed_statistics', true)

   

  SYS.DBMS_SYSTEM.SET_INT_PARAM_IN_SESSION(:sid,:serial,'max_dump_file_size', 2147483647)

   

   

   

   

  设置的方法：

   

  session级别：alter sessionset events ‘10046  trace name context forever,level X';

  system级别 : alter system set events ‘10046  trace name context forever,level X';

   

  --关闭Trace，任何级别

  ALTERSESSION SETEVENTS '10046 trace namecontext off'

   

   

   

   

  针对非本会话的某一个进程设置，如果你知道他的SPID操作系统进程号(TOP或查询视图)

  oradebug setospid SPID;

  oradebug event 10046 trace name contextforever, level X;

   

  例如：

   

  [oracle@vrh8~]$ ps -ef|grep LOCAL 

  oracle  12421 12420 0 Aug21 ?       00:00:00 oracleG10R25(DESCRIPTION=(LOCAL=YES)(ADDRESS=(PROTOCOL=beq)))

  oracle  12522 12521 0 Aug21 ?       00:00:00oracleG10R25 (DESCRIPTION=(LOCAL=YES)(ADDRESS=(PROTOCOL=beq)))

  oracle  12533    1 0 Aug21 ?        00:00:00 oracleG10R25 (LOCAL=NO)

  oracle  15354 15353 0 Aug21 ?       00:00:08oracleG10R25 (DESCRIPTION=(LOCAL=YES)(ADDRESS=(PROTOCOL=beq)))

  oracle  15419 15418 0 Aug21 ?       00:00:11oracleG10R25 (DESCRIPTION=(LOCAL=YES)(ADDRESS=(PROTOCOL=beq)))

  oracle  16219 16218 0 Aug21 ?       00:00:00oracleG10R25 (DESCRIPTION=(LOCAL=YES)(ADDRESS=(PROTOCOL=beq)))

  oracle  17098 17097 0 03:12 ?       00:00:00oracleG10R25 (DESCRIPTION=(LOCAL=YES)(ADDRESS=(PROTOCOL=beq)))

   

  要跟踪 17098 这个进程

   

  SQL>oradebug event 10046 trace name context forever, level 28;

  Statementprocessed.

   

  从 sid定位到 SPID或者 ORAPID的查询如下：

   

  SQL>select distinct sid from v$mystat;

   

        SID

  ----------

        141

   

  SQL>select spid,pid from v$Process where addr=(select paddr from v$session wheresid=141);

   

  SPID               PID

  ----------------------

  17196               24

   

  selectspid,pid from v$Process where addr=(select paddr from v$session wheresid=&SID)

   

  如果只知道 ORA的PID那么也可以

   

  oradebugsetorapid 24;

  oradebugevent 10046 trace name context forever, level 28;

   

   

   

  10046 trace示例解析

   

   

   

  这里我们引入一个全表扫描的10046例子并解析该例子中的TRACE信息：

   

   

   

  PARSING IN CURSOR #20len=44 dep=0uid=0 oct=3 lid=0tim=1344883874047619 hv=2241892608 ad='a7902a08'

  selectcount(*) from fullscan where owner=:v

  END OFSTMT

  PARSE      #20:c=2000,e=1087,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=1,tim=1344883874047610

   

  PARSINGIN CURSOR #26 len=198 dep=1 uid=0 oct=3 lid=0 tim=1344883874048534hv=4125641360 ad='a7ab9fc0'

  selectobj#,type#,ctime,mtime,stime,status,dataobj#,flags,oid$, spare1, spare2 fromobj$ where owner#=:1 and name=:2 and namespace=:3 and remoteowner is null andlinkna

  me isnull and subname is null

  END OFSTMT

  PARSE   #26:c=0,e=531,p=0,cr=0,cu=0,mis=1,r=0,dep=1,og=4,tim=1344883874048501

  BINDS#26:

  kkscoacd

   Bind#0

   oacdty=02 mxl=22(22) mxlc=00 mal=00 scl=00pre=00

   oacflg=08 fl2=0001 frm=00 csi=00 siz=24 off=0

   kxsbbbfp=7f9ccfec6bd8 bln=22 avl=01  flg=05

   value=0

   Bind#1 

   oacdty=01 mxl=32(08) mxlc=00 mal=00 scl=00pre=00

   oacflg=18 fl2=0001 frm=01 csi=873 siz=32off=0

   kxsbbbfp=7f9ccfec6ba0 bln=32 avl=08  flg=05

   value="FULLSCAN" askmaclean.com

   Bind#2

    oacdty=02 mxl=22(22) mxlc=00 mal=00 scl=00pre=00

   oacflg=08 fl2=0001 frm=00 csi=00 siz=24 off=0

   kxsbbbfp=7f9ccfec6b70 bln=24 avl=02  flg=05

   value=1

  EXEC   #26:c=1998,e=1506,p=0,cr=0,cu=0,mis=1,r=0,dep=1,og=4,tim=1344883874050177

  WAIT #26:nam='db file sequential read' ela= 26 file#=1 block#=58007 blocks=1 obj#=37tim=1344883874050345

  WAIT #26:nam='db file sequential read' ela= 19 file#=1 block#=58966 blocks=1 obj#=18tim=1344883874050452

   

  PARSINGIN CURSOR #25 len=493 dep=1 uid=0 oct=3 lid=0 tim=1344883874051980hv=2584065658 ad='a7a9ef68'

  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.e

  mpcnt,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),n

  vl(t.spare1,0),nvl(t.spare2,0),t.spare4,t.spare6,ts.cachedblk,ts.cachehit,ts.logicalreadfrom tab$ t, tab_stats$ ts where t.obj#= :1 and t.obj# = ts.obj# (+)

  END OFSTMT

  PARSE     #25:c=1000,e=585,p=0,cr=0,cu=0,mis=1,r=0,dep=1,og=4,tim=1344883874051971

  BINDS#25:

  kkscoacd

   Bind#0

   oacdty=02 mxl=22(22) mxlc=00 mal=00 scl=00pre=00

   oacflg=08 fl2=0001 frm=00 csi=00 siz=24 off=0

   kxsbbbfp=7f9ccfec6bd8 bln=22 avl=04  flg=05

   value=96551

  EXEC#25:c=3000,e=2757,p=0,cr=0,cu=0,mis=1,r=0,dep=1,og=4,tim=1344883874054930

  WAIT #25:nam='db file sequential read' ela= 21 file#=1 block#=48756 blocks=1 obj#=3tim=1344883874055059

  WAIT #25:nam='db file sequential read' ela= 18 file#=1 block#=51327 blocks=1 obj#=4tim=1344883874055149

  FETCH    #25:c=0,e=538,p=2,cr=5,cu=0,mis=0,r=1,dep=1,og=4,tim=1344883874055512

  STAT #25id=1 cnt=1 pid=0 pos=1 obj=0 op='MERGE JOIN OUTER (cr=5 pr=2 pw=0 time=565 us)'

  STAT #25id=2 cnt=1 pid=1 pos=1 obj=4 op='TABLE ACCESS CLUSTER TAB$ (cr=3 pr=2 pw=0time=228 us)'

  STAT #25id=3 cnt=1 pid=2 pos=1 obj=3 op='INDEX UNIQUE SCAN I_OBJ# (cr=2 pr=1 pw=0time=115 us)'

  STAT #25id=4 cnt=0 pid=1 pos=2 obj=0 op='BUFFER SORT (cr=2 pr=0 pw=0 time=251 us)'

  STAT #25id=5 cnt=0 pid=4 pos=1 obj=709 op='TABLE ACCESS BY INDEX ROWID TAB_STATS$ (cr=2pr=0 pw=0 time=207 us)'

  STAT #25id=6 cnt=0 pid=5 pos=1 obj=710 op='INDEX UNIQUE SCAN I_TAB_STATS$_OBJ# (cr=2pr=0 pw=0 time=33 us)'

   

  ................

   

  BINDS#20:

  kkscoacd

   Bind#0

   oacdty=96 mxl=2000(150) mxlc=00 mal=00 scl=00pre=00

   oacflg=03 fl2=1000000 frm=01 csi=873 siz=2000off=0

   kxsbbbfp=7f9ccfec6420 bln=2000 avl=50  flg=05

   value="MACLEAN                                          "

  EXEC#   20:c=20996,e=21249,p=7,cr=19,cu=0,mis=1,r=0,dep=0,og=1,tim=1344883874068951

  WAIT #20:nam='SQL*Net message to client' ela= 6 driver id=1650815232 #bytes=1 p3=0 obj#=36tim=1344883874069011

  WAIT #20:nam='db file sequential read' ela= 23 file#=1 block#=80385 blocks=1 obj#=96551tim=1344883874069159

  WAIT #20:nam='db file scattered read' ela= 42 file#=1 block#=80386 blocks=7 obj#=96551tim=1344883874069383

  WAIT #20:nam='db file scattered read' ela= 41 file#=1 block#=82313 blocks=8 obj#=96551tim=1344883874069543

  WAIT #20:nam='db file scattered read' ela= 30 file#=1 block#=82321 blocks=8 obj#=96551tim=1344883874069678

  WAIT #20:nam='db file scattered read' ela= 38 file#=1 block#=82329 blocks=8 obj#=96551tim=1344883874069949

  WAIT #20:nam='db file scattered read' ela= 848 file#=1 block#=82337 blocks=8 obj#=96551tim=1344883874070846

  WAIT #20:nam='db file scattered read' ela= 63 file#=1 block#=82345 blocks=8 obj#=96551tim=1344883874071042

  WAIT #20:nam='db file scattered read' ela= 37 file#=1 block#=92593 blocks=8 obj#=96551tim=1344883874071190

  WAIT #20:nam='db file scattered read' ela= 73 file#=1 block#=92601 blocks=8 obj#=96551tim=1344883874071393

  FETCH  #20:c=18997,e=18234,p=1139,cr=1143,cu=0,mis=0,r=1,dep=0,og=1,tim=1344883874087322

  WAIT #20:nam='SQL*Net message from client' ela= 285 driver id=1650815232 #bytes=1 p3=0obj#=96551 tim=1344883874087675

  FETCH  #20:c=0,e=3,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=0,tim=1344883874087715

  WAIT #20:nam='SQL*Net message to client' ela= 3 driver id=1650815232 #bytes=1 p3=0obj#=96551 tim=1344883874087744

  ***2013-08-22 04:44:59.527

  WAIT #20:nam='SQL*Net message from client' ela= 12169104 driver id=1650815232 #bytes=1p3=0 obj#=96551 tim=1344883886256887

  STAT #20id=1 cnt=1 pid=0 pos=1 obj=0 op='SORT AGGREGATE (cr=1143 pr=1139 pw=0time=18243 us)'

  STAT #20id=2 cnt=0 pid=1 pos=1 obj=96551 op='TABLE ACCESS FULL FULLSCAN (cr=1143pr=1139 pw=0 time=18200 us)'

  WAIT #0:nam='SQL*Net message to client' ela= 8 driver id=1650815232 #bytes=1 p3=0obj#=96551 tim=1344883886257193

  WAIT #0:nam='SQL*Net message from client' ela= 455225 driver id=1650815232 #bytes=1p3=0 obj#=96551 tim=1344883886712468

  WAIT #0:nam='SQL*Net message to client' ela= 0 driver id=1650815232 #bytes=1 p3=0obj#=96551 tim=1344883886712594

   

   

  PARSING IN CURSOR #20 len=44 dep=0uid=0oct=3 lid=0 tim=1344883874047619 hv=2241892608 ad=’a7902a08′
  select count(*) from fullscan where owner=:v
  END OF STMT
  PARSE #20:c=2000,e=1087,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=1,tim=1344883874047610

   

  PARSING IN CURSOR #20，这里的#20是游标号，这个游标号非常重要，后面的 FETCH、WAIT、EXECUTE、PARSE都通过这个游标号和前面的SQL联系起来。  

   

  注意可以看到在执行PARSING INCURSOR #20后 ,PARSE #20之后没有紧跟着 #20游标的运行，而是跟了 #25、#26游标的运行情况，仔细看一下 #25和#26他们是系统递归的recursive SQL ，这些递归SQL由用户的SQL触发，一般来说是查一些数据字典基表例如 obj$、tab$等，常规情况下递归SQL运行消耗的资源和时间都非常少。

  LEN=44 指SQL的长度

  OCT=3   Oracle command type指Oracle中命令分类的类型  可以通过 V$SQL.COMMAND_TYPE获得对应关系

  11g中提供了 V$SQLCOMMAND视图可以看到完整的对照列表， http://www.askmaclean.com/archives/vsqlcommand-sql-opcodes-and-names.html

   

  LID=0权限用户ID Privilege user id.

   

  TIM   timestamp一个时间戳，在9i之前这个指标的单位是 1/100 s即 10ms。到9i以后单位为 1/1000000  的microsecond。这个时间戳可以用来判断 trace中2个点的时间差。  这个 TIm的值来自于V$TIMER视图，这个视图是Oracle内部计时用的。

   

  DEP=0  代表该SQL的递归深入(recursive depth)，因为递归SQL可能再引发下一层的递归SQL，如果DEP=0则说明不是递归SQL，如果DEP>0则说明是递归SQL。

   

   UID=0  UID即USERID用以标明是谁在解析这个游标，如果是0则说明是SYS用户，具体用户名和UID对应可以通过如下查询获得：

  select user#,name from user$;

   

  OG=1  OG代表optimizer_mode，具体对应关系见下表

• 0  游标不可见或优化器环境未合理创建

• 1 –  ALL_ROWS

• 2  – FIRST_ROWS

• 3   – RULE

• 4   – CHOOSE

   

   

  mis=0  该指标说明library cache未发生miss，则本次解析我们不需要硬解析，而是采用软解析或者更好的方式。硬解析在Oracle中成本是很高的。注意由于在任何阶段包括PARSE/EXECUTE/FETCH阶段都可能发生游标被age out的现象，所以在这些阶段都会打印mis指标。如果mis>0则说明可能发生了硬解析。

   

  HV   代表这个SQL的hash value， 10g之前没有SQL_ID时主要靠HASH VALUE来定位一个SQL

  AD      代表SQLTEXT的地址来源于V$SQLAREA.ADDRESS

  err   代表 Oracle错误代码例如ORA-1555

   

  PARSE   是SQL运行的第一个阶段，解析SQL

  EXEC     是SQL运行的第二个阶段，运行已经解析过的语句

  FETCH  从游标中  fetch数据行

  UNMAP 是当游标使用临时表时，若游标关闭则使用UNMAP释放临时表相关的资源，包括释放锁和释放临时段

   

  C    比较重要的指标，代表本步操作消耗的CPU时间片； 9i以后单位为microsecond

  E     Elapsed Time，代表本步操作消耗的自然时间，  9i以后单位为microsecond

   

   

  这里存在一个问题例如在我们的例子中PARSE#20:c=2000,e=1087   CPU_TIME> Elapsed time  ；

  理论上应当是  ElapsedTime = CPU TIME + WAIT TIME (等待事件的时间)，但是由于CPU TIME和Elapsed time使用了不同的clock时钟计时，所以在 2者都很短，或者是CPU敏感的操作时有可能 CPUTIME> Elapsed time。

  相关的BUG有:

• Bug 4161114 : IN V$SQL, CPU_TIME > ELAPSED_TIME

• Bug 7603849 : CPU_TIME > ELAPSED_TIME FOR CERTAINSQL’S IN V$SQL

• Bug 7580277 : ELAPSED_TIME SHOWING 0 FOR CERTAIN SQL’S INV$SQL

• Bug 8243074 : INCORRECT ELAPSED_TIME IN V$SQL

  该问题可能在12c中得到修复

   

   p 物理读的数目

  CR  CR一致性读引起的buffer get 数目

  CU 当前读current read引起的buffer get数目

  r   处理的行数

   

  CLOSE #[CURSOR]:c=%u e=%u dep=%d type=%utim=%u   ==》一个游标关闭的例子

   CLOSE  游标关闭

  type    关闭游标的操作类型

• 0    该游标从未被缓存且执行次数小于3次，也叫hard close

• 1      该游标从未被缓存但执行次数至少3次，若在session cached cursor中有free slot则将该游标放入session cached cursor

• 2     该游标从未被缓存但执行次数至少3次，该游标置入session cached cursor的条件是讲老的缓存age out掉

• 3      该游标已经在缓存里，则还会去

   

   

  STAT #[CURSOR] id=N cnt=0 [pid=0 pos=0obj=0 op=’SORT AGGREGATE ‘]  

   

• STAT   相关行反应解释执行计划的统计信息

• [CURSOR]    游标号

• id    执行计划的行数从1开始

• cnt    该数据源的行数

• pid    该数据源的父ID

• pos    在执行计划中的位置

• obj    对应数据源的  object id

• op=    数据源的访问操作，例如 FULL SCAN

  11g以上还提供如下信息：

   

  STAT #2 id=1 cnt=26 pid=0 pos=1 obj=0op=’HASH GROUP BY (cr=1143 pr=1139 pw=0 time=61372 us)’
  STAT #2 id=2cnt=77276 pid=1 pos=1 obj=96551 op=’TABLE ACCESS FULL FULLSCAN (cr=1143 pr=1139pw=0 time=927821 us)’

   

• CR 代表一致性读的数量

• PR  代表物理读的数量

• pw  代表物理写的数量

• time  单位为microsecond，本步骤的耗时

• cost    本操作的优化器成本

• size    评估的数据源大小，单位为字节

• card      评估的优化器基数Cardinality.

   

   XCTEND rlbk=0, rd_only=1

•  XCTEND  一个事务结束的标志

• rlbk          如果是1代表有回滚操作，如果是0代表不会滚即 commit提交了

• rd_only    如果是1代表事务只读，如果是0说明数据改变发生过

   

   

  绑定变量  

  BINDS #20:
  kkscoacd
  Bind#0
  oacdty=96mxl=2000(150) mxlc=00 mal=00 scl=00 pre=00
  oacflg=03fl2=1000000 frm=01 csi=873 siz=2000 off=0
  kxsbbbfp=7f9ccfec6420bln=2000 avl=50 flg=05
  value=”MACLEAN

• BINDS #20:  说明绑定变量是针对 20号游标的

• kkscoacd  是绑定变量相关的描述符

• Bind#0  说明是第0个变量

• oacdty      data type   96是 ANSI fixed char

• oacflg      代表绑定选项的特殊标志位

• size          为该内存chunk分配的内存大小

• mxl      绑定变量的最大长度

• pre      precision

• scl      Scale

• kxsbbbfp         buffer point

• bln               bindbuffer length

• avl    实际的值的长度

• flg          代表绑定状态

• value=”MACLEAN    实际的绑定值

   

  如果看到 “bind 6: (Nooacdef for this bind)”类似的信息则说明在trace时，还没有定义绑定数据。这可能是在trace时游标还没绑定变量。

   

  WAIT #20: nam=’db file scattered read’ela= 42 file#=1 block#=80386 blocks=7 obj#=96551 tim=1344883874069383

   

• WAIT #20 等待 20号游标的相关等待事件

• Nam      等待针对的事件名字，它的P1、P2、P3可以参考视图V$EVENT_NAME，也可以从V$SESSION、ASH中观察到等待事件

• ela          本操作的耗时，单位为microsecond

• p1,p2,p3      针对该事件的三个描述参数，见V$EVENT_NAME

   

  在上例中针对 db filescattered read， P1为文件号， P2为起始块号， p3为读的块数，  即db file scattered read是从 1号文件的第80386个块开始一次读取了7个块。

  注意在10046中出现的WAIT行信息都是已经结束的等待事件，而当前等待则不会在trace中出现，直到这个当前等待结束。你可以通过systemstatedump/errorstack等trace来获得当前等待信息。