Re: Extreme slowdown of update statement
- From: "Riyaj Shamsudeen" <riyaj.shamsudeen@xxxxxxxxx>
- To: kennaim@xxxxxxxxx
- Date: Mon, 29 Dec 2008 08:51:25 -0600
Hello Vladimir
Recursive depth is 2 in slower plan and 1 in faster plan, obviously
stemming from the fact that slower SQL was executed from a PL/SQL block.
optimizer_mode is ALL_ROWS for calls executed from PL/SQL.
But, plans are exactly the same, optimizer_mode is ALL_ROWS in both
plans and even logical reads are closer. This is suspicious. How did you get
this plan information? If this is from tkprof, did you use explain
parameter? explain will do another explain plan during tkprof and can show
inconsistencies due to changed optimizer environment.
If you still have trace files, can you send them to me, please?
Also, you might want to send optimizer_mode and print those plan lines
here.
alter session set optimizer_mode='ALL_ROWS';
explain plan for
UPDATE....
;
select * from table(dbms_xplan.display(null,'','all'))
alter session set optimizer_mode='FIRST_ROWS';
UPDATE....
;
select * from table(dbms_xplan.display(null,'','all'))
--
Cheers
Riyaj Shamsudeen
Principal DBA,
Ora!nternals - http://www.orainternals.com
Specialists in Performance, Recovery and EBS11i
Blog: http://orainternals.wordpress.com
On Sun, Dec 28, 2008 at 9:54 PM, Kenneth Naim <kennaim@xxxxxxxxx> wrote:
> I ran into this situation a few years back. I don't remember all the
> details
> but the summary is that the while under the scheduler the query got a
> different explain plan than when run by the same user via any other tool
> (sqlplus/toad etc). Our traces showed identical execution plans but when we
> queried some of the v$tables which escape me at the moment we saw that it
> was doing a full scan rather than an index scan. Our solution was adding an
> primary key onto an existing unique index.
> ......
> Ken
>
>
>
>
>
>
>
>
> -----Original Message-----
> From: oracle-l-bounce@xxxxxxxxxxxxx [mailto:oracle-l-bounce@xxxxxxxxxxxxx]
> On Behalf Of Vladimir Barac
> Sent: Sunday, December 28, 2008 2:30 PM
> To: oracle-l@xxxxxxxxxxxxx
> Subject: Extreme slowdown of update statement
>
> Hi, listers
>
> Oracle EE 10.2.0.4 64bit, Linux
>
> We have some update statement (part of PL/SQL procedure) that may run for
> less than a minute if executed from SQL*Plus prompt or may take ~30 minutes
> if executed as a DBMS_SCHEDULER scheduled job. TKPROF output is pasted
> below.
>
> What could be the reason for this behaviour? Is there some "slowdown"
> imposed by DBMS_SCHEDULER?
>
> All insights are welcomed,
> Vladimir Barac
>
>
> ****************************************************************************
> ****
> UPDATE /*+ no_parallel(x) */ ELE_PRODUCT X SET X.FIRST_FOB_PRICE =(SELECT
> MAX(D.UNIT_PRICE) FROM ELEC_PO_ORDER_DETAILS D,ELEC_PO E,(SELECT
> MIN(B.DATE_CREATED) MIN_DATE,MAX(B.DATE_CREATED) MAX_DATE,A.ITEM_NO FROM
> ELEC_PO_ORDER_DETAILS A,ELEC_PO B
> WHERE
> A.COMP_CODE=B.COMP_CODE AND A.PO_NO=B.PO_NO GROUP BY ITEM_NO) C WHERE
> D.COMP_CODE=E.COMP_CODE AND D.PO_NO=E.PO_NO AND E.DATE_CREATED =
> C.MIN_DATE
> AND D.ITEM_NO = X.ITEM_CODE AND C.ITEM_NO = X.ITEM_CODE)
>
> call count cpu elapsed disk query current
> rows
> ------- ------ -------- ---------- ---------- ---------- ----------
> ----------
> Parse 1 0.06 0.07 1 432 0
> 0
> Execute 1 1747.92 1732.64 209 753991 120144
> 54039
> Fetch 0 0.00 0.00 0 0 0
> 0
> ------- ------ -------- ---------- ---------- ---------- ----------
> ----------
> total 2 1747.98 1732.72 210 754423 120144
> 54039
> Misses in library cache during parse: 1
> Optimizer mode: ALL_ROWS
> Parsing user id: 24 (DM_ELEC_MANAGER) (recursive depth: 2)
> Rows Execution Plan
> ------- ---------------------------------------------------
> 0 UPDATE STATEMENT MODE: ALL_ROWS
> 0 UPDATE OF 'ELE_PRODUCT'
> 0 TABLE ACCESS MODE: ANALYZED (FULL) OF 'ELE_PRODUCT' (TABLE)
> 0 SORT (AGGREGATE)
> 0 HASH JOIN
> 0 NESTED LOOPS
> 0 VIEW
> 0 SORT (GROUP BY)
> 0 NESTED LOOPS
> 0 INDEX MODE: ANALYZED (RANGE SCAN) OF
> 'ELEC_PO_ORDER_DETAILS1' (INDEX)
> 0 INDEX MODE: ANALYZED (RANGE SCAN) OF
> 'CUST_ELEC_PO01' (INDEX)
> 0 INDEX MODE: ANALYZED (RANGE SCAN) OF 'ELEC_PO2' (INDEX)
> 0 INDEX MODE: ANALYZED (RANGE SCAN) OF
> 'ELEC_PO_ORDER_DETAILS1' (INDEX)
>
> Elapsed times include waiting on following events:
> Event waited on Times Max. Wait Total
> Waited
> ---------------------------------------- Waited ----------
> ------------
> db file sequential read 209 0.10
> 1.45
> log file switch completion 4 0.09
> 0.18
> log buffer space 5 0.25
> 0.74
>
> ****************************************************************************
> ****
>
>
>
> ****************************************************************************
> ****
> UPDATE /*+ no_parallel(x) */ ELE_PRODUCT X SET X.FIRST_FOB_PRICE =(SELECT
> MAX(D.UNIT_PRICE) FROM ELEC_PO_ORDER_DETAILS D,ELEC_PO E,(SELECT
> MIN(B.DATE_CREATED) MIN_DATE,MAX(B.DATE_CREATED) MAX_DATE,A.ITEM_NO FROM
> ELEC_PO_ORDER_DETAILS A,ELEC_PO B
> WHERE
> A.COMP_CODE=B.COMP_CODE AND A.PO_NO=B.PO_NO GROUP BY ITEM_NO) C WHERE
> D.COMP_CODE=E.COMP_CODE AND D.PO_NO=E.PO_NO AND E.DATE_CREATED =
> C.MIN_DATE
> AND D.ITEM_NO = X.ITEM_CODE AND C.ITEM_NO = X.ITEM_CODE)
>
> call count cpu elapsed disk query current
> rows
> ------- ------ -------- ---------- ---------- ---------- ----------
> ----------
> Parse 1 0.05 0.22 2 432 0
> 0
> Execute 1 28.68 28.62 0 743780 119906
> 54039
> Fetch 0 0.00 0.00 0 0 0
> 0
> ------- ------ -------- ---------- ---------- ---------- ----------
> ----------
> total 2 28.73 28.84 2 744212 119906
> 54039
> Misses in library cache during parse: 1
> Optimizer mode: ALL_ROWS
>
Other related posts:
