【EVENT】使用10046事件获取SQL语句中绑定变量的具体值

  在OLTP环境下的应用开发过程中，会大量采用绑定变量技术来避免SQL语句的硬解析。含有绑定变量的SQL语句只用在执行的时候才能确定变量的最终值。因此，如何获取绑定变量的具体值这个问题便摆在我们面前。
  本文给出使用10046事件获取绑定变量具体信息的方法。

1.环境准备
1）在sec用户下创建测试用表T
sys@ora10g> conn sec/sec
Connected.
sec@ora10g> create table t (x varchar2(8));

Table created.

sec@ora10g> desc t;
 Name         Null?    Type
 ------------ -------- ---------------
 X                     VARCHAR2(8)

测试表T准备就绪。

2）准备测试用PL/SQL块代码
用以下PL/SQL语句来模拟含有绑定变量的SQL语句。
declare
  v_secooler char(8) := 'secooler' ;
begin
  insert into t values (v_secooler);
end;
/

2.执行PL/SQL块代码
sec@ora10g> declare
  2    v_secooler char(8) := 'secooler' ;
  3  begin
  4    insert into t values (v_secooler);
  5  end;
  6  /

PL/SQL procedure successfully completed.

sec@ora10g> select * from t;

X
--------
secooler

使用PL/SQL向表T中插入数据成功。
注意，这里使用绑定变量的方式向表T中插入数据时，是无法记录绑定变量的具体值的。

3.使用10046事件的LEVEL 4获取绑定变量的具体值
1）使用session级别生效的方法启用10046事件
sec@ora10g> alter session set events '10046 trace name context forever, level 4';

Session altered.

2）在此执行PL/SQL代码
sec@ora10g> declare
  2    v_secooler char(8) := 'secooler' ;
  3  begin
  4    insert into t values (v_secooler);
  5  end;
  6  /

PL/SQL procedure successfully completed.

使用10046事件是将以上命令的执行信息记录在trace文件中，并不会在SQL*Plus中体现出来。由于是用户产生的trace信息，因此对应的trace文件存放在user_dump_dest参数对应的目录中。

3）获取user_dump_dest参数对应的目录
sys@ora10g> show parameter user_dump_dest

NAME                 TYPE                 VALUE
-------------------- -------------------- ---------------------------------------
user_dump_dest       string               /oracle/ora10gR2/admin/ora10g/udump

4）获取对应的trace文件
ora10g@secdb /oracle/ora10gR2/admin/ora10g/udump$ ls -ltr | tail -1
-rw-r----- 1 oracle oinstall 3.7K Apr 10 23:01 ora10g_ora_24852.trc

5）获取trace文件内容
将完整的trace文件内容展示于此，便于查看PL/SQL的执行过程。
ora10g@secdb /oracle/ora10gR2/admin/ora10g/udump$ cat ora10g_ora_24852.trc
/oracle/ora10gR2/admin/ora10g/udump/ora10g_ora_24852.trc
Oracle Database 10g Enterprise Edition Release 10.2.0.1.0 - Production
With the Partitioning, OLAP and Data Mining options
ORACLE_HOME = /oracle/ora10gR2/product/10.2.0/db_2
System name:    Linux
Node name:      secdb
Release:        2.6.18-194.el5
Version:        #1 SMP Mon Mar 29 20:06:41 EDT 2010
Machine:        i686
Instance name: ora10g
Redo thread mounted by this instance: 1
Oracle process number: 15
Unix process pid: 24852, image: oracle@secdb (TNS V1-V3)

*** ACTION NAME:() 2011-04-10 23:00:59.282
*** MODULE NAME:(SQL*Plus) 2011-04-10 23:00:59.282
*** SERVICE NAME:(SYS$USERS) 2011-04-10 23:00:59.282
*** SESSION ID:(142.12934) 2011-04-10 23:00:59.282
=====================
PARSING IN CURSOR #3 len=68 dep=0 uid=62 ct=42 lid=62 tim=1271921542268000 hv=1896049376 ad='2bf858a4'
alter session set events '10046 trace name context forever, level 4'
END OF STMT
EXEC #3:c=1000,e=184,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,tim=1271921542267993
=====================
PARSING IN CURSOR #2 len=52 dep=0 uid=62 ct=47 lid=62 tim=1271921542268760 hv=1029988163 ad='2bc63e04'
BEGIN DBMS_OUTPUT.GET_LINES(:LINES, :NUMLINES); END;
END OF STMT
PARSE #2:c=0,e=49,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,tim=1271921542268754
BINDS #2:
kkscoacd
 Bind#0
  acdty=123 mxl=4000(4000) mxlc=00 mal=00 scl=00 pre=00
  acflg=00 fl2=1000000 frm=00 csi=00 siz=4000 ff=0
  kxsbbbfp=b7f0306c  bln=4000  avl=00  flg=15
 Bind#1
  acdty=02 mxl=22(22) mxlc=00 mal=00 scl=00 pre=00
  acflg=01 fl2=1000000 frm=00 csi=00 siz=24 ff=0
  kxsbbbfp=b7f04400  bln=22  avl=22  flg=05
  value=###
  An invalid number has been seen.Memory contents are :
Dump of memory from 0xB7F04400 to 0xB7F04416
B7F04400 000102C2 00000000 00000000 00000000  [................]
B7F04410 00000000 00000000                    [........]
EXEC #2:c=0,e=512,p=0,cr=0,cu=0,mis=0,r=1,dep=0,og=1,tim=1271921542269430
*** 2011-04-10 23:01:03.765
=====================
PARSING IN CURSOR #2 len=92 dep=0 uid=62 ct=47 lid=62 tim=1271921546645703 hv=2109960532 ad='28377174'
declare
  v_secooler char(8) := 'secooler' ;
begin
  insert into t values (v_secooler);
end;
END OF STMT
PARSE #2:c=0,e=191,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,tim=1271921546645695
BINDS #2:
=====================
PARSING IN CURSOR #3 len=27 dep=1 uid=62 ct=2 lid=62 tim=1271921546646168 hv=3116513188 ad='2833eab8'
INSERT INTO T VALUES (:B1 )
END OF STMT
PARSE #3:c=0,e=97,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=1,tim=1271921546646165
BINDS #3:
kkscoacd
 Bind#0
  acdty=96 mxl=32(08) mxlc=00 mal=00 scl=00 pre=00
  acflg=13 fl2=206001 frm=01 csi=31 siz=32 ff=0
  kxsbbbfp=b7ee4604  bln=32  avl=08  flg=09
  value="secooler"
EXEC #3:c=1000,e=824,p=0,cr=1,cu=5,mis=0,r=1,dep=1,og=1,tim=1271921546647096
EXEC #2:c=1000,e=1296,p=0,cr=1,cu=5,mis=0,r=1,dep=0,og=1,tim=1271921546647178
=====================
PARSING IN CURSOR #4 len=52 dep=0 uid=62 ct=47 lid=62 tim=1271921546647512 hv=1029988163 ad='2bc63e04'
BEGIN DBMS_OUTPUT.GET_LINES(:LINES, :NUMLINES); END;
END OF STMT
PARSE #4:c=0,e=45,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,tim=1271921546647506
BINDS #4:
kkscoacd
 Bind#0
  acdty=123 mxl=4000(4000) mxlc=00 mal=00 scl=00 pre=00
  acflg=00 fl2=1000000 frm=00 csi=00 siz=4000 ff=0
  kxsbbbfp=b7f02424  bln=4000  avl=00  flg=15
 Bind#1
  acdty=02 mxl=22(22) mxlc=00 mal=00 scl=00 pre=00
  acflg=01 fl2=1000000 frm=00 csi=00 siz=24 ff=0
  kxsbbbfp=b7f037b8  bln=22  avl=22  flg=05
  value=###
  An invalid number has been seen.Memory contents are :
Dump of memory from 0xB7F037B8 to 0xB7F037CE
B7F037B0                   000102C2 00000000          [........]
B7F037C0 00000000 00000000 00000000 00000000  [................]
EXEC #4:c=0,e=469,p=0,cr=0,cu=0,mis=0,r=1,dep=0,og=1,tim=1271921546648129
XCTEND rlbk=0, rd_only=0

6）仔细阅读trace文件中的内容
trace文件记录了整个PL/SQL语句解析和执行的过程。
由于开启了LEVEL 4级别的10046事件，对应的绑定变量的值亦得以体现。
注：为了快速的获得绑定变量信息可以对trace文件以“value=”关键字进行检索定位。

PARSING IN CURSOR #3 len=27 dep=1 uid=62 ct=2 lid=62 tim=1271921546646168 hv=3116513188 ad='2833eab8'
INSERT INTO T VALUES (:B1 )
END OF STMT
PARSE #3:c=0,e=97,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=1,tim=1271921546646165
BINDS #3:
kkscoacd
 Bind#0
  acdty=96 mxl=32(08) mxlc=00 mal=00 scl=00 pre=00
  acflg=13 fl2=206001 frm=01 csi=31 siz=32 ff=0
  kxsbbbfp=b7ee4604  bln=32  avl=08  flg=09
  value="secooler"
EXEC #3:c=1000,e=824,p=0,cr=1,cu=5,mis=0,r=1,dep=1,og=1,tim=1271921546647096
EXEC #2:c=1000,e=1296,p=0,cr=1,cu=5,mis=0,r=1,dep=0,og=1,tim=1271921546647178

这段内容便是insert语句中绑定变量具体值的体现！

4.开启10046事件的另外一种方法
除了在session级别开启10046事件，也可以通过调整数据库参数的方法来实现。
具体方法如下：
1）查看数据库event参数的内容
sys@ora10g> show parameter event

NAME        TYPE                 VALUE
----------- -------------------- ---------------
event       string

2）调整event参数
注意event参数是静态参数，直接修改会收到如下报错信息。
sys@ora10g> alter system set event="10046 trace name context forever, level 4";
alter system set event="10046 trace name context forever, level 4"
                 *
ERROR at line 1:
ORA-02095: specified initialization parameter cannot be modified

使用“scope=spfile”选项进行调整。
sys@ora10g> alter system set event="10046 trace name context forever, level 4" scope=spfile;

System altered.

3）重启数据库使调整后的EVENT参数生效
sys@ora10g> show parameter event

NAME        TYPE                 VALUE
----------- -------------------- ----------------
event       string
sys@ora10g> startup force;
ORACLE instance started.

Total System Global Area  268435456 bytes
Fixed Size                  1218868 bytes
Variable Size             117442252 bytes
Database Buffers          142606336 bytes
Redo Buffers                7168000 bytes
Database mounted.
Database opened.
sys@ora10g> show parameter event

NAME       TYPE                 VALUE
---------- -------------------- -------------------------------------------
event      string               10046 trace name context forever, level 4

4）获取trace文件信息
按照上面介绍的方法重新获取trace文件的内容，内容如下，与session级别开启10046事件的方法内容大同小异。

trace文件信息如下，供参考比对。

……省略其他输出信息……
=====================
PARSING IN CURSOR #7 len=92 dep=0 uid=62 ct=47 lid=62 tim=1271922490324608 hv=2109960532 ad='27bc8ea4'
declare
  v_secooler char(8) := 'secooler' ;
begin
  insert into t values (v_secooler);
end;
END OF STMT
PARSE #7:c=9998,e=9205,p=4,cr=22,cu=0,mis=1,r=0,dep=0,og=1,tim=1271922490324601
BINDS #7:
=====================

……省略其他输出信息……

=====================
PARSING IN CURSOR #5 len=151 dep=2 uid=0 ct=3 lid=0 tim=1271922490328760 hv=4139184264 ad='2fafe8c0'
select grantee#,privilege#,nvl(col#,0),max(mod(nvl(option$,0),2))from objauth$ where obj#=:1 group by grantee#,privilege#,nvl(col#,0) order by grantee#
END OF STMT
PARSE #5:c=0,e=29,p=0,cr=0,cu=0,mis=0,r=0,dep=2,og=4,tim=1271922490328756
BINDS #5:
kkscoacd
 Bind#0
  acdty=02 mxl=22(22) mxlc=00 mal=00 scl=00 pre=00
  acflg=08 fl2=0001 frm=00 csi=00 siz=24 ff=0
  kxsbbbfp=b7fd43d4  bln=22  avl=04  flg=05
  value=52718
EXEC #5:c=0,e=148,p=0,cr=0,cu=0,mis=0,r=0,dep=2,og=4,tim=1271922490329030
FETCH #5:c=0,e=27,p=0,cr=2,cu=0,mis=0,r=0,dep=2,og=4,tim=1271922490329090
STAT #5 id=1 cnt=0 pid=0 pos=1 bj=0 p='SORT GROUP BY (cr=2 pr=0 pw=0 time=43 us)'
STAT #5 id=2 cnt=0 pid=1 pos=1 bj=57 p='TABLE ACCESS BY INDEX ROWID OBJAUTH$ (cr=2 pr=0 pw=0 time=25 us)'
STAT #5 id=3 cnt=0 pid=2 pos=1 bj=103 p='INDEX RANGE SCAN I_OBJAUTH1 (cr=2 pr=0 pw=0 time=19 us)'
BINDS #6:
kkscoacd
 Bind#0
  acdty=96 mxl=32(08) mxlc=00 mal=00 scl=00 pre=00
  acflg=13 fl2=206001 frm=01 csi=31 siz=32 ff=0
  kxsbbbfp=b7fa4530  bln=32  avl=08  flg=09
  value="secooler"
EXEC #6:c=6000,e=5327,p=4,cr=12,cu=5,mis=1,r=1,dep=1,og=1,tim=1271922490330536
EXEC #7:c=6000,e=5933,p=4,cr=12,cu=5,mis=0,r=1,dep=0,og=1,tim=1271922490330683
=====================

在不需要使用10046事件的时候，需要将event参数调整为空的状态，否则会在user_dump_dest对应的目录中生成大量trace文件。
sys@ora10g> alter system set event='' scope=spfile;

5.小结
  使用10046事件是获取绑定变量值的一种直观高效的方法，可以在这个基础上结合Shell技术完成对trace文件自动检索和分析的任务。

Good luck.

secooler
11.04.10

-- The End --

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

转载于:http://blog.itpub.net/519536/viewspace-692196/