Skip to Main Content
  • Questions
  • Unusual: Bind Values missing in sql trace?

Breadcrumb

Question and Answer

Connor McDonald

Thanks for the question, Khalid.

Asked: December 16, 2021 - 12:57 am UTC

Last updated: January 11, 2022 - 2:48 am UTC

Version: 12.1.0.2

Viewed 1000+ times

You Asked

Product version = 12.1.0.2
Compatible = 11.2.0.4.0
Q1) Please see SQL-Trace snippet for this question:
Query is coming from Informatica, I am just tracing it because V$SQL_MONITOR did not show me the binds either, so I did a full
10046 sql trace for that Informatica session, but I notice all the bind values for the WHERE clause is missing; The full sql-trace has 5994 EXECs and none of the :v[5-7] have the bind values.
Does that mean that the Bind Value passed is NULL?


PARSING IN CURSOR #18446744071524820856 len=186 dep=0 uid=2546 oct=6 lid=2546 tim=37426523713981 hv=4200148307 ad='929ae57c8' sqlid='0nx6ubzx5kbam'
UPDATE KUALI_ADMIN_IICS.CA_ACCOUNT_D SET ACCOUNT_SID = :V1, EFF_END_DT = :V2, CURRENT_IND = :V3, LASTUPD_EW_DTTM = :V4 WHERE FIN_COA_CD = :V5 AND ACCOUNT_NBR = :V6 AND SUB_ACCT_NBR = :V7
END OF STMT
EXEC #18446744071524820856:c=321250,e=321250,p=0,cr=16330,cu=0,mis=1,r=0,dep=0,og=1,plh=761120615,tim=37426523713978
WAIT #18446744071524820856: nam='SQL*Net message to client' ela= 2 driver id=675562835 #bytes=1 p3=0 obj#=-1 tim=37426523716334
WAIT #18446744071524820856: nam='SQL*Net message from client' ela= 7345 driver id=675562835 #bytes=1 p3=0 obj#=-1 tim=37426523723728
BINDS #18446744071524820856:
Bind#0
oacdty=01 mxl=128(45) mxlc=00 mal=00 scl=00 pre=00
oacflg=01 fl2=1000000 frm=01 csi=873 siz=288 off=0
kxsbbbfp=ffffffff7dc79900 bln=128 avl=03 flg=05
value="283"
Bind#1
oacdty=180 mxl=11(11) mxlc=00 mal=00 scl=00 pre=00
oacflg=01 fl2=1000000 frm=00 csi=873 siz=0 off=128
kxsbbbfp=ffffffff7dc79980 bln=11 avl=11 flg=01
value=2021-12-15 16:59:59
Bind#2
oacdty=96 mxl=32(04) mxlc=00 mal=00 scl=00 pre=00
oacflg=01 fl2=1000000 frm=02 csi=2000 siz=0 off=144
kxsbbbfp=ffffffff7dc79990 bln=32 avl=02 flg=01
value=0 4e
Bind#3
oacdty=180 mxl=11(11) mxlc=00 mal=00 scl=00 pre=00
oacflg=01 fl2=1000000 frm=00 csi=873 siz=0 off=176
kxsbbbfp=ffffffff7dc799b0 bln=11 avl=11 flg=01
value=2021-12-15 17:00:00
Bind#4
oacdty=01 mxl=32(04) mxlc=00 mal=00 scl=00 pre=00
oacflg=01 fl2=1000000 frm=02 csi=2000 siz=0 off=192
kxsbbbfp=ffffffff7dc799c0 bln=32 avl=00 flg=01
Bind#5
oacdty=01 mxl=32(14) mxlc=00 mal=00 scl=00 pre=00
oacflg=01 fl2=1000000 frm=02 csi=2000 siz=0 off=224
kxsbbbfp=ffffffff7dc799e0 bln=32 avl=00 flg=01
Bind#6
oacdty=01 mxl=32(10) mxlc=00 mal=00 scl=00 pre=00
oacflg=01 fl2=1000000 frm=02 csi=2000 siz=0 off=256
kxsbbbfp=ffffffff7dc79a00 bln=32 avl=00 flg=01

Q2) I did a tkprof with an explain on the above, and you will see from the execution plan that the Index 'CA_ACCOUNT_D02' which has an index on :v5, :v6, :v7 above was used:
--> Q2.1) Is this the real plan?
--> Q2.2) If so, where did it get the bind values from?

-- tkprof output
TKPROF: Release 12.1.0.2.0 - Development on Wed Dec 15 19:21:15 2021

Copyright (c) 1982, 2014, Oracle and/or its affiliates. All rights reserved.

Trace file: wq102_ora_21067.trc
Sort options: exeela fchela
********************************************************************************
count = number of times OCI procedure was executed
cpu = cpu time in seconds executing
elapsed = elapsed time in seconds executing
disk = number of physical reads of buffers from disk
query = number of buffers gotten for consistent read
current = number of buffers gotten in current mode (usually for update)
rows = number of rows processed by the fetch or execute call
********************************************************************************

