Tracing the Bind Values

Posted by Steve Racanovic | Posted in , | Posted on 11:52 AM

0

Created a simple example of how you can isolate and trace the bind variables for the records inserted and understand what to look for in the trace file.

The table here consists of 3 columns. A varchar2, number and timestamp.

The jdev 11113 workspace for this example is here.

When running the application, this following results are displayed:


=============
Java Vendor is ... Sun Microsystems Inc.

Java Version is  1.6.0_18

=============
Database Product Name is ... Oracle

Database Product Version is  Oracle Database 10g Enterprise Edition Release 10.2.0.1.0 - Production
With the Partitioning, OLAP and Data Mining options

=============
JDBC Driver Name is ........ Oracle JDBC driver

JDBC Driver Version is ..... 11.1.0.7.0-Production

=============
Dropping/Creating table...

 execSQL() returning: 0 for SQL=DROP TABLE SCOTT.BIND_TEST

 execSQL() returning: 0 for SQL=CREATE TABLE SCOTT.BIND_TEST (VARCHAR_FIELD VARCHAR2(50), NO_FIELD NUMBER(2), TIMESTAMP_FIELD TIMESTAMP)
Preparing stmt: INSERT INTO SCOTT.BIND_TEST (VARCHAR_FIELD, NO_FIELD, TIMESTAMP_FIELD) VALUES (?, ?, ?)
Inserting ...
Inserting Complete...
DISPLAY...
test_string_0.8433509446104999 0 2010-05-17 11:35:46.328
test_string_0.32801143775147246 1 2010-05-17 11:35:46.5
test_string_0.6936132181788695 2 2010-05-17 11:35:46.515
test_string_0.4458248593661084 3 2010-05-17 11:35:46.515
test_string_0.8349244238371425 4 2010-05-17 11:35:46.515
test_string_0.014215120763115707 5 2010-05-17 11:35:46.515
test_string_0.7895349187550287 6 2010-05-17 11:35:46.515
test_string_0.33693148690955965 7 2010-05-17 11:35:46.531
test_string_0.60803516417148 8 2010-05-17 11:35:46.531
test_string_0.5201490476224547 9 2010-05-17 11:35:46.531

Show Trace File...
TRACE FILE NAME : /u01/programs/oracle/product/10.2.0/db_1/admin/orcl/udump/orcl_ora_16541.trc


Open the trace file I can see the following:

...
PARSING IN CURSOR #8 len=90 dep=0 uid=5 oct=2 lid=5 tim=1244198234987514 hv=896770016 ad='2b9e3258'
INSERT INTO SCOTT.BIND_TEST (VARCHAR_FIELD, NO_FIELD, TIMESTAMP_FIELD) VALUES (:1, :2, :3)
END OF STMT
PARSE #8:c=2000,e=2579,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=1,tim=1244198234987507
=====================
PARSING IN CURSOR #12 len=227 dep=1 uid=0 oct=3 lid=0 tim=1244198235054488 hv=2190775527 ad='2f56e994'
select u.name,o.name, t.update$, t.insert$, t.delete$, t.enabled  from obj$ o,user$ u,trigger$ t  where t.baseobject=:1 and t.obj#=o.obj# and o.owner#=u.user#  and bitand(property,16)=0 and bitand(property,8)=0  order by o.obj#
END OF STMT
PARSE #12:c=3000,e=2745,p=0,cr=0,cu=0,mis=1,r=0,dep=1,og=4,tim=1244198235054480
BINDS #12:
kkscoacd
 Bind#0
  oacdty=02 mxl=22(22) mxlc=00 mal=00 scl=00 pre=00
  oacflg=00 fl2=0001 frm=00 csi=00 siz=24 off=0
  kxsbbbfp=b7234fe8  bln=22  avl=04  flg=05
  value=150767
EXEC #12:c=5999,e=73474,p=0,cr=0,cu=0,mis=1,r=0,dep=1,og=4,tim=1244198235128125
FETCH #12:c=0,e=59,p=0,cr=1,cu=0,mis=0,r=0,dep=1,og=4,tim=1244198235128225
STAT #12 id=1 cnt=0 pid=0 pos=1 obj=0 op='SORT ORDER BY (cr=1 pr=0 pw=0 time=103 us)'
STAT #12 id=2 cnt=0 pid=1 pos=1 obj=0 op='NESTED LOOPS  (cr=1 pr=0 pw=0 time=77 us)'
STAT #12 id=3 cnt=0 pid=2 pos=1 obj=0 op='NESTED LOOPS  (cr=1 pr=0 pw=0 time=69 us)'
STAT #12 id=4 cnt=0 pid=3 pos=1 obj=81 op='TABLE ACCESS BY INDEX ROWID TRIGGER$ (cr=1 pr=0 pw=0 time=64 us)'
STAT #12 id=5 cnt=0 pid=4 pos=1 obj=125 op='INDEX RANGE SCAN I_TRIGGER1 (cr=1 pr=0 pw=0 time=35 us)'
STAT #12 id=6 cnt=0 pid=3 pos=2 obj=18 op='TABLE ACCESS BY INDEX ROWID OBJ$ (cr=0 pr=0 pw=0 time=0 us)'
STAT #12 id=7 cnt=0 pid=6 pos=1 obj=36 op='INDEX UNIQUE SCAN I_OBJ1 (cr=0 pr=0 pw=0 time=0 us)'
STAT #12 id=8 cnt=0 pid=2 pos=2 obj=22 op='TABLE ACCESS CLUSTER USER$ (cr=0 pr=0 pw=0 time=0 us)'
STAT #12 id=9 cnt=0 pid=8 pos=1 obj=11 op='INDEX UNIQUE SCAN I_USER# (cr=0 pr=0 pw=0 time=0 us)'
BINDS #8:
kkscoacd
 Bind#0
  oacdty=01 mxl=32(30) mxlc=00 mal=00 scl=00 pre=00
  oacflg=03 fl2=1000010 frm=01 csi=31 siz=68 off=0
  kxsbbbfp=b722aaec  bln=32  avl=30  flg=05
  value="test_string_0.8433509446104999"
 Bind#1
  oacdty=02 mxl=22(22) mxlc=00 mal=00 scl=00 pre=00
  oacflg=03 fl2=1000000 frm=01 csi=31 siz=0 off=32
  kxsbbbfp=b722ab0c  bln=22  avl=01  flg=01
  value=0
 Bind#2
  oacdty=180 mxl=11(11) mxlc=00 mal=00 scl=00 pre=00
  oacflg=03 fl2=1000000 frm=01 csi=31 siz=0 off=56
  kxsbbbfp=b722ab24  bln=11  avl=11  flg=01
  value=
Dump of memory from 0xB722AB24 to 0xB722AB2F
B722AB20          11056E78 132F240C 0000E28C      [xn...$/.....]
EXEC #8:c=12998,e=101172,p=0,cr=2,cu=21,mis=1,r=1,dep=0,og=1,tim=1244198235152633
XCTEND rlbk=0, rd_only=0
...


Here you can see the first insert query references "CURSOR #8" that will bind to "BINDS #8:" which shows the binding values:

value="test_string_0.8433509446104999"
value=0
value=

Timestamp is in hex format. You will to convert that yourself to find the value.

http://wiki.oracle.com/page/Structure+of+an+Extended+SQL+Trace+file

Comments (0)