5 Replies Latest reply: May 24, 2010 9:11 AM by 109137 RSS

    Trace files showing bind variables value=""

    109137
      10g on solaris

      Hi All,

      We have an issue with an informatica workflow issuing an update statment to Oracle in trems of performace.

      I switched the tracing on using DBMS_SUPPORT with binds set to TRUE. It has captured the trace files accordingly against a controlled set of data. Twot trace files were produced.

      The first trace files shows the SELECT statment being issues that identifies the records that will be updated.

      The 2nd trace file shows the actual UPDATE statment being issued as a PL/SQL loop to do the update.

      There were 20 records that the users have rigged to updated and the update statment shows 20 cases where updates took place. All updates took place succesfully after checking the post results. However my issue is why the trace files are showing the bind vaules as being set to ""?..any ideas appreciated!

      an extract of the trace file...
      PARSING IN CURSOR #1 len=123 dep=0 uid=1482 oct=6 lid=1482 tim=994827916280 hv=3649357857 ad='8b5b98f0'
      UPDATE /*+ index(FCT_TASK IDX_FCT_TASK_CASE_SBL_ROW_ID)*/ FCT_TASK SET DWH_LAST_UPD_DT = SYSDATE WHERE CASE_SBL_ROW_ID = :1
      END OF STMT
      PARSE #1:c=10000,e=980,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=1,tim=994827916264
      =====================
      PARSING IN CURSOR #5 len=227 dep=1 uid=0 oct=3 lid=0 tim=994827919231 hv=2190775527 ad='8e622670'
      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 #5:c=0,e=1310,p=0,cr=0,cu=0,mis=1,r=0,dep=1,og=1,tim=994827919223
      BINDS #5:
      bind 0: dty=2 mxl=22(22) mal=00 scl=00 pre=00 oacflg=00 oacfl2=0001 size=24 offset=0
      bfp=ffffffff7c058d98 bln=22 avl=04 flg=05
      value=425212
      EXEC #5:c=10000,e=9476,p=0,cr=0,cu=0,mis=1,r=0,dep=1,og=4,tim=994827928883
      FETCH #5:c=0,e=104,p=0,cr=1,cu=0,mis=0,r=0,dep=1,og=4,tim=994827929051
      STAT #5 id=1 cnt=0 pid=0 pos=1 obj=0 op='SORT ORDER BY (cr=1 pr=0 pw=0 time=172 us)'
      STAT #5 id=2 cnt=0 pid=1 pos=1 obj=0 op='NESTED LOOPS (cr=1 pr=0 pw=0 time=110 us)'
      STAT #5 id=3 cnt=0 pid=2 pos=1 obj=0 op='NESTED LOOPS (cr=1 pr=0 pw=0 time=105 us)'
      STAT #5 id=4 cnt=0 pid=3 pos=1 obj=79 op='TABLE ACCESS BY INDEX ROWID TRIGGER$ (cr=1 pr=0 pw=0 time=103 us)'
      STAT #5 id=5 cnt=0 pid=4 pos=1 obj=123 op='INDEX RANGE SCAN I_TRIGGER1 (cr=1 pr=0 pw=0 time=78 us)'
      STAT #5 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 #5 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 #5 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 #5 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 #1:
      bind 0: dty=1 mxl=32(30) mal=00 scl=00 pre=00 oacflg=01 oacfl2=800000 size=32 offset=0
      bfp=ffffffff7c17b0a0 bln=32 avl=04 flg=05
      value=""
      EXEC #1:c=8390000,e=8740989,p=55593,cr=55610,cu=3,mis=1,r=1,dep=0,og=1,tim=994836657483
      BINDS #1:
      bind 0: dty=1 mxl=32(30) mal=00 scl=00 pre=00 oacflg=01 oacfl2=800000 size=32 offset=0
      bfp=ffffffff7c17b0a0 bln=32 avl=04 flg=05
      value=""
      EXEC #1:c=7980000,e=7962369,p=55591,cr=55608,cu=1,mis=0,r=1,dep=0,og=1,tim=994844621479
      BINDS #1:
      bind 0: dty=1 mxl=32(30) mal=00 scl=00 pre=00 oacflg=01 oacfl2=800000 size=32 offset=0
      bfp=ffffffff7c17b0a0 bln=32 avl=04 flg=05
      value=""


      ect ect ect...



      Regards
      Satnam
        • 1. Re: Trace files showing bind variables value=""
          Charles Hooper
          BINDS #1:
          bind 0: dty=1 mxl=32(30) mal=00 scl=00 pre=00 oacflg=01 oacfl2=800000 size=32 offset=0
          bfp=ffffffff7c17b0a0 bln=32 avl=04 flg=05
          value=""
          "dty=1" indicates that the datatype is either VARCHAR or NVARCHAR. Like timestamp data types, blobs data types, and various others, bind variables defined as NVARCHAR will not have their values dumped to a 10046 trace file. I suspect that the :1 bind variable is being passed in as a NVARCHAR2.

          Charles Hooper
          Co-author of "Expert Oracle Practices: Oracle Database Administration from the Oak Table"
          http://hoopercharles.wordpress.com/
          IT Manager/Oracle DBA
          K&M Machine-Fabricating, Inc.
          • 2. Re: Trace files showing bind variables value=""
            109137
            Nice 1 :-)

            Much appreciated!

            Satnam
            • 3. Re: Trace files showing bind variables value=""
              109137
              Having investigated on the comment of NVARCHAR2 not allowing bind variables to be displayed in the trace file... I checked the datatype of the table/column being used in the index and its is defined as VARCHAR2(15)... ? so Im still not sure as to why we are still getting this.. could it be to do with the clinet application and the way in which it passes the bind vlaues to the oracle update statment?

              any ideas appreciated?

              regards
              Satnam
              • 4. Re: Trace files showing bind variables value=""
                Charles Hooper
                spliffer wrote:
                Having investigated on the comment of NVARCHAR2 not allowing bind variables to be displayed in the trace file... I checked the datatype of the table/column being used in the index and its is defined as VARCHAR2(15)... ? so Im still not sure as to why we are still getting this.. could it be to do with the clinet application and the way in which it passes the bind vlaues to the oracle update statment?

                any ideas appreciated?

                regards
                Satnam
                Here is a very brief demonstration.

                The script:
                VARIABLE V1 VARCHAR2
                VARIABLE V2 NVARCHAR2
                 
                EXEC :V1:='A'
                EXEC :V2:='A'
                 
                ALTER SESSION SET TRACEFILE_IDENTIFIER = 'FIND_ME';
                ALTER SESSION SET EVENTS '10046 TRACE NAME CONTEXT FOREVER, LEVEL 12';
                 
                SELECT
                  *
                FROM
                  (SELECT
                    ROWNUM COUNTER,
                    CHR(MOD(ROWNUM-1,26)+65) CHARACTER
                  FROM
                    DUAL
                  CONNECT BY
                    LEVEL<=100)
                WHERE
                  CHARACTER= :V1;
                 
                SELECT
                  *
                FROM
                  (SELECT
                    ROWNUM COUNTER,
                    CHR(MOD(ROWNUM-1,26)+65) CHARACTER
                  FROM
                    DUAL
                  CONNECT BY
                    LEVEL<=100)
                WHERE
                  CHARACTER= :V2;
                 
                SELECT SYSDATE FROM DUAL;
                 
                ALTER SESSION SET EVENTS '10046 TRACE NAME CONTEXT OFF';
                In the script we have two bind variables defined, the first a VARCHAR2 and the second a NVARCHAR2. The output of the script looks like this in both cases:
                   COUNTER C
                ---------- -
                         1 A
                        27 A
                        53 A
                        79 A
                The 10046 trace file looks like this:
                ...
                PARSING IN CURSOR #3 len=152 dep=0 uid=31 oct=3 lid=31 tim=2874162497 hv=2898495116 ad='a5259590'
                SELECT
                  *
                FROM
                  (SELECT
                    ROWNUM COUNTER,
                    CHR(MOD(ROWNUM-1,26)+65) CHARACTER
                  FROM
                    DUAL
                  CONNECT BY
                    LEVEL<=100)
                WHERE
                  CHARACTER= :V1
                END OF STMT
                PARSE #3:c=0,e=128,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,tim=2874162493
                BINDS #3:
                kkscoacd
                 Bind#0
                  oacdty=01 mxl=32(01) mxlc=00 mal=00 scl=00 pre=00
                  oacflg=03 fl2=1000000 frm=01 csi=178 siz=32 off=0
                  kxsbbbfp=0f176c88  bln=32  avl=01  flg=05
                  value="A"
                EXEC #3:c=0,e=498,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,tim=2874163947
                WAIT #3: nam='SQL*Net message to client' ela= 3 driver id=1413697536 #bytes=1 p3=0 obj#=10192 tim=2874164058
                FETCH #3:c=0,e=68,p=0,cr=0,cu=0,mis=0,r=1,dep=0,og=1,tim=2874164215
                WAIT #3: nam='SQL*Net message from client' ela= 299 driver id=1413697536 #bytes=1 p3=0 obj#=10192 tim=2874164657
                WAIT #3: nam='SQL*Net message to client' ela= 2 driver id=1413697536 #bytes=1 p3=0 obj#=10192 tim=2874164903
                FETCH #3:c=15625,e=359,p=0,cr=0,cu=0,mis=0,r=3,dep=0,og=1,tim=2874165155
                WAIT #3: nam='SQL*Net message from client' ela= 1162 driver id=1413697536 #bytes=1 p3=0 obj#=10192 tim=2874166774
                STAT #3 id=1 cnt=4 pid=0 pos=1 obj=0 op='VIEW  (cr=0 pr=0 pw=0 time=76 us)'
                STAT #3 id=2 cnt=100 pid=1 pos=1 obj=0 op='COUNT  (cr=0 pr=0 pw=0 time=50 us)'
                STAT #3 id=3 cnt=100 pid=2 pos=1 obj=0 op='CONNECT BY WITHOUT FILTERING (cr=0 pr=0 pw=0 time=47 us)'
                STAT #3 id=4 cnt=1 pid=3 pos=1 obj=0 op='FAST DUAL  (cr=0 pr=0 pw=0 time=4 us)'
                WAIT #0: nam='SQL*Net message to client' ela= 3 driver id=1413697536 #bytes=1 p3=0 obj#=10192 tim=2874167438
                WAIT #0: nam='SQL*Net message from client' ela= 3939 driver id=1413697536 #bytes=1 p3=0 obj#=10192 tim=2874171452
                =====================
                PARSING IN CURSOR #2 len=152 dep=0 uid=31 oct=3 lid=31 tim=2874171761 hv=2346424803 ad='a597e190'
                SELECT
                  *
                FROM
                  (SELECT
                    ROWNUM COUNTER,
                    CHR(MOD(ROWNUM-1,26)+65) CHARACTER
                  FROM
                    DUAL
                  CONNECT BY
                    LEVEL<=100)
                WHERE
                  CHARACTER= :V2
                END OF STMT
                PARSE #2:c=0,e=155,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,tim=2874171757
                BINDS #2:
                kkscoacd
                 Bind#0
                  oacdty=01 mxl=32(02) mxlc=01 mal=00 scl=00 pre=00
                  oacflg=03 fl2=1000010 frm=02 csi=2000 siz=32 off=0
                  kxsbbbfp=0f176c88  bln=32  avl=02  flg=05
                  value=""
                EXEC #2:c=0,e=489,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,tim=2874173190
                WAIT #2: nam='SQL*Net message to client' ela= 3 driver id=1413697536 #bytes=1 p3=0 obj#=10192 tim=2874173300
                FETCH #2:c=0,e=68,p=0,cr=0,cu=0,mis=0,r=1,dep=0,og=1,tim=2874173453
                WAIT #2: nam='SQL*Net message from client' ela= 326 driver id=1413697536 #bytes=1 p3=0 obj#=10192 tim=2874173906
                WAIT #2: nam='SQL*Net message to client' ela= 2 driver id=1413697536 #bytes=1 p3=0 obj#=10192 tim=2874174137
                FETCH #2:c=0,e=334,p=0,cr=0,cu=0,mis=0,r=3,dep=0,og=1,tim=2874174398
                WAIT #2: nam='SQL*Net message from client' ela= 1052 driver id=1413697536 #bytes=1 p3=0 obj#=10192 tim=2874175570
                STAT #2 id=1 cnt=4 pid=0 pos=1 obj=0 op='VIEW  (cr=0 pr=0 pw=0 time=76 us)'
                STAT #2 id=2 cnt=100 pid=1 pos=1 obj=0 op='COUNT  (cr=0 pr=0 pw=0 time=46 us)'
                STAT #2 id=3 cnt=100 pid=2 pos=1 obj=0 op='CONNECT BY WITHOUT FILTERING (cr=0 pr=0 pw=0 time=43 us)'
                STAT #2 id=4 cnt=1 pid=3 pos=1 obj=0 op='FAST DUAL  (cr=0 pr=0 pw=0 time=4 us)'
                WAIT #0: nam='SQL*Net message to client' ela= 1 driver id=1413697536 #bytes=1 p3=0 obj#=10192 tim=2874176119
                WAIT #0: nam='SQL*Net message from client' ela= 998 driver id=1413697536 #bytes=1 p3=0 obj#=10192 tim=2874177197
                ...
                Notice that the value for the bind variable defined as VARCHAR2 printed in the trace file, while the value for the bind variable defined as NVARCHAR2 did not print in the trace file.

                If I had set the STATISTICS_LEVEL to ALL (or used a GATHER_PLAN_STATISTICS hint) I could retrieve the actual execution plan for the above SQL statements like this (if not, replace ALLSTATS LAST with TYPICAL):
                SET PAGESIZE 1000
                SET LINESIZE 160
                 
                SELECT /*+ LEADING(S) */
                  T.PLAN_TABLE_OUTPUT
                FROM
                  (SELECT
                    SQL_ID,
                    CHILD_NUMBER
                  FROM
                    V$SQL
                  WHERE
                    SQL_TEXT LIKE '%  CHARACTER= :V_') S,
                  TABLE(DBMS_XPLAN.DISPLAY_CURSOR(S.SQL_ID,S.CHILD_NUMBER,'ALLSTATS LAST +COST')) T;
                The output of the above looks like this:
                SQL_ID  33wwr3kqc71nc, child number 0
                -------------------------------------
                SELECT   * FROM   (SELECT     ROWNUM COUNTER,     CHR(MOD(ROWNUM-1,26)+65) CHARACTER   FROM
                    DUAL   CONNECT BY     LEVEL<=100) WHERE   CHARACTER= :V1
                 
                Plan hash value: 761049541
                 
                ----------------------------------------------------------------------------------------------------
                | Id  | Operation                      | Name | Starts | E-Rows | Cost (%CPU)| A-Rows |   A-Time   |
                ----------------------------------------------------------------------------------------------------
                |*  1 |  VIEW                          |      |      1 |      1 |     2   (0)|      4 |00:00:00.01 |
                |   2 |   COUNT                        |      |      1 |        |            |    100 |00:00:00.01 |
                |   3 |    CONNECT BY WITHOUT FILTERING|      |      1 |        |            |    100 |00:00:00.01 |
                |   4 |     FAST DUAL                  |      |      1 |      1 |     2   (0)|      1 |00:00:00.01 |
                ----------------------------------------------------------------------------------------------------
                 
                Predicate Information (identified by operation id):
                ---------------------------------------------------
                   1 - filter("CHARACTER"=:V1)
                 
                SQL_ID  7qzd4aq5xr6g3, child number 0
                -------------------------------------
                SELECT   * FROM   (SELECT     ROWNUM COUNTER,     CHR(MOD(ROWNUM-1,26)+65) CHARACTER   FROM
                    DUAL   CONNECT BY     LEVEL<=100) WHERE   CHARACTER= :V2
                 
                Plan hash value: 761049541
                 
                ----------------------------------------------------------------------------------------------------
                | Id  | Operation                      | Name | Starts | E-Rows | Cost (%CPU)| A-Rows |   A-Time   |
                ----------------------------------------------------------------------------------------------------
                |*  1 |  VIEW                          |      |      1 |      1 |     2   (0)|      4 |00:00:00.01 |
                |   2 |   COUNT                        |      |      1 |        |            |    100 |00:00:00.01 |
                |   3 |    CONNECT BY WITHOUT FILTERING|      |      1 |        |            |    100 |00:00:00.01 |
                |   4 |     FAST DUAL                  |      |      1 |      1 |     2   (0)|      1 |00:00:00.01 |
                ----------------------------------------------------------------------------------------------------
                 
                Predicate Information (identified by operation id):
                ---------------------------------------------------
                   1 - filter(SYS_OP_C2C("CHARACTER")=:V2)
                Notice in the Predicate Information section of the second execution plan, a function is applied to the column - that SYS_OP_C2C function will likely prevent a normal (non-function based) index from helping to improve the execution performance.

                To answer your question, it is the client application that must correctly define the bind variable types.

                Charles Hooper
                Co-author of "Expert Oracle Practices: Oracle Database Administration from the Oak Table"
                http://hoopercharles.wordpress.com/
                IT Manager/Oracle DBA
                K&M Machine-Fabricating, Inc.
                • 5. Re: Trace files showing bind variables value=""
                  109137
                  Very thorough explanation and it is the clent application that seems to have a datatype defined as NVARCHAR2 which we have managed to pin down.

                  Once again.. the effort was much appreciated!

                  Regards
                  Satnam