Wednesday, January 14, 2009

Obtain bind variable values in a SQL

I searched the internet and learned that sql trace can be used to obtain actual bind variable values in a SQL. The value will appear in the raw trace file, not available in the formatted reprot by TKPROF. I don't always remember the meaning of trace levels, usually just do 10046 with level 12 - highest level.

In 10 g, there is a view called v$sql_bind_capture that can be used for this purpose. See a post here.

Below is a test about using sql trace to find the bind varialbe values.

Once execute the followoing code, I check the trace file:




drop table t1;
create table t1 (v1 varchar2(20), n1 number);

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

variable b1 varchar2(5);
variable b2 number;

exec :b1 := 'abc5'; :b2 := 123;
insert into t1 values (:b1, :b2);
commit;

exec :b1 := 'efg'; :b2 := 456;
insert into t1 values (:b1, :b2);
commit;

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

exit;


Here are the results




******** Observiation in the trace 10.2.0.1:

Only can find the following related to that sql statment. Note the bind variable values for the
first time execution are not shown in the trace file:


=====================
PARSING IN CURSOR #7 len=32 dep=0 uid=62 oct=2 lid=62 tim=98152339039 hv=1961723033 ad='69629204'
insert into t1 values (:b1, :b2)
END OF STMT
PARSE #7:c=0,e=434,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=1,tim=98152339027

=====================
PARSING IN CURSOR #3 len=32 dep=0 uid=62 oct=2 lid=62 tim=98152761378 hv=1961723033 ad='69629204'
insert into t1 values (:b1, :b2)
END OF STMT
PARSE #3:c=0,e=164,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,tim=98152761367
BINDS #3:
kkscoacd
Bind#0
oacdty=01 mxl=32(05) mxlc=00 mal=00 scl=00 pre=00
oacflg=03 fl2=1000000 frm=01 csi=178 siz=56 off=0
kxsbbbfp=07c125b4 bln=32 avl=03 flg=05
value="efg"
Bind#1
oacdty=02 mxl=22(22) mxlc=00 mal=00 scl=00 pre=00
oacflg=03 fl2=1000000 frm=00 csi=00 siz=0 off=32
kxsbbbfp=07c125d4 bln=22 avl=03 flg=01
value=456
EXEC #3:c=0,e=841,p=0,cr=1,cu=5,mis=0,r=1,dep=0,og=1,tim=98152762535
WAIT #3: nam='SQL*Net message to client' ela= 7 driver id=1111838976 #bytes=1 p3=0 obj#=-1 tim=98152762774
WAIT #3: nam='SQL*Net message from client' ela= 375 driver id=1111838976 #bytes=1 p3=0 obj#=-1 tim=98152763291


********************************************************************************

TKPROF

insert into t1
values
(:b1, :b2)


call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 2 0.00 0.00 0 0 0 0
Execute 2 0.12 0.11 0 2 26 2
Fetch 0 0.00 0.00 0 0 0 0
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 4 0.12 0.11 0 2 26 2

Misses in library cache during parse: 1
Misses in library cache during execute: 1
Optimizer mode: ALL_ROWS
Parsing user id: 62

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








******** Observiation in the trace 9.2.0.8: we can see values for the two executions

=====================
PARSING IN CURSOR #1 len=32 dep=0 uid=178 oct=2 lid=178 tim=10450665631029 hv=340431440 ad='b8241108'
insert into t1 values (:b1, :b2)
END OF STMT
PARSE #1:c=0,e=2540,p=0,cr=5,cu=0,mis=1,r=0,dep=0,og=0,tim=10450665631025
BINDS #1:
bind 0: dty=1 mxl=32(05) mal=00 scl=00 pre=00 oacflg=03 oacfl2=0 size=56 offset=0
bfp=ffffffff7c95fb70 bln=32 avl=04 flg=05
value="abc5"
bind 1: dty=2 mxl=22(22) mal=00 scl=00 pre=00 oacflg=03 oacfl2=0 size=0 offset=32
bfp=ffffffff7c95fb90 bln=22 avl=03 flg=01
value=123
EXEC #1:c=0,e=1043,p=0,cr=1,cu=20,mis=0,r=1,dep=0,og=4,tim=10450665632203
WAIT #1: nam='SQL*Net message to client' ela= 9 p1=1413697536 p2=1 p3=0
WAIT #1: nam='SQL*Net message from client' ela= 145321 p1=1413697536 p2=1 p3=0

=====================
PARSING IN CURSOR #1 len=32 dep=0 uid=178 oct=2 lid=178 tim=10450667390749 hv=340431440 ad='b8241108'
insert into t1 values (:b1, :b2)
END OF STMT
PARSE #1:c=0,e=156,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=4,tim=10450667390743
BINDS #1:
bind 0: dty=1 mxl=32(05) mal=00 scl=00 pre=00 oacflg=03 oacfl2=0 size=56 offset=0
bfp=ffffffff7c95fb60 bln=32 avl=03 flg=05
value="efg"
bind 1: dty=2 mxl=22(22) mal=00 scl=00 pre=00 oacflg=03 oacfl2=0 size=0 offset=32
bfp=ffffffff7c95fb80 bln=22 avl=03 flg=01
value=456
EXEC #1:c=0,e=554,p=0,cr=1,cu=4,mis=0,r=1,dep=0,og=4,tim=10450667391444
WAIT #1: nam='SQL*Net message to client' ela= 3 p1=1413697536 p2=1 p3=0
WAIT #1: nam='SQL*Net message from client' ela= 144598 p1=1413697536 p2=1 p3=0

No comments: