child cursor with bind mismatch, implicit conversion of timestamp to date
- From: anthony Sanchez <anthonycsanchez@xxxxxxxxx>
- To: oracle-l <Oracle-L@xxxxxxxxxxxxx>
- Date: Wed, 5 Mar 2014 11:21:35 -0700
Hi Folks,
I've got a child cursor with nasty performance against a ranged partitioned
table (EMAPP.LP_INTERVALS) by date.
Oracle 11.2.0.3
RHEL 5.9
The application is passing in bind values of type timestamp to filter
against a date column (UTC_INTERVAL_TIME,partition key). Sometimes this
results in an implicit from conversion from timestamp to date to date and
terrible performance. According to the oracle data warehousing guide this
is a construct to avoid. What I find interesting is that it only does the
implicit conversion some of the time and not always.
SELECT INSERT_TIME INSERT_TIME,
UTC_INTERVAL_TIME END_DATE,
LP_VALUE VALUE,
LP_INTERVAL_LENGTH INTERVAL_LENGTH
FROM LP_INTERVALS
WHERE CHANNEL_ID = :1 AND UTC_INTERVAL_TIME > :2 AND UTC_INTERVAL_TIME
<= :3
ORDER BY END_DATE ASC
below you'll see dbms_xplan.display_cursor for both the good and the bad
cursors with peeked_binds enabled. Timestamp values won't display but I
used the handy script to convert hex to timestamp for display -
http://oaktable.net/content/convert-rawhex-timestamp
GOOD cursor:
PLAN_TABLE_OUTPUT
--------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
SQL_ID br5s8sn8hbhtb, child number 1
-------------------------------------
SELECT INSERT_TIME INSERT_TIME,
UTC_INTERVAL_TIME END_DATE, LP_VALUE VALUE,
LP_INTERVAL_LENGTH INTERVAL_LENGTH FROM
LP_INTERVALS WHERE CHANNEL_ID = :1 AND
UTC_INTERVAL_TIME > :2 AND UTC_INTERVAL_TIME <= :3
ORDER BY END_DATE ASC
Plan hash value: 687203500
-----------------------------------------------------------------------------------------------------------------------
| Id | Operation | Name | Rows |
Bytes | Cost (%CPU)| Time | Pstart| Pstop |
-----------------------------------------------------------------------------------------------------------------------
| 0 | SELECT STATEMENT | | |
| 101 (100)| | | |
|* 1 | FILTER | | |
| | | | |
| 2 | PARTITION RANGE ITERATOR | | 1221 |
36630 | 100 (0)| 00:00:02 | KEY | KEY |
| 3 | TABLE ACCESS BY LOCAL INDEX ROWID| LP_INTERVALS | 1221 |
36630 | 100 (0)| 00:00:02 | KEY | KEY |
|* 4 | INDEX RANGE SCAN | PK_LP_INTERVALS | 1221 |
| 11 (0)| 00:00:01 | KEY | KEY |
-----------------------------------------------------------------------------------------------------------------------
PLAN_TABLE_OUTPUT
--------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
Peeked Binds (identified by position):
--------------------------------------
1 - :1 (VARCHAR2(30), CSID=873): '1-3ML6O'
2 - :2 (TIMESTAMP): [Not Printable] (2/26/2014 7:00:00.000000000 AM)
3 - :3 (TIMESTAMP): [Not Printable] (3/26/2014 6:00:00.000000000 AM)
Predicate Information (identified by operation id):
---------------------------------------------------
1 - filter(:2<:3)
4 - access("CHANNEL_ID"=:1 AND "UTC_INTERVAL_TIME">:2 AND
"UTC_INTERVAL_TIME"<=:3)
BAD Cursor (see predicate information section):
PLAN_TABLE_OUTPUT
--------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
SQL_ID br5s8sn8hbhtb, child number 24
--------------------------------------
SELECT INSERT_TIME INSERT_TIME,
UTC_INTERVAL_TIME END_DATE, LP_VALUE VALUE,
LP_INTERVAL_LENGTH INTERVAL_LENGTH FROM
LP_INTERVALS WHERE CHANNEL_ID = :1 AND
UTC_INTERVAL_TIME > :2 AND UTC_INTERVAL_TIME <= :3
ORDER BY END_DATE ASC
Plan hash value: 2873790348
----------------------------------------------------------------------------------------------------------------------
| Id | Operation | Name | Rows |
Bytes | Cost (%CPU)| Time | Pstart| Pstop |
----------------------------------------------------------------------------------------------------------------------
| 0 | SELECT STATEMENT | | |
| 12 (100)| | | |
| 1 | PARTITION RANGE ITERATOR | | 1 |
30 | 11 (0)| 00:00:01 | KEY | 78 |
| 2 | TABLE ACCESS BY LOCAL INDEX ROWID| LP_INTERVALS | 1 |
30 | 11 (0)| 00:00:01 | KEY | 78 |
|* 3 | INDEX RANGE SCAN | PK_LP_INTERVALS | 1 |
| 10 (0)| 00:00:01 | KEY | 78 |
----------------------------------------------------------------------------------------------------------------------
Peeked Binds (identified by position):
PLAN_TABLE_OUTPUT
--------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
--------------------------------------
1 - :1 (VARCHAR2(30), CSID=873): '1-4J5PW'
2 - :2 (TIMESTAMP): [Not Printable] (3/4/2014 7:00:00.000000000 AM)
3 - :3 (TIMESTAMP): [Not Printable] (3/4/2014 11:04:13.000000000 PM)
--interesting that this is the only one with seconds greater than zero.
Predicate Information (identified by operation id):
---------------------------------------------------
3 - access("CHANNEL_ID"=:1 AND "UTC_INTERVAL_TIME">:2)
filter(INTERNAL_FUNCTION("UTC_INTERVAL_TIME")<=:3) ***THIS IS
NASTY***
In v$sql_shared_cursor, cursor 24 is listed as having a bind_mismatch=Y.
The reason column XML states the following that I'm not sure how to
interpret:
*<ChildNode><ChildNumber>24</ChildNumber><ID>34</ID><reason>Rolling
Invalidate Window
Exceeded(2)</reason><size>0x0</size><details>already_processed</details></ChildNode><ChildNode><ChildNumber>24</ChildNumber><ID>34</ID><reason>Rolling
Invalidate Window
Exceeded(3)</reason><size>2x4</size><invalidation_window>1394035130</invalidation_window><ksugctm>1394038111</ksugctm></ChildNode><ChildNode><ChildNumber>24</ChildNumber><ID>40</ID><reason>Bind
mismatch(14)</reason><size>4x4</size><bind_position>2</bind_position><original_oacflg>3</original_oacflg><original_oacscl>9</original_oacscl><new_oacscl>0</new_oacscl></ChildNode>
*
Does anyone know how to interpret the reason xml above? Any ideas as to why
the implicit conversion happens some of the time but not all of the time?
thanks in advance,
Anthony
Other related posts:
