10046事件分析

10046事件跟踪:是oracle提供用于进行sql跟踪的手段，其内容包括sql的解析过程、sql的执行计划、绑定变量的使用、会话发生的等待事件；该事件跟踪不解释优化器的具体工作情况，这个要通过10053来跟踪额。
1、在做10046事件跟踪时，要注意一下参数的设置，很重要。

SQL> show parameter max_dump_file_size-->时间限制NAME                                 TYPE        VALUE------------------------------------ ----------- ------------------------------max_dump_file_size                   string      UNLIMITEDSQL> show parameter timed_statistics;-->对重要信息的收集NAME                                 TYPE        VALUE------------------------------------ ----------- ------------------------------timed_statistics                     boolean     TRUE

2、10046事件的级别介绍:
a)、leve1：等价sql_trace，有SQL语句、响应时间、服务时间、处理的行数，物理读和写的数目、执行计划等。到版本10.2中 执行计划写入到 trace 的条件是仅当相关游标已经关闭时，且与之相关的执行统计信息是所有执行次数的总和数据。到版本11.1中仅在每次游标的第一次执行后将执行计划写入到trace，执行统计信息仅仅和这第一次执行相关。
b)、level4:level1+绑定值
c)、level8:level1+等待事件跟踪
d)、level12:等价level1+绑定变量+等待事件
e)、level16:仅在11.1后为每一次执行生成STAT信息
f)、level32:比level 1少执行计划
g)、level64:和level 1 相比 在第一次执行后还可能生成执行计划信息 ； 条件是某个游标在前一次执行的前提下 运行耗时变长了一分钟。仅在 11.2.0.2中可用
h)、Level28:同时启用 level 4 、level 8、level 16
i)、level 68:同时启用 level 64、level 4
3、10046事件的作用域
a)、对所有用户
在参数文件中加入event="10046 trace name context forever,leve 12"
或者alter system set events '10046 trace name context forever, level 8';
alter system set events '10046 trace name context off';
b)、针对当前用户
alter session set events '10046 trace name context forever, level 12';
或者 alter session set events '10046 trace name context off';
c)、针对其他机器及其对应的用户

SQL> col machine for a25;SQL> select sid,serial#,username,machine from v$session where username is not null;       SID    SERIAL# USERNAME                       MACHINE---------- ---------- ------------------------------ -------------------------       117        873 SCOTT                          trsen       130       3420 SYSMAN                         trsen       132         39 DBSNMP                         trsen       133       2935 SYS                            trsen       134         84 DBSNMP                         trsen       144        956 SYSMAN                         trsen       150         53 SYSMAN                         trsen       153         96 SYSMAN                         trsen

--执行跟踪begin  dbms_system.set_ev(117,873,10046,8,'');end;--结束跟踪,切记一定要结束会话跟踪begin  dbms_system.set_ev(117,873,10046,0,'');end;

4、分析10046跟踪文件内容
1）、跟踪的文件头信息包含了:数据库版本、数据库实例名、系统类型、节点名、系统内核、跟踪的时间等信息。
2）、解析、执行、获取里一些参数信息的解释，下面是10046事件文件部分信息

PARSING IN CURSOR #3 len=493 dep=1 uid=0 oct=3 lid=0 tim=1356588518518811 hv=2584065658 ad='30a52988'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 STMTPARSE #3:c=2000,e=1844,p=0,cr=0,cu=0,mis=1,r=0,dep=1,og=4,tim=1356588518518778EXEC #3:c=2999,e=3469,p=0,cr=0,cu=0,mis=1,r=0,dep=1,og=4,tim=1356588518524033FETCH #3:c=1000,e=348,p=0,cr=4,cu=0,mis=0,r=1,dep=1,og=4,tim=1356588518524438

PARSING IN CURSOR里参数含义：
PARSING IN CURSOR #3 =#3这个是有标号，这个游标号就是让FETCH,WAIT,EXECUTE,PARSE和sql语句关联起来的
len=sql语句文本字节长度；
dep=递归调用深度；
uid=解析用户标示符，可以查看user$这个视图，0(sys)，表明那个用户在用这个游标什么的；
oct=oracle命令类型，与视图v$sql.command_type以及v$session.commd对应,11g里查视图v$sqlcommand
    常见值:1(create table),2(insert),3(select),6(update),7(delete),10(drop index),44(commit),45(rollback)
