Enforcing SQL execution plan
Date: Fri, 2 Sep 2016 01:11:53 +0000
Message-ID: <AF02C941134B1A4AB5F61A726D08DCED2015B3E4_at_USA7109MB012.na.xerox.net>
Hi,
We run a certain job in the Oracle E-Business Suite (EBS) through a concurrent program. The environment information is listed below: DB version - 11.2.0.4
EBS version - 11.5.10.2
OS - Solaris
The statement uses bind variables that are supplied as part of running the concurrent program. As far as I can tell, the statement always produces the following execution plan:
| Id | Operation | Name | Starts | E-Rows |E-Bytes| Cost (%CPU)| E-Time | A-Rows | A-Time | Buffers | --------------------------------------------------------------------------------------------------------------------------------------------------------- | 0 | SELECT STATEMENT | | 17 | | | 12 (100)| | 17 |00:00:00.01 | 145 | | 1 | CONCATENATION | | 17 | | | | | 17 |00:00:00.01 | 145 |...
|* 2 | FILTER | | 17 | | | | | 17 |00:00:00.01 | 145 |
| 3 | NESTED LOOPS | | 17 | 1 | 197 | 6 (0)| 00:00:01 | 17 |00:00:00.01 | 145 |
|* 4 | TABLE ACCESS BY INDEX ROWID | WSH_DELIVERY_DETAILS | 17 | 1 | 184 | 3 (0)| 00:00:01 | 17 |00:00:00.01 | 73 |
|* 5 | INDEX UNIQUE SCAN | WSH_DELIVERY_DETAILS_U1 | 17 | 1 | | 2 (0)| 00:00:01 | 17 |00:00:00.01 | 51 |
|* 6 | TABLE ACCESS BY INDEX ROWID | WSH_DELIVERY_ASSIGNMENTS | 17 | 1 | 13 | 3 (0)| 00:00:01 | 17 |00:00:00.01 | 72 |
|* 7 | INDEX RANGE SCAN | WSH_DELIVERY_ASSIGNMENTS_N3 | 17 | 1 | | 2 (0)| 00:00:01 | 17 |00:00:00.01 | 53 |
|* 8 | FILTER | | 0 | | | | | 0 |00:00:00.01 | 0 |
| 9 | NESTED LOOPS | | 0 | 1 | 197 | 6 (0)| 00:00:01 | 0 |00:00:00.01 | 0 | | 10 | NESTED LOOPS | | 0 | 1 | 197 | 6 (0)| 00:00:01 | 0 |00:00:00.01 | 0 |
|* 11 | TABLE ACCESS BY INDEX ROWID| WSH_DELIVERY_DETAILS | 0 | 1 | 184 | 3 (0)| 00:00:01 | 0 |00:00:00.01 | 0 |
|* 12 | INDEX RANGE SCAN | WSH_DELIVERY_DETAILS_N1 | 0 | 1 | | 3 (0)| 00:00:01 | 0 |00:00:00.01 | 0 |
|* 13 | INDEX RANGE SCAN | WSH_DELIVERY_ASSIGNMENTS_N3 | 0 | 1 | | 2 (0)| 00:00:01 | 0 |00:00:00.01 | 0 |
|* 14 | TABLE ACCESS BY INDEX ROWID | WSH_DELIVERY_ASSIGNMENTS | 0 | 1 | 13 | 3 (0)| 00:00:01 | 0 |00:00:00.01 | 0 |
--------------------------------------------------------------------------------------------------------------------------------------------------------- For the past few weeks, the concurrent program has been intermittently taking time to complete. When traced, one of the "bad" runs produced the following information: call count cpu elapsed disk query current rows ------- ------ -------- ---------- ---------- ---------- ---------- ---------- Parse 1 0.00 0.00 0 0 0 0 Execute 1 0.00 0.00 0 0 0 0 Fetch 1 614.23 11147.25 941317 18000438 0 1 ------- ------ -------- ---------- ---------- ---------- ---------- ---------- total 3 614.23 11147.25 941317 18000438 0 1 Event waited on Times Max. Wait Total Waited ---------------------------------------- Waited ---------- ------------ db file sequential read 941317 1.00 3563.29 Disk file operations I/O 74 0.00 0.00 gc current grant busy 3 0.00 0.00 gc cr grant 2-way 44 0.08 0.09 read by other session 1706610 1.49 6482.34 gc buffer busy acquire 83710 1.00 431.39 latch: cache buffers chains 173199 0.01 9.25
(only the main wait events are shown above)
Rows (1st) Rows (avg) Rows (max) Row Source Operation
---------- ---------- ---------- --------------------------------------------------- 1 1 1 CONCATENATION (cr=18000438 pr=941317 pw=0 time=2557323227 us) 0 0 0 FILTER (cr=0 pr=0 pw=0 time=2 us) 0 0 0 NESTED LOOPS (cr=0 pr=0 pw=0 time=0 us cost=6 size=197 card=1) 0 0 0 TABLE ACCESS BY INDEX ROWID WSH_DELIVERY_DETAILS (cr=0 pr=0 pw=0 time=0 us cost=3 size=184 card=1) 0 0 0 INDEX UNIQUE SCAN WSH_DELIVERY_DETAILS_U1 (cr=0 pr=0 pw=0 time=0 us cost=2 size=0 card=1)(object id 165859) 0 0 0 TABLE ACCESS BY INDEX ROWID WSH_DELIVERY_ASSIGNMENTS (cr=0 pr=0 pw=0 time=0 us cost=3 size=13 card=1) 0 0 0 INDEX RANGE SCAN WSH_DELIVERY_ASSIGNMENTS_N3 (cr=0 pr=0 pw=0 time=0 us cost=2 size=0 card=1)(object id 165871) 1 1 1 FILTER (cr=18000438 pr=941317 pw=0 time=2557323217 us) 1 1 1 NESTED LOOPS (cr=18000438 pr=941317 pw=0 time=2557323212 us cost=6 size=197 card=1) 1 1 1 NESTED LOOPS (cr=18000361 pr=941296 pw=0 time=2557119556 us cost=6 size=197 card=1) 1 1 1 TABLE ACCESS BY INDEX ROWID WSH_DELIVERY_DETAILS (cr=18000336 pr=941295 pw=0 time=2557112429 us cost=3 size=184 card=1) 42599164 42599164 42599164 INDEX RANGE SCAN WSH_DELIVERY_DETAILS_N1 (cr=1798095 pr=99233 pw=0 time=600382285 us cost=3 size=0 card=1)(object id 917318) 1 1 1 INDEX RANGE SCAN WSH_DELIVERY_ASSIGNMENTS_N3 (cr=25 pr=1 pw=0 time=7116 us cost=2 size=0 card=1)(object id 165871) 1 1 1 TABLE ACCESS BY INDEX ROWID WSH_DELIVERY_ASSIGNMENTS (cr=77 pr=21 pw=0 time=203643 us cost=3 size=13 card=1)
It seems that when it runs longer, it scans a lot of rows from index WSH_DELIVERY_DETAILS_N1. This index is defined on a date column and is not very selective.
As part of the troubleshooting exercise, I captured bind variables of the bad run from DBA_HIST_SQLBIND, defined them as variables with appropriate data type and then ran them through SQL*Plus. The problem that I am facing is that from SQL*Plus, by using this technique, it always produces the following plan, regardless of whether I use values from the good run or the bad run:
| Id | Operation | Name | Starts | E-Rows |E-Bytes| Cost (%CPU)| E-Time | A-Rows | A-Time | Buffers | -------------------------------------------------------------------------------------------------------------------------------------------------------- | 0 | SELECT STATEMENT | | 1 | | | 12 (100)| | 0 |00:00:00.01 | 4 | | 1 | CONCATENATION | | 1 | | | | | 0 |00:00:00.01 | 4 |
|* 2 | FILTER | | 1 | | | | | 0 |00:00:00.01 | 0 |
| 3 | NESTED LOOPS | | 0 | 1 | 197 | 6 (0)| 00:00:01 | 0 |00:00:00.01 | 0 |
|* 4 | TABLE ACCESS BY INDEX ROWID| WSH_DELIVERY_DETAILS | 0 | 1 | 184 | 3 (0)| 00:00:01 | 0 |00:00:00.01 | 0 |
|* 5 | INDEX UNIQUE SCAN | WSH_DELIVERY_DETAILS_U1 | 0 | 1 | | 2 (0)| 00:00:01 | 0 |00:00:00.01 | 0 |
|* 6 | TABLE ACCESS BY INDEX ROWID| WSH_DELIVERY_ASSIGNMENTS | 0 | 1 | 13 | 3 (0)| 00:00:01 | 0 |00:00:00.01 | 0 |
|* 7 | INDEX RANGE SCAN | WSH_DELIVERY_ASSIGNMENTS_N3 | 0 | 1 | | 2 (0)| 00:00:01 | 0 |00:00:00.01 | 0 |
|* 8 | FILTER | | 1 | | | | | 0 |00:00:00.01 | 4 |
| 9 | NESTED LOOPS | | 1 | 1 | 197 | 6 (0)| 00:00:01 | 0 |00:00:00.01 | 4 |
|* 10 | TABLE ACCESS BY INDEX ROWID| WSH_DELIVERY_DETAILS | 1 | 1 | 184 | 3 (0)| 00:00:01 | 0 |00:00:00.01 | 4 |
|* 11 | INDEX UNIQUE SCAN | WSH_DELIVERY_DETAILS_U1 | 1 | 1 | | 2 (0)| 00:00:01 | 1 |00:00:00.01 | 3 |
|* 12 | TABLE ACCESS BY INDEX ROWID| WSH_DELIVERY_ASSIGNMENTS | 0 | 1 | 13 | 3 (0)| 00:00:01 | 0 |00:00:00.01 | 0 |
|* 13 | INDEX RANGE SCAN | WSH_DELIVERY_ASSIGNMENTS_N3 | 0 | 1 | | 2 (0)| 00:00:01 | 0 |00:00:00.01 | 0 |
--------------------------------------------------------------------------------------------------------------------------------------------------------
I have tried to capture hints through outline from the bad run and added them as hints to the statement that I am running from SQL*Plus but I am still not able to enforce the "bad" plan. The outline hints are shown below:
/*+
BEGIN_OUTLINE_DATA IGNORE_OPTIM_EMBEDDED_HINTS OPTIMIZER_FEATURES_ENABLE('11.2.0.4') DB_VERSION('11.2.0.4') OPT_PARAM('_b_tree_bitmap_plans' 'false') OPT_PARAM('_fast_full_scan_enabled' 'false') OPT_PARAM('_index_join_enabled' 'false') ALL_ROWS OUTLINE_LEAF(_at_"SEL$1") OUTLINE_LEAF(_at_"SEL$1_1") USE_CONCAT(_at_"SEL$1" 8 OR_PREDICATES(6) PREDICATE_REORDERS((23 22) (24 23) (26 24) (22 26))) OUTLINE_LEAF(_at_"SEL$1_2") OUTLINE(_at_"SEL$1") INDEX_RS_ASC(_at_"SEL$1_1" "WDD"_at_"SEL$1" ("WSH_DELIVERY_DETAILS"."DELIVERY_DETAIL_ID")) INDEX_RS_ASC(_at_"SEL$1_1" "WDA"_at_"SEL$1" ("WSH_DELIVERY_ASSIGNMENTS"."DELIVERY_DETAIL_ID")) INDEX_RS_ASC(_at_"SEL$1_2" "WDD"_at_"SEL$1_2" ("WSH_DELIVERY_DETAILS"."DATE_SCHEDULED")) INDEX(_at_"SEL$1_2" "WDA"_at_"SEL$1_2" ("WSH_DELIVERY_ASSIGNMENTS"."DELIVERY_DETAIL_ID")) LEADING(_at_"SEL$1_1" "WDD"_at_"SEL$1" "WDA"@"SEL$1") LEADING(_at_"SEL$1_2" "WDD"_at_"SEL$1_2" "WDA"@"SEL$1_2") USE_NL(_at_"SEL$1_1" "WDA"_at_"SEL$1") USE_NL(_at_"SEL$1_2" "WDA"_at_"SEL$1_2") NLJ_BATCHING(_at_"SEL$1_2" "WDA"_at_"SEL$1_2") END_OUTLINE_DATA
*/
The SQL statement is also pasted below:
SELECT WDD.SOURCE_LINE_ID, WDD.SOURCE_HEADER_ID, WDD.INVENTORY_ITEM_ID,
WDD.SHIPMENT_PRIORITY_CODE, WDD.SOURCE_CODE SOURCE_CODE, WDD.SOURCE_HEADER_NUMBER SOURCE_HEADER_NUMBER, WDD.ORGANIZATION_ID, WDD.MOVE_ORDER_LINE_ID, WDD.SHIP_FROM_LOCATION_ID, WDD.SHIP_METHOD_CODE, WDD.SHIPMENT_PRIORITY_CODE, WDD.DATE_SCHEDULED, WDD.REQUESTED_QUANTITY, WDD.REQUESTED_QUANTITY_UOM, WDD.PREFERRED_GRADE, WDD.REQUESTED_QUANTITY2, WDD.REQUESTED_QUANTITY_UOM2, WDD.PROJECT_ID, WDD.TASK_ID, WDD.SUBINVENTORY, WDD.SUBINVENTORY, WDD.RELEASED_STATUS, WDD.SHIP_MODEL_COMPLETE_FLAG, WDD.TOP_MODEL_LINE_ID, WDD.SHIP_SET_ID, WDA.DELIVERY_ID, WDD.LAST_UPDATE_DATE
FROM
WSH_DELIVERY_DETAILS WDD, WSH_DELIVERY_ASSIGNMENTS WDA WHERE
WDD.DELIVERY_DETAIL_ID = :B15 AND WDA.DELIVERY_DETAIL_ID = WDD.DELIVERY_DETAIL_ID AND WDD.DATE_SCHEDULED IS NOT NULL AND WDD.DATE_REQUESTED >= NVL(:B14 , WDD.DATE_REQUESTED) AND WDD.DATE_REQUESTED<= NVL(:B13 , WDD.DATE_REQUESTED) AND WDD.DATE_SCHEDULED >= NVL(:B12 , WDD.DATE_SCHEDULED) AND WDD.DATE_SCHEDULED <= NVL(:B11 , WDD.DATE_SCHEDULED) AND NVL(WDD.REQUESTED_QUANTITY,0) > 0 AND WDD.RELEASED_STATUS IN ('R','B', 'X') AND NVL(WDD.SUBINVENTORY, -99) = DECODE(:B10 , NULL, NVL(WDD.SUBINVENTORY, -99), :B10 ) AND NVL(WDD.PROJECT_ID,0) = DECODE(:B9 , 0, NVL(WDD.PROJECT_ID,0), :B9 ) AND NVL(WDD.TASK_ID,0) = DECODE(:B8 , 0, NVL(WDD.TASK_ID,0), :B8 ) AND NVL(WDD.SHIP_SET_ID,0) = DECODE(:B7 , 0, NVL(WDD.SHIP_SET_ID,0), :B7 ) AND NVL(WDD.SHIPMENT_PRIORITY_CODE,-99) = DECODE(:B6 , NULL, NVL(WDD.SHIPMENT_PRIORITY_CODE,-99), :B6 ) AND WDD.ORGANIZATION_ID = NVL(:B5 , WDD.ORGANIZATION_ID) AND WDD.SHIP_FROM_LOCATION_ID = DECODE(:B4 , -1, WDD.SHIP_FROM_LOCATION_ID, :B4 ) AND (( WDA.DELIVERY_ID IS NOT NULL AND ( :B3 <> 'N' OR WDA.DELIVERY_ID = :B2 OR :B1 <> 0 ) ) OR ( WDA.DELIVERY_ID IS NULL AND :B2 = 0 AND :B1 = 0 ) )
How can I enforce the bad execution plan from SQL*Plus? If I am able to enforce it then I already have bind values from that run and I will be able to reproduce the issue.
Thanks,
Amir
-- http://www.freelists.org/webpage/oracle-lReceived on Fri Sep 02 2016 - 03:11:53 CEST