【EVENT】使用10046事件獲取SQL語句中繫結變數的具體值

secooler發表於2011-04-10
  在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/,如需轉載,請註明出處,否則將追究法律責任。

相關文章