RE: SQL run time changed after DB upgrade but execution plan did not change

From: Mark W. Farnham <mwf_at_rsiz.com>
Date: Fri, 26 Apr 2013 16:43:00 -0400
Message-ID: <048e01ce42be$a52974a0$ef7c5de0$_at_rsiz.com>



How much of T1 was routinely sitting in the sga block buffer cache in 11.1.x?

One possibility is that adaptive direct read of T1's full table scan is putting that into your PGA and actually being read from disk each time. Sometimes that is a good thing.

However IF that is the change and in 11.1.x you routinely had much of T1 in memory and/or delayed block cleanouts of T1 repeatedly force read consistency operations, the symptoms would match what you report. If you prescan T1 into the sga or (fiddle with the params that influence adaptive director read [careful - that's a shotgun, not a bullet]) then you should be able to tell.

You can read in T1 by rowid reference if you nest scanning through dbms_rowid package or indirectly through index range scans.

Or, it could be something else entirely. But I *think* the fact that you still have the same plan limits the possibilities.

(Frits Hoogland has written good stuff about adaptive direct read, btw.)

mwf

-----Original Message-----

From: oracle-l-bounce_at_freelists.org [mailto:oracle-l-bounce_at_freelists.org] On Behalf Of Hameed, Amir
Sent: Friday, April 26, 2013 4:25 PM
To: oracle-l_at_freelists.org
Subject: SQL run time changed after DB upgrade but execution plan did not change

We recently upgraded one of our ERP databases from 11.1.0.7 to 11.2.0.3 on Solaris 10. The following SQL statement, which used to run in a few minutes, is now taking forever to run and is not even finishing (I have fudged the table names and data values for privacy reasons): DECLARE
CURSOR s_cur IS
SELECT * FROM T1 ; TYPE fetch_array IS TABLE OF s_cur%ROWTYPE; s_array fetch_array; BEGIN

  OPEN s_cur;
  LOOP
    FETCH s_cur BULK COLLECT INTO s_array ; --LIMIT 100

    FORALL I IN 1..S_ARRAY.COUNT
   INSERT

        INTO T2
      SELECT 999,
             S_ARRAY(I).SUBINVENTORY_CODE,
             s_array(I).INVENTORY_ITEM_ID,
             (select max(TRANSACTION_DATE)
                from MTL_MATERIAL_TRANSACTIONS MMT
               WHERE MMT.TRANSACTION_TYPE_ID IN (11, 22, 33, 44, 55)
                 AND ORGANIZATION_ID    = 123
                 AND INVENTORY_ITEM_ID  = S_ARRAY(I).INVENTORY_ITEM_ID
                 and SUBINVENTORY_CODE  = s_array(I).SUBINVENTORY_CODE)
        FROM DUAL;

    COMMIT;
    EXIT WHEN s_cur%NOTFOUND;
  END LOOP;
  CLOSE s_cur;
  COMMIT;
END;
/

I have verified that the explain plan of the SELECT statement has NOT changed after the upgrade and is shown below:



| Id  | Operation                    | Name                         | Rows
| Bytes | Cost (%CPU)| Time     |

----------------------------------------------------------------------------
---------------------------------
| 0 | SELECT STATEMENT | | 1 | 29 | 12 (0)| 00:00:01 | | 1 | SORT AGGREGATE | | 1 | 29 | | | |* 2 | TABLE ACCESS BY INDEX ROWID| MTL_MATERIAL_TRANSACTIONS | 1 | 29 | 12 (0)| 00:00:01 | |* 3 | INDEX RANGE SCAN | MTL_MATERIAL_TRANSACTIONS_N1 | 12 | | 4 (0)| 00:00:01 |
----------------------------------------------------------------------------
---------------------------------

Predicate Information (identified by operation id):


   2 - filter("SUBINVENTORY_CODE"=:B1 AND ("MMT"."TRANSACTION_TYPE_ID" OR

              "MMT"."TRANSACTION_TYPE_ID"" OR "MMT"."TRANSACTION_TYPE_ID"3 OR "MMT"."TRANSACTION_TYPE_ID"D
              OR "MMT"."TRANSACTION_TYPE_ID"U))    3 - access("INVENTORY_ITEM_ID"=:B2 AND "ORGANIZATION_ID"3)

However, in 11.1.0.7, it was doing much less IOs than in 11.2.0.3. Below are statistics from 11.1.0.7 when all 1.5 million rows from "T1" table were processed:
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ----------



Parse 1 0.00 0.00 0 0 0 0
Execute 1 67.22 67.20 1280 42104 6500059 1588081
Fetch 0 0.00 0.00 0 0 0 0
------- ------ -------- ---------- ---------- ---------- ----------


total 2 67.22 67.20 1280 42104 6500059 1588081

In 11.2.0.3, the statistics look below when processing 100 rows from "T1": call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ----------



Parse 1 0.00 0.00 0 0 0 0
Execute 1 89.16 106.70 1417957 1634828 311 100
Fetch 0 0.00 0.00 0 0 0 0
------- ------ -------- ---------- ---------- ---------- ----------


total 2 89.16 106.70 1417957 1634828 311 100

I am not sure if this is due to a bug or something else is causing this much IOs.

Thanks,
Amir

--
http://www.freelists.org/webpage/oracle-l


--
http://www.freelists.org/webpage/oracle-l
Received on Fri Apr 26 2013 - 22:43:00 CEST

Original text of this message