10046事件

10046类似于tkprof工具，但比sql_trace能够获得更多的内容
10046事件按照收集的信息内容，可分4级
level 1 等同于sql_trace
level 4 在level 1的基础上增加收集绑定变量的信息
level 8 在level 1的基础上增加等待事件的信息
level 12 等同于level 4 + level 8

10046的使用
SQL> alter session set events '10046 trace name context forever,level 4';

Session altered.

SQL> variable x number;
SQL> variable y varchar2;
SQL> exec :x:=20;

PL/SQL procedure successfully completed.

SQL> exec :y:='T';

PL/SQL procedure successfully completed.

SQL> select object_id,object_name from t where object_id=:x or object_name=:y;

 OBJECT_ID OBJECT_NAME
---------- ------------------------------
        20 ICOL$
     25968 T

SQL> alter session set events '10046 trace name context off';

Session altered.

一个等级为4的10046事件完成，现在来看日志（摘取）
vi oral_ora_4910.trc

PARSING IN CURSOR #1 len=20 dep=0 uid=35 ct=47 lid=35 tim=1263817116678008 hv=49482013 ad='2be63ffc'
BEGIN :x:=20; END;
END OF STMT
PARSE #1:c=1000,e=611,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=2,tim=1263817116678000
BINDS #1:
kkscoacd
 Bind#0
  acdty=02 mxl=22(22) mxlc=00 mal=00 scl=00 pre=00
  acflg=03 fl2=1000000 frm=00 csi=00 siz=24 ff=0
  kxsbbbfp=b7efc128  bln=22  avl=00  flg=05
EXEC #1:c=2000,e=1833,p=0,cr=0,cu=0,mis=1,r=1,dep=0,og=2,tim=1263817116680594
=====================
PARSING IN CURSOR #2 len=21 dep=0 uid=35 ct=47 lid=35 tim=1263817127843142 hv=2342387260 ad='2be2a17c'
BEGIN :y:='T'; END;
END OF STMT
PARSE #2:c=1000,e=1754,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=2,tim=1263817127843125
BINDS #2:
kkscoacd
 Bind#0
  acdty=01 mxl=32(01) mxlc=00 mal=00 scl=00 pre=00
  acflg=03 fl2=1000000 frm=01 csi=852 siz=32 ff=0
  kxsbbbfp=b7efc120  bln=32  avl=00  flg=05

CURSOR #1说明是运行了绑定了变量的sql

level 设成8时

PARSING IN CURSOR #4 len=21 dep=0 uid=35 ct=47 lid=35 tim=1263817646999187 hv=2342387260 ad='2be2a17c'
BEGIN :y:='T'; END;
END OF STMT
PARSE #4:c=999,e=1140,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=2,tim=1263817646999173
WAIT #4: nam='SQL*Net message to client' ela= 5 driver id=1650815232 #bytes=1 p3=0 obj#=25968 tim=1263817646999803
EXEC #4:c=1000,e=334,p=0,cr=0,cu=0,mis=0,r=1,dep=0,og=2,tim=1263817646999948
*** 2011-01-04 21:54:36.037
WAIT #4: nam='SQL*Net message from client' ela= 5380271 driver id=1650815232 #bytes=1 p3=0 obj#=25968 tim=1263817652380368
=====================
PARSING IN CURSOR #2 len=72 dep=0 uid=35 ct=3 lid=35 tim=1263817652381083 hv=1308460522 ad='2be641a0'
select object_id,object_name from t where object_id=:x or object_name=:y
END OF STMT
PARSE #2:c=0,e=164,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=2,tim=1263817652381071
EXEC #2:c=0,e=263,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=2,tim=1263817652381800
WAIT #2: nam='SQL*Net message to client' ela= 6 driver id=1650815232 #bytes=1 p3=0 obj#=25968 tim=1263817652381975
FETCH #2:c=2000,e=2111,p=0,cr=11,cu=0,mis=0,r=1,dep=0,og=2,tim=1263817652384245
WAIT #2: nam='SQL*Net message from client' ela= 1095 driver id=1650815232 #bytes=1 p3=0 obj#=25968 tim=1263817652385556
WAIT #2: nam='SQL*Net message to client' ela= 11 driver id=1650815232 #bytes=1 p3=0 obj#=25968 tim=1263817652393411
FETCH #2:c=5999,e=8018,p=0,cr=82,cu=0,mis=0,r=1,dep=0,og=2,tim=1263817652393841
WAIT #2: nam='SQL*Net message from client' ela= 3782638 driver id=1650815232 #bytes=1 p3=0 obj#=25968 tim=1263817656176850
STAT #2 id=1 cnt=2 pid=0 pos=1 bj=25968 p='TABLE ACCESS FULL T (cr=93 pr=0 pw=0 time=2098 us)'
PARSE #1:c=0,e=40,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=0,tim=1263817656177967
EXEC #1:c=0,e=133,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=0,tim=1263817656178262

从上面的信息中看到FETCH #2后面跟着的等待事件，用tkprof之后的trace，会多了一项是等待事件的信息
tkprof oral_ora_4910.trc sys=no

cat oral_ora_4910.trc找到如下信息

Elapsed times include waiting on following events:
  Event waited on                             Times   Max. Wait  Total Waited
  ----------------------------------------   Waited  ----------  ------------
  SQL*Net message to client                       4        0.00          0.00
  SQL*Net message from client                     4        5.38         13.28

 

level 设成12

PARSING IN CURSOR #1 len=72 dep=0 uid=35 ct=3 lid=35 tim=1263817910419255 hv=1308460522 ad='2be641a0'
select object_id,object_name from t where object_id=:x or object_name=:y
END OF STMT
PARSE #1:c=0,e=73,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=2,tim=1263817910419243
BINDS #1:
kkscoacd
 Bind#0
  acdty=02 mxl=22(22) mxlc=00 mal=00 scl=00 pre=00
  acflg=03 fl2=1000000 frm=00 csi=00 siz=56 ff=0
  kxsbbbfp=b7e7d45c  bln=22  avl=02  flg=05
  value=20
 Bind#1
  acdty=01 mxl=32(01) mxlc=00 mal=00 scl=00 pre=00
  acflg=03 fl2=1000000 frm=01 csi=852 siz=0 ff=24
  kxsbbbfp=b7e7d474  bln=32  avl=01  flg=01
  value="T"
EXEC #1:c=999,e=928,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=2,tim=1263817910420637
WAIT #1: nam='SQL*Net message to client' ela= 4 driver id=1650815232 #bytes=1 p3=0 obj#=25968 tim=1263817910420759
FETCH #1:c=1000,e=1009,p=0,cr=11,cu=0,mis=0,r=1,dep=0,og=2,tim=1263817910421939
WAIT #1: nam='SQL*Net message from client' ela= 832 driver id=1650815232 #bytes=1 p3=0 obj#=25968 tim=1263817910422946
WAIT #1: nam='SQL*Net message to client' ela= 8 driver id=1650815232 #bytes=1 p3=0 obj#=25968 tim=1263817910429429
FETCH #1:c=4999,e=6865,p=0,cr=82,cu=0,mis=0,r=1,dep=0,og=2,tim=1263817910429989
WAIT #1: nam='SQL*Net message from client' ela= 3508531 driver id=1650815232 #bytes=1 p3=0 obj#=25968 tim=1263817913938775
STAT #1 id=1 cnt=2 pid=0 pos=1 bj=25968 p='TABLE ACCESS FULL T (cr=93 pr=0 pw=0 time=991 us)'
PARSE #3:c=0,e=41,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=0,tim=1263817913939501
EXEC #3:c=0,e=117,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=0,tim=1263817913939738

从trace 中可以看到既有绑定变量的信息，又有等待事件的信息

 

使用sql_trace 和10046事件对其他的会话进行跟踪

sql_trace

SQL> select sid,serial# from v$session where sid=150;

       SID    SERIAL#
---------- ----------
       150         88

SQL> exec dbms_system.set_sql_trace_in_session(150,88,true);

PL/SQL procedure successfully completed.

SQL> exec dbms_system.set_sql_trace_in_session(150,88,false);

PL/SQL procedure successfully completed.

10046事件

SQL> select sid,serial# from v$session where sid=150;

       SID    SERIAL#
---------- ----------
       150         94

SQL> exec dbms_monitor.session_trace_enable(150,94,waits=>true,binds=>true);

PL/SQL procedure successfully completed.

SQL> exec dbms_monitor.session_trace_disable(150,94);

PL/SQL procedure successfully completed.

来自 “ ITPUB博客 ” ，链接：http://blog.itpub.net/7862652/viewspace-709964/，如需转载，请注明出处，否则将追究法律责任。

转载于:http://blog.itpub.net/7862652/viewspace-709964/