SQL ID: 0nx6ubzx5kbam Plan Hash: 761120615

UPDATE KUALI_ADMIN_IICS.CA_ACCOUNT_D SET ACCOUNT_SID = :V1, EFF_END_DT = :V2,
CURRENT_IND = :V3, LASTUPD_EW_DTTM = :V4
WHERE
FIN_COA_CD = :V5 AND ACCOUNT_NBR = :V6 AND SUB_ACCT_NBR = :V7


call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 0 0.00 0.00 0 0 0 0
Execute 5994 2196.21 2196.29 0 97877528 0 0
Fetch 0 0.00 0.00 0 0 0 0
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 5994 2196.21 2196.29 0 97877528 0 0

Misses in library cache during parse: 0
Misses in library cache during execute: 1
Optimizer mode: ALL_ROWS
Parsing user id: 2546 (KUALI_ADMIN_IICS)

Rows Execution Plan
------- ---------------------------------------------------
0 UPDATE STATEMENT MODE: ALL_ROWS
0 UPDATE OF 'CA_ACCOUNT_D'
0 INDEX MODE: ANALYZED (RANGE SCAN) OF 'CA_ACCOUNT_D02' (INDEX)



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



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

OVERALL TOTALS FOR ALL NON-RECURSIVE STATEMENTS

call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 0 0.00 0.00 0 0 0 0
Execute 5994 2196.21 2196.29 0 97877528 0 0
Fetch 0 0.00 0.00 0 0 0 0
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 5994 2196.21 2196.29 0 97877528 0 0

Misses in library cache during parse: 0
Misses in library cache during execute: 1

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


OVERALL TOTALS FOR ALL RECURSIVE STATEMENTS

call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 0 0.00 0.00 0 0 0 0
Execute 0 0.00 0.00 0 0 0 0
Fetch 0 0.00 0.00 0 0 0 0
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 0 0.00 0.00 0 0 0 0

Misses in library cache during parse: 0

1 user SQL statements in session.
0 internal SQL statements in session.
1 SQL statements in session.
1 statement EXPLAINed in this session.
********************************************************************************
Trace file: wq102_ora_21067.trc
Trace file compatibility: 11.1.0.7
Sort options: exeela fchela
1 session in tracefile.
1 user SQL statements in trace file.
0 internal SQL statements in trace file.
1 SQL statements in trace file.
1 unique SQL statements in trace file.
1 SQL statements EXPLAINed using schema:
KR.prof$plan_table
Default table was used.
Table was created.
Table was dropped.
220206 lines in trace file.
2223 elapsed seconds in trace file.

Q3) Out of the 2223 elapsed seconds in trace file above, 2196.21 was consumed in the EXEC of the above query: And a lot of them was a huge number of buffer Gets, so if it is using the Index; and the Index is very SELECTIVE (1); where did all that time get spent?

If the trace was not helpful, Can you suggest on how I can drill down further?

Thanks,
-- kr


and Connor said...

Does that mean that the Bind Value passed is NULL?

Correct. For example

SQL> variable v1 number
SQL> variable v2 number
SQL> exec :v1 := 10

PL/SQL procedure successfully completed.

SQL>
SQL> select *
  2  from emp
  3  where deptno >= :v1
  4  and sal= :v2;

no rows selected

PARSING IN CURSOR #2508490100072 len=50 dep=0 uid=107 oct=3 lid=107 tim=1656419137 hv=2144171524 ad='7ffa0d167910' sqlid='1h661gtzwuxh4'
select *
from emp
where deptno >= :v1
and sal= :v2
END OF STMT
PARSE #2508490100072:c=15302,e=14279,p=7,cr=72,cu=0,mis=1,r=0,dep=0,og=1,plh=0,tim=1656419137

BINDS #2508490100072:

 Bind#0
  oacdty=02 mxl=22(22) mxlc=00 mal=00 scl=00 pre=00
  oacflg=03 fl2=1000000 frm=00 csi=00 siz=48 off=0
  kxsbbbfp=0db1e688  bln=22  avl=02  flg=05
  value=10
 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=24
  kxsbbbfp=0db1e6a0  bln=22  avl=00  flg=01



Rating

  (1 rating)

Is this answer out of date? If it is, please let us know via a Comment

Comments

Needed you confirmation!

Khalid, December 16, 2021 - 2:26 pm UTC

Thanks much Connor, that helped.
I had a Q3, where I got an explain-plan using tkprof;
The tkprof-plan shows that I am using an Index based on the 3 missing (NULL) bind-values, this cannot be the real-time plan correct?

Connor McDonald
January 11, 2022 - 2:48 am UTC

select *
from my_table
where col = :x

*can* use an index for any value of x, even if x is null, because it is an equality predicate. If wont *find* any rows because (as you said), complete null keys aren't in the index.

Where the index would *not* be used is:

select *
from my_table
where col IS NULL

More to Explore

Administration

Need more information on Administration? Check out the Administrators guide for the Oracle Database