Re: Extreme slowdown of update statement
From: Riyaj Shamsudeen <riyaj.shamsudeen_at_gmail.com>
Date: Mon, 29 Dec 2008 08:51:25 -0600
Message-ID: <203315c10812290651l2a7a352pc9733460a07b7af@mail.gmail.com>
Date: Mon, 29 Dec 2008 08:51:25 -0600
Message-ID: <203315c10812290651l2a7a352pc9733460a07b7af@mail.gmail.com>
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_at_gmail.com> wrote:Received on Mon Dec 29 2008 - 08:51:25 CST
> 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_at_freelists.org [mailto:oracle-l-bounce_at_freelists.org]
> On Behalf Of Vladimir Barac
> Sent: Sunday, December 28, 2008 2:30 PM
> To: oracle-l_at_freelists.org
> 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
>
-- http://www.freelists.org/webpage/oracle-l