lid=解析模式标示符，与视图all_users.user_id以及v$sql.parsing_schema_id对应
tim=微秒单位的时间戳，在关联的parse条目中通常比tim的值早一点,这个时间戳可以用来判断 trace中2个点的时间差,V$TIMER视图，这个视图是Oracle内部计时用的
hv=散列值，与视图v$sql.hash_value对应
ad=地址，与视图v$sql.address对应
11g中有sqlid=sql标示符，对应于v$sql.sql_id
PARSE、EXEC、FETCH里参数含义：
c=cpu开销
e=运行时间
p=物理读
cr=一致读
cu=当前读buffer get数据块
mis=游标丢失，0为软解析；1为硬解析。可能是硬解析
r=被处理的数据行
dep=递归调用深度
og=优化目标，1为all_rows,2为fisrt_rows，3为rule，4为choose
plh=执行计划散列值，与视图v$sql_plan.plan_hash_value、v$sql_plan_statistics_all.plan_hash_value以及v$sqlstats.plan_hash_value对应
tim=时间戳，单位是微秒
3）、提交和回滚里一些参数信息的解释，10046跟踪事件的文件信息（选取了两段）如下:

PARSING IN CURSOR #1 len=6 dep=0 uid=54 oct=44 lid=54 tim=1356588524157378 hv=3480936638 ad='0'commitEND OF STMTPARSE #1:c=0,e=83,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=0,tim=1356588524157368XCTEND rlbk=0, rd_only=0*** 2014-01-08 10:04:54.168WAIT #0: nam='SQL*Net message from client' ela= 14447740 driver id=1650815232 #bytes=1 p3=0 obj#=51149 tim=1356588568523994XCTEND rlbk=0, rd_only=1

XCTEND里一些参数的含义:
rlbk=rollback的简写，0代表commit，1代表rollback
rd_only=只读事物，0代表发生读写操作，1带哦表只读，没有数据发生改变
由上可知，可以对rlbk，rd_only进行组合了：
rlbk=0,rd_only=0:commit,数据被修改
rlbk=0,rd_only=1:commit，数据没有被修改
rlbk=1,rd_only=0:rollback，数据被修改
rlbk=1,rd_only=1:rollback，数据没有被修改
4）、执行计划，统计信息里一些参数信息的解释，10046跟踪事件的文件信息如下:

STAT #14 id=1 cnt=1 pid=0 pos=1 obj=0 op='SORT ORDER BY (cr=8 pr=0 pw=0 time=653 us)'STAT #14 id=2 cnt=1 pid=1 pos=1 obj=0 op='HASH JOIN OUTER (cr=8 pr=0 pw=0 time=587 us)'STAT #14 id=3 cnt=1 pid=2 pos=1 obj=0 op='NESTED LOOPS OUTER (cr=5 pr=0 pw=0 time=167 us)'STAT #14 id=4 cnt=1 pid=3 pos=1 obj=19 op='TABLE ACCESS CLUSTER IND$ (cr=4 pr=0 pw=0 time=66 us)'STAT #14 id=5 cnt=1 pid=4 pos=1 obj=3 op='INDEX UNIQUE SCAN I_OBJ# (cr=2 pr=0 pw=0 time=33 us)'STAT #14 id=6 cnt=0 pid=3 pos=2 obj=710 op='TABLE ACCESS BY INDEX ROWID IND_STATS$ (cr=1 pr=0 pw=0 time=77 us)'STAT #14 id=7 cnt=0 pid=6 pos=1 obj=711 op='INDEX UNIQUE SCAN I_IND_STATS$_OBJ# (cr=1 pr=0 pw=0 time=64 us)'STAT #14 id=8 cnt=0 pid=2 pos=2 obj=0 op='VIEW  (cr=3 pr=0 pw=0 time=136 us)'STAT #14 id=9 cnt=0 pid=8 pos=1 obj=0 op='SORT GROUP BY (cr=3 pr=0 pw=0 time=125 us)'STAT #14 id=10 cnt=0 pid=9 pos=1 obj=31 op='TABLE ACCESS BY INDEX ROWID CDEF$ (cr=3 pr=0 pw=0 time=93 us)'STAT #14 id=11 cnt=2 pid=10 pos=1 obj=51 op='INDEX RANGE SCAN I_CDEF2 (cr=2 pr=0 pw=0 time=51 us)'

STAT里一些参数的含义:
id=在执行计划中指示行数据源顺序的标示符，通常一个执行计划的第一条STAT行的id=1
cnt=被处理的行数
pid=父标识符，通常一个执行计划的第一条STAT行的pid=0，通过比较id和pid做缩进
pos=在执行计划中的位置
obj=对象标识符，与视图all_objects.object_id和v$sql_plan.object#对应
op=执行的行数据源操作，比如表访问，索引扫描，排序，联合等，与视图v$sql_plan.operation对应。
cr=一致读
pr=物理读
pw=物理写
time=估计运行时间，单位微秒
这个条目有几个值会在11g中有：
cost=CBO计算的执行计划成本
size=估计的数据量，单位为字节，该值是基于对象统计数据的，如果对象统计数据不可用则会用来自数据段头部的信息
card=估计的基数，即被处理的行数，该值也是基于统计数据
5）、等待事件里一些参数信息的解释，10046跟踪事件的文件信息如下:

WAIT #4: nam='SQL*Net break/reset to client' ela= 7 driver id=1650815232 break?=1 p3=0 obj#=51149 tim=1356588554058694WAIT #4: nam='SQL*Net break/reset to client' ela= 448 driver id=1650815232 break?=0 p3=0 obj#=51149 tim=1356588554059168WAIT #4: nam='SQL*Net message to client' ela= 4 driver id=1650815232 #bytes=1 p3=0 obj#=51149 tim=1356588554059198WAIT #4: nam='SQL*Net message from client' ela= 16719 driver id=1650815232 #bytes=1 p3=0 obj#=51149 tim=1356588554076041WAIT #0: nam='SQL*Net message to client' ela= 3 driver id=1650815232 #bytes=1 p3=0 obj#=51149 tim=1356588554076149WAIT #3: nam='db file sequential read' ela= 25365 file#=7 block#=35 blocks=1 obj#=494 tim=1356528201258708WAIT #3: nam='rdbms ipc reply' ela= 20 from_process=7 timeout=21474836 p3=0 obj#=494 tim=1356528201261559

WAIT里一些参数的含义:
name=等待事件的名称
ela=运行时间，单位微秒
p1、p2、p3分别是等待事件的三个参数，即v$event_name.parameter1/parameter2/parameter3.
file#=文件编号,dba_data_file.file_id
block#=数据块号
blocks=读取的数据块量
obj#=对象编号，object_id
tim=时间戳
driver id=驱动的编号
6）、绑定变量里一些参数信息的解释，10046跟踪事件的文件信息如下:

BINDS #43:kkscoacd Bind#0  oacdty=02 mxl=22(22) mxlc=00 mal=00 scl=00 pre=00  oacflg=08 fl2=0001 frm=00 csi=00 siz=24 off=0  kxsbbbfp=b7cffac8  bln=24  avl=02  flg=05  value=3 Bind#1  oacdty=02 mxl=22(22) mxlc=00 mal=00 scl=00 pre=00  oacflg=08 fl2=0001 frm=00 csi=00 siz=24 off=0  kxsbbbfp=b7cffaa4  bln=24  avl=02  flg=05  value=8 

Bind里一些参数含义:
BINDS#43=说明绑定变量针对43号游标
Bind#0=说明是第0个变量
oacdty=数据类型代码
mxl=绑定变量值的最大长度
mxlc
mal=数组长度
scl=比例
pre=精度
oacflg=特殊标识，指示绑定选项
fl2=oacflg的第二部分
frm
csi=数据库字符集或者国际字符集的标识符
siz=给该chunk分配内存中的总量
off=该绑定缓冲区在chunk中的偏移
kxsbbbfp=buffer point
bln=bind buffer length
avl=实际值长度
flg=绑定状态标识
values=绑定变量值
如果看到 “bind 6: (No oacdef for this bind)”类似的信息则说明在trace时 还没有定义绑定数据。 这可能是在trace时游标还没绑定变量。
案例解析:
案例1:对一张表的insert 10046跟踪报告

PARSING IN CURSOR #10 len=23 dep=0 uid=54 oct=2 lid=54 tim=1357030060470088 hv=102734125 ad='2ae8be88'--uid=54说明是scott用户insert into e values(1)END OF STMTPARSE #10:c=8999,e=8728,p=0,cr=22,cu=0,mis=1,r=0,dep=0,og=1,tim=1357030060470083--22个一致性读，mis=1，很大可能是硬解析BINDS #10:--绑定的变量的编号为10，但是没有值EXEC #10:c=2000,e=1202,p=0,cr=1,cu=20,mis=0,r=1,dep=0,og=1,tim=1357030060471343--执行所花的cpu时间和实际运行时间，og=1，说明是基于cost的优化器WAIT #10: nam='SQL*Net message to client' ela= 6 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1357030060471400--没有臭名昭著的等待事件WAIT #10: nam='SQL*Net message from client' ela= 1684 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1357030060473117WAIT #0: nam='SQL*Net message to client' ela= 3 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1357030060473240WAIT #0: nam='SQL*Net message from client' ela= 2556584 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1357030063029953=====================PARSING IN CURSOR #7 len=6 dep=0 uid=54 oct=44 lid=54 tim=1357030063031134 hv=3480936638 ad='0'commitEND OF STMTPARSE #7:c=999,e=709,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=0,tim=1357030063031126--从这里开始，显而可见，是对commit的跟踪，og=0游标不可见 或 优化器环境未合理创建XCTEND rlbk=0, rd_only=0--在此处提示，数据commit，并且数据被修改EXEC #7:c=0,e=1830,p=0,cr=0,cu=1,mis=0,r=0,dep=0,og=0,tim=1357030063033029--这个buffer数据块被读到WAIT #7: nam='SQL*Net message to client' ela= 4 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1357030063033127WAIT #7: nam='SQL*Net message from client' ela= 1832 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1357030063034992WAIT #0: nam='SQL*Net message to client' ela= 3 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1357030063035181WAIT #0: nam='SQL*Net message from client' ela= 3457918 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1357030066493214XCTEND rlbk=0, rd_only=1

案例2：select

*** 2014-01-13 17:12:12.977WAIT #0: nam='SQL*Net message from client' ela= 5683096 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1357035481423195=====================PARSING IN CURSOR #1 len=316 dep=1 uid=0 oct=3 lid=0 tim=1357035481429944 hv=2704863313 ad='30a82ca4'SELECT /* OPT_DYN_SAMP */ /*+ ALL_ROWS IGNORE_WHERE_CLAUSE NO_PARALLEL(SAMPLESUB) opt_param('parallel_execution_enabled', 'false') NO_PARALLEL_INDEX(SAMPLESUB) NO_SQL_TUNE */ NVL(SUM(C1),0), NVL(SUM(C2),0) FROM (SELECT /*+ NO_PARALLEL("E") FULL("E") NO_PARALLEL_INDEX("E") */ 1 AS C1, 1 AS C2 FROM "E" "E") SAMPLESUBEND OF STMTPARSE #1:c=2999,e=2334,p=0,cr=0,cu=0,mis=1,r=0,dep=1,og=1,tim=1357035481429933BINDS #1:EXEC #1:c=0,e=137,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=1,tim=1357035481430230FETCH #1:c=0,e=321,p=0,cr=3,cu=0,mis=0,r=1,dep=1,og=1,tim=1357035481430600STAT #1 id=1 cnt=1 pid=0 pos=1 obj=0 op='SORT AGGREGATE (cr=3 pr=0 pw=0 time=325 us)'STAT #1 id=2 cnt=1 pid=1 pos=1 obj=54757 op='TABLE ACCESS FULL E (cr=3 pr=0 pw=0 time=224 us)'=====================PARSING IN CURSOR #2 len=210 dep=1 uid=0 oct=3 lid=0 tim=1357035481431451 hv=864012087 ad='30a42b3c'select /*+ rule */ bucket_cnt, row_cnt, cache_cnt, null_cnt, timestamp#, sample_size, minimum, maximum, distcnt, lowval, hival, density, col#, spare1, spare2, avgcln from hist_head$ where obj#=:1 and intcol#=:2END OF STMTPARSE #2:c=0,e=210,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=3,tim=1357035481431418BINDS #2:kkscoacd Bind#0  oacdty=02 mxl=22(22) mxlc=00 mal=00 scl=00 pre=00  oacflg=08 fl2=0001 frm=00 csi=00 siz=24 off=0  kxsbbbfp=b7fb7780  bln=22  avl=04  flg=05  value=54757 Bind#1  oacdty=02 mxl=22(22) mxlc=00 mal=00 scl=00 pre=00  oacflg=08 fl2=0001 frm=00 csi=00 siz=24 off=0  kxsbbbfp=b7fb775c  bln=24  avl=02  flg=05  value=2EXEC #2:c=0,e=378,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=3,tim=1357035481432403FETCH #2:c=0,e=220,p=0,cr=2,cu=0,mis=0,r=0,dep=1,og=3,tim=1357035481432693STAT #2 id=1 cnt=0 pid=0 pos=1 obj=255 op='TABLE ACCESS BY INDEX ROWID HIST_HEAD$ (cr=2 pr=0 pw=0 time=245 us)'STAT #2 id=2 cnt=0 pid=1 pos=1 obj=257 op='INDEX RANGE SCAN I_HH_OBJ#_INTCOL# (cr=2 pr=0 pw=0 time=213 us)'BINDS #3:kkscoacd Bind#0  oacdty=02 mxl=22(22) mxlc=00 mal=00 scl=00 pre=00  oacflg=08 fl2=0001 frm=00 csi=00 siz=24 off=0  kxsbbbfp=b7fb7780  bln=22  avl=04  flg=05  value=54757 Bind#1  oacdty=02 mxl=22(22) mxlc=00 mal=00 scl=00 pre=00  oacflg=08 fl2=0001 frm=00 csi=00 siz=24 off=0  kxsbbbfp=b7fb775c  bln=24  avl=02  flg=05  value=1=====================PARSING IN CURSOR #3 len=210 dep=1 uid=0 oct=3 lid=0 tim=1357035481433500 hv=864012087 ad='30a42b3c'select /*+ rule */ bucket_cnt, row_cnt, cache_cnt, null_cnt, timestamp#, sample_size, minimum, maximum, distcnt, lowval, hival, density, col#, spare1, spare2, avgcln from hist_head$ where obj#=:1 and intcol#=:2--查询object_id为54757对象，此对象是sys下的E表。END OF STMTEXEC #3:c=0,e=436,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=3,tim=1357035481433471FETCH #3:c=0,e=39,p=0,cr=2,cu=0,mis=0,r=0,dep=1,og=3,tim=1357035481433722=====================PARSING IN CURSOR #4 len=15 dep=0 uid=0 oct=3 lid=0 tim=1357035481434154 hv=1993667061 ad='2ac95dd4'select * from eEND OF STMTPARSE #4:c=9999,e=9738,p=0,cr=8,cu=0,mis=1,r=0,dep=0,og=1,tim=1357035481434143BINDS #4:EXEC #4:c=0,e=60,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,tim=1357035481434316WAIT #4: nam='SQL*Net message to client' ela= 9 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1357035481434437FETCH #4:c=0,e=159,p=0,cr=3,cu=0,mis=0,r=1,dep=0,og=1,tim=1357035481434668--取出一行数据WAIT #4: nam='SQL*Net message from client' ela= 1459 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1357035481436245FETCH #4:c=0,e=51,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,tim=1357035481436384WAIT #4: nam='SQL*Net message to client' ela= 5 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1357035481436471WAIT #4: nam='SQL*Net message from client' ela= 3785 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1357035481440379STAT #4 id=1 cnt=1 pid=0 pos=1 obj=54757 op='TABLE ACCESS FULL E (cr=3 pr=0 pw=0 time=131 us)'WAIT #0: nam='SQL*Net message to client' ela= 3 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1357035481440509WAIT #0: nam='SQL*Net message from client' ela= 4395267 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1357035485835876XCTEND rlbk=0, rd_only=1

后面会继续对一些问题导致的著名等待事件，进行10046的跟踪分析。