10046诊断事件——跟踪SQL语句！

10046事件并不是oracle官方提供给用户的使用命令，但是使用非常的广泛。它比sql_trace能够获得更多的信息。10046事件分成4个级别：

level 1：等同于sql_trace的功能。

level 4：在level 1的基础上增加收集绑定变量的信息。

level 8：在level 1的基础上增加等待事件的信息。

level 12：等同于level 4 + level 8。即同事收集绑定变量的信息和等待事件信息。

level 4：

SQL> select spid from v$process where addr = (select paddr from v$session where sid = (select sid from v$mystat where rownum = 1));

SPID
------------
3992

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

会话已更改。

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

PL/SQL 过程已成功完成。

SQL> exec :y:='T';

PL/SQL 过程已成功完成。

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

OWNER
------------------------------
OBJECT_NAME
--------------------------------------------------------------------------------
SUBOBJECT_NAME                  OBJECT_ID DATA_OBJECT_ID OBJECT_TYPE
------------------------------ ---------- -------------- -------------------
CREATED        LAST_DDL_TIME  TIMESTAMP           STATUS  T G S
-------------- -------------- ------------------- ------- - - -
SYS
ICOL$
20              2 TABLE
17-2月 -08     17-2月 -08     2008-02-17:01:50:56 VALID   N N N

OWNER
------------------------------
OBJECT_NAME
--------------------------------------------------------------------------------
SUBOBJECT_NAME                  OBJECT_ID DATA_OBJECT_ID OBJECT_TYPE
------------------------------ ---------- -------------- -------------------
CREATED        LAST_DDL_TIME  TIMESTAMP           STATUS  T G S
-------------- -------------- ------------------- ------- - - -
U1
T
52968          52970 TABLE
28-10月-11     28-10月-11     2011-10-28:20:28:56 VALID   N N N

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

会话已更改。

截取trace文件中的一段来说明，

Bind#0表示第一个变量，最后的value=20是变量的值。

Bind#1表示第二个变量，最后的value="T"是变量的值。

=====================
PARSING IN CURSOR #1 len=56 dep=0 uid=65 oct=3 lid=65 tim=1288935229855385 hv=446894842 ad='29a77058'
select * from t where object_id = :x or object_name = :y
END OF STMT
PARSE #1:c=3000,e=3260,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=1,tim=1288935229855375
BINDS #1:
kkscoacd
Bind#0
oacdty=02 mxl=22(22) mxlc=00 mal=00 scl=00 pre=00
oacflg=03 fl2=1000000 frm=00 csi=00 siz=56 off=0
kxsbbbfp=b7e45de8  bln=22  avl=02  flg=05
value=20
Bind#1
oacdty=01 mxl=32(01) mxlc=00 mal=00 scl=00 pre=00
oacflg=03 fl2=1000000 frm=01 csi=852 siz=0 off=24
kxsbbbfp=b7e45e00  bln=32  avl=01  flg=01
value="T"
EXEC #1:c=6000,e=5759,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,tim=1288935229861529
FETCH #1:c=1000,e=909,p=0,cr=9,cu=0,mis=0,r=1,dep=0,og=1,tim=1288935229862509
FETCH #1:c=28996,e=28807,p=0,cr=723,cu=0,mis=0,r=1,dep=0,og=1,tim=1288935229893303
STAT #1 id=1 cnt=2 pid=0 pos=1 obj=52968 op='TABLE ACCESS FULL T (cr=732 pr=0 pw=0 time=1275 us)'
=====================

level 8：

SQL> select spid from v$process where addr = (select paddr from v$session where sid = (select sid from v$mystat where rownum = 1));

SPID
------------
4037

SQL> alter session set events '10046 trace name context forever,level 8';

会话已更改。

SQL> select * from t where object_id = 100;

OWNER
------------------------------
OBJECT_NAME
--------------------------------------------------------------------------------
SUBOBJECT_NAME                  OBJECT_ID DATA_OBJECT_ID OBJECT_TYPE
------------------------------ ---------- -------------- -------------------
CREATED        LAST_DDL_TIME  TIMESTAMP           STATUS  T G S
-------------- -------------- ------------------- ------- - - -
SYS
I_TYPED_VIEW1
100            100 INDEX
17-2月 -08     17-2月 -08     2008-02-17:01:50:58 VALID   N N N

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

会话已更改。

还是截取一段来说明，

SQL*Net message to client：客户端等待服务器的反馈信息。

QLS*Net message from client：服务器等待客户端的请求。

因为我们发出的sql数据量很小，所以说看到的等待事件基本上都是消息在客户端和服务器端传递时的等待。

=====================
PARSING IN CURSOR #2 len=37 dep=0 uid=65 oct=3 lid=65 tim=1288936051913775 hv=556034074 ad='29aafa1c'
select * from t where object_id = 100
END OF STMT
PARSE #2:c=1000,e=1076,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,tim=1288936051913763
EXEC #2:c=0,e=94,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,tim=1288936051913962
WAIT #2: nam='SQL*Net message to client' ela= 3 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1288936051914040
FETCH #2:c=6998,e=6507,p=0,cr=552,cu=0,mis=0,r=1,dep=0,og=1,tim=1288936051920586
WAIT #2: nam='QLS*Net message from client' ela= 1330 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1288936051922002
FETCH #2:c=3000,e=2496,p=0,cr=180,cu=0,mis=0,r=0,dep=0,og=1,tim=1288936051924571
WAIT #2: nam='SQL*Net message to client' ela= 2 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1288936051925338
WAIT #2: nam='SQL*Net message from client' ela= 9587914 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1288936061513284
STAT #2 id=1 cnt=1 pid=0 pos=1 obj=52968 op='TABLE ACCESS FULL T (cr=732 pr=0 pw=0 time=6497 us)'
=====================

使用tkprof工具处理这个trace文件，可以看见多了如下内容

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

level 12：

SQL> select spid from v$process where addr = (select paddr from v$session where sid = (select sid from v$mystat where rownum = 1));

SPID
------------
4067

SQL> alter session set events '10046 trace name context forever,level 12';

会话已更改。

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

PL/SQL 过程已成功完成。

SQL> exec :y:='T';

PL/SQL 过程已成功完成。

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

OWNER
------------------------------
OBJECT_NAME
--------------------------------------------------------------------------------
SUBOBJECT_NAME                  OBJECT_ID DATA_OBJECT_ID OBJECT_TYPE
------------------------------ ---------- -------------- -------------------
CREATED        LAST_DDL_TIME  TIMESTAMP           STATUS  T G S
-------------- -------------- ------------------- ------- - - -
SYS
ICOL$
20              2 TABLE
17-2月 -08     17-2月 -08     2008-02-17:01:50:56 VALID   N N N

OWNER
------------------------------
OBJECT_NAME
--------------------------------------------------------------------------------
SUBOBJECT_NAME                  OBJECT_ID DATA_OBJECT_ID OBJECT_TYPE
------------------------------ ---------- -------------- -------------------
CREATED        LAST_DDL_TIME  TIMESTAMP           STATUS  T G S
-------------- -------------- ------------------- ------- - - -
U1
T
52968          52970 TABLE
28-10月-11     28-10月-11     2011-10-28:20:28:56 VALID   N N N

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

可以看见，level 12就是level 4 + level 8。不再多说。

=====================
PARSING IN CURSOR #2 len=56 dep=0 uid=65 oct=3 lid=65 tim=1288936586180240 hv=446894842 ad='29a77058'
select * from t where object_id = :x or object_name = :y
END OF STMT
PARSE #2:c=0,e=108,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,tim=1288936586180234
BINDS #2:
kkscoacd
Bind#0
oacdty=02 mxl=22(22) mxlc=00 mal=00 scl=00 pre=00
oacflg=03 fl2=1000000 frm=00 csi=00 siz=56 off=0
kxsbbbfp=b7fa8bc8  bln=22  avl=02  flg=05
value=20
Bind#1
oacdty=01 mxl=32(01) mxlc=00 mal=00 scl=00 pre=00
oacflg=03 fl2=1000000 frm=01 csi=852 siz=0 off=24
kxsbbbfp=b7fa8be0  bln=32  avl=01  flg=01
value="T"
EXEC #2:c=1000,e=691,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,tim=1288936586180998
WAIT #2: nam='SQL*Net message to client' ela= 3 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1288936586181039
FETCH #2:c=0,e=279,p=0,cr=9,cu=0,mis=0,r=1,dep=0,og=1,tim=1288936586181351
WAIT #2: nam='SQL*Net message from client' ela= 1524 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1288936586182920
WAIT #2: nam='SQL*Net message to client' ela= 6 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1288936586186159
FETCH #2:c=11998,e=12518,p=0,cr=723,cu=0,mis=0,r=1,dep=0,og=1,tim=1288936586195476
WAIT #2: nam='SQL*Net m