Re: performance issue after upgrade to oracle 11.2.0.1 linux 32 bit.

From: lsllcm <lsllcm_at_gmail.com>
Date: Sun, 8 Nov 2009 08:15:57 -0800 (PST)
Message-ID: <eada64ab-56d7-4472-85fe-60de18ec2f2e_at_z3g2000prd.googlegroups.com>



On Nov 8, 9:36 pm, Charles Hooper <hooperc2..._at_yahoo.com> wrote:
> On Nov 7, 9:13 am, lsllcm <lsl..._at_gmail.com> wrote:
>
> > Thanks Charles and Randolf for your comments:
>
> Thanks for running all of the test cases.  Many of the plans produced
> are identical, but none show the same plan as you posted for 11.1.0.6
> and 11.2.0.1.
>
> > Below are test cases and results.
>
> > ------------------------case
> > 1------------------------------------------------
> > 1. Use hint /*+ index(SD SETDETAILS_SETID_IX) */
>
> > Result: the result is same as no index hint
>
> It appears that the optimizer was originally using the
> SETDETAILS_PID_IX index based on your first post in this thread, so it
> does appear that the index hint did actually change the plan when
> using your original OPTIMIZER_MODE, OPTIMIZER_INDEX_COST_ADJ and
> OPTIMIZER_INDEX_CACHING parameter settings.
>
> (snip)
>
> > SQL> exec :efd:='2008-12-04 23:59:59';
> > PL/SQL procedure successfully completed.
> > Elapsed: 00:00:00.37
>
> > SQL> rem exec :p1:='254413'
> > SQL> exec :p1:='SET07'
> > PL/SQL procedure successfully completed.
> > Elapsed: 00:00:00.03
>
> > SQL> exec :p2:='Contractor'
> > PL/SQL procedure successfully completed.
> > Elapsed: 00:00:00.18
>
> It seems a little odd that some of these commands to set bind variable
> values requires 370ms - about 1/2 as long as it takes to actually
> execute the SQL statement with OPTIMIZER_MODE set to ALL_ROWS.  I am
> not sure if there is significance to this observation, or not.
>
> (snip)
>
>
>
>
>
> > 6------------------------------------------------
> > 6. If query is expected to retrieve 100,000 rows, but the application
> > front-end will ONLY read just the first 100 rows and then throw away
> > the rest of the query results without bother fetching the remaining
> > rows.
> > [lsllcm] There are many queries like the case in our environment. So
> > we use FIRST_ROWS_100. I will test different queries in both
> > FIRST_ROWS_100 and ALL_ROWS in 10g db and see difference.
>
> > ------------------------item
> > 7------------------------------------------------
> > Is it a special case that no rows are returned due to some of the
> > bind
> > values used? How many rows does this kind of statement return
> > typically?
>
> > [lsllcm] The data in table SETDETAILS is skew, most of them have less
> > than 100 rows returned
> > based on SETDETAILS_SETID_IX. 10 of them have from 10,000 - 40,000
> > rows returned.
>
> Skewed data and bind variables may lead to problems with the re-use of
> plans, especially if histograms are present.  Oracle 11.2.0.1 (with
> OPTIMIZER_MODE = ALL_ROWS) might be trying to build a "safer" plan
> which will work reasonably well for 10 or 40,000 rows, while 11.1.0.6
> and 10.2.0.4 appear to be relying on a short-circuit in the plan which
> required only 3 logical IOs.  Any idea how the plan produced on the
> older releases of Oracle might have handled the situations where the
> plan returned 40,000 rows?  In other words, while the one case you
> have identified with returning 0 rows executes quickly, the case where
> 40,000 rows are returned might execute much slower than the 11.2.0.1
> execution.
>
> > I use below command to gather statistics.
>
> > exec dbms_stats.gather_schema_stats
> > ('TEST',estimate_percent=>100,cascade=> TRUE);
>
> OK, the above collects table and index statistics, but I am not sure
> if that will collect the statistics on the hidden columns (Randolf or
> Jonathan should be able to answer this question).
>
> > Below are histogram of SYS_NC00017$
>
> What is the purpose of this index?  This is the same index that I
> mentioned previously that showed a strange IO cost in the 10053 trace
> file:
> cost_io
> 179769313486231570814527423731704356798070567525844996598917476803157260780­­
> 028538760589558632766878171540458953514382464234321326889464182768467546703­­
> 537516986049910576551282076245490090389328944075868508455133942304583236903­­
> 222948165808559332123348274797826204144723168738177180919299881250404026184­­
> 124858368.00
>
>
>
> > ------------------------item
> > 8------------------------------------------------
> > [lsllcm] The reason to set "_optimizer_cost_based_transformation is to
> > check if
> > the issue is related to the setting. Now I have set it back to
> > default.
>
> OK, so you temporarily set _optimizer_cost_based_transformation to
> false to check for changes in performance, and have returned the
> parameter to its original value.  I might be remembering incorrectly,
> but I believe that there was a bug in 10.2.0.4, and the work-around
> for the bug required this hidden parameter to be set to false.  That
> might explain why you saw that parameter set to false in 10.2.0.4.
>
> > ------------------------item
> > 9------------------------------------------------
> > 9. You might try collecting system statistics during a busy time
> > period.
> > To collect the system statistics with a 60 minute monitoring period,
> > enter the following in SQL*Plus (the SQL*Plus command prompt will
> > return immediately):
> > EXEC DBMS_STATS.GATHER_SYSTEM_STATS('interval',interval=>60)
>
> > [lsllcm] I did not gather system statistics, and I check again
> > scheduled job, no job
> > gather system staitstics.
>
> There is no automated job for *system* (CPU) statistics gathering -
> the DBA must tell Oracle when to collect the statistics using
> DBMS_STATS.GATHER_SYSTEM_STATS.
> From:http://download.oracle.com/docs/cd/E11882_01/server.112/e10821/stats....
> "System statistics describe the system's hardware characteristics,
> such as I/O and CPU performance and utilization, to the query
> optimizer. When choosing an execution plan, the optimizer estimates
> the I/O and CPU resources required for each query. System statistics
> enable the query optimizer to more accurately estimate I/O and CPU
> costs, enabling the query optimizer to choose a better execution
> plan."
>
> Jonathan has also written several articles on the topic, here are a
> couple of those articles:http://jonathanlewis.wordpress.com/2007/04/30/system-statistics/http://jonathanlewis.wordpress.com/2007/05/20/system-stats-strategy/http://jonathanlewis.wordpress.com/2007/10/17/system-statistics-3/
>
> > 10------------------------------------------------
> > 10. As you suggested, I change the optimizer setting into default as
> > combination ALL_ROWS + OICA (100) + OIC (0) in test environment. The
> > result is
> > system looks like to become stable. Even if the query does not choose
> > best
> > execution plan, it chooses not worst execution plan. Like the test
> > case above,
> > it has 3 consistent reads in 10g db (it should be best execution
> > plan). In 11g
> > (ALL_ROWS), it has 3656 consistent reads (it is not best, but it is
> > not worst
> > too). In 11g (FIRST_ROWS_100), it has 2891740  consistent gets(like
> > worst one).
>
> It is good that you found a suitable plan, which might be suitable if
> 0 rows, 10 rows, or 40,000 rows are returned.
>
> Charles Hooper
> IT Manager/Oracle DBA
> K&M Machine-Fabricating, Inc.- Hide quoted text -
>
> - Show quoted text -

Thanks Charles and Randolf, I learned a lot about optimizer from this thread.

------------------------case
1------------------------------------------------
1. Use hint /*+ index(SD SETDETAILS_SETID_IX) */

Result: yes, the execution plan is different and use different index. I did not check it carefully.

------------------------item
2------------------------------------------------
Below are histogram of SYS_NC00017$

Yes, SYS_NC00017$ is function index column UPPER("SD"."SET_ID") in index SETDETAILS_SET_IX
It showed a strange IO cost in the 10053 trace file: cost_io

179769313486231570814527423731704356798070567525844996598917476803157260780--
028538760589558632766878171540458953514382464234321326889464182768467546703--
537516986049910576551282076245490090389328944075868508455133942304583236903--
222948165808559332123348274797826204144723168738177180919299881250404026184--
124858368.00
------------------------item
3------------------------------------------------
Below sql still runs slow regardless optimzer mode is FIRST_ROWS_100 and ALL_ROWS

SELECT *

  FROM (SELECT A.SERV_PROV_CODE AS SERV_PROV_CODE,
               A.B1_PER_ID1 AS B1_PER_ID1,
               A.B1_PER_ID2 AS B1_PER_ID2,
               A.B1_PER_ID3 AS B1_PER_ID3,
               A.B1_PER_GROUP,
               A.B1_PER_TYPE,
               A.B1_PER_SUB_TYPE,
               A.B1_PER_CATEGORY,
               A.B1_SPECIAL_TEXT,
               A.B1_CREATED_BY_ACA,
               A.R3_STD_TIME_CLASS_CODE,
               A.B1_STANDARD_TIME,
               A.B1_EVENT_CODE,
               A.B1_REF_ID,
               A.B1_APPL_STATUS,
               A.REC_FUL_NAM,
               A.REC_STATUS,
               A.PROJECT_NBR,
               A.B1_ALT_ID,
               A.B1_TRACKING_NBR,
               A.B1_APPL_STATUS_DATE,
               A.B1_REF_ID1,
               A.B1_REF_ID2,
               A.B1_REF_ID3,
               A.B1_Q_UD1,
               A.B1_Q_UD2,
               A.B1_Q_UD3,
               A.B1_Q_UD4,
               A.APP_STATUS_GROUP_CODE,
               A.B1_MODULE_NAME,
               A.B1_FILE_DD,
               A.REC_DATE,
               A.B1_REPORTED_DATE,
               A.B1_APPL_CLASS,
               A.B1_APP_TYPE_ALIAS,
               A.B1_CREATED_BY,
               A.B1_INITIATED_BY_PRODUCT,
               B.APP_STATUS,
               B.APP_STATUS_DATE,
               B.DISPOSITION,
               B.DISPOSITION_DATE,
               B.TOTAL_FEE,
               B.TOTAL_PAY,
               B.PERCENT_COMPLETE,
               B.BALANCE,
               B.BALANCE_DATE,
               B.HOUSE_COUNT,
               B.BUILDING_COUNT,
               B.PUBLIC_OWNED,
               B.CONST_TYPE_CODE,
               B.ACTION,
               B.GA_AGENCY_CODE,
               B.GA_BUREAU_CODE,
               B.GA_DIVISION_CODE,
               B.GA_OFFICE_CODE,
               B.GA_SECTION_CODE,
               B.GA_GROUP_CODE,
               B.GA_FNAME,
               B.GA_MNAME,
               B.GA_LNAME,
               B.B1_APPL_SUB_STATUS,
               B.B1_SHORT_NOTES,
               B.B1_CLOSED_DATE,
               B.B1_CLOSEDBY,
               B.B1_REPORTED_CHANNEL,
               B.B1_ASGN_DEPT,
               B.B1_ASGN_STAFF,
               B.B1_PRIORITY,
               B.B1_SEVERITY,
               B.B1_ASGN_DATE,
               B.TOTAL_JOB_COST,
               B.B1_CLOSED_DEPT,
               B.B1_COMPLETE_BY,
               B.B1_COMPLETE_DEPT,
               B.B1_COMPLETE_DATE,
               B.B1_SCHEDULED_DATE,
               B.B1_CREATOR_DEPT,
               B.PM_SCHEDULE_SEQ,
               B.B1_EST_PROD_UNITS,
               B.B1_ACTUAL_PROD_UNITS,
               B.B1_EST_COST_PER_UNIT,
               B.B1_COST_PER_UNIT,
               B.B1_EST_JOB_COST,
               B.B1_PROD_UNIT_TYPE,
               B.B1_CREATED_BY AS B1CREATEDBY,
               B.B1_TRACK_START_DATE,
               B.B1_ESTIMATED_DUE_DATE,
               B.B1_IN_POSSESSION_TIME,
               B.C6_ANONYMOUS_FLAG,
               B.C6_REFERENCE_TYPE,
               B.C6_APPEARANCE_DAYOFWEEK,
               B.C6_APPEARANCE_DD,
               B.C6_BOOKING_FLAG,
               B.C6_DFNDT_SIGNATURE_FLAG,
               B.C6_ENFORCE_OFFICER_ID,
               B.C6_ENFORCE_OFFICER_NAME,
               B.C6_INFRACTION_FLAG,
               B.C6_INSPECTOR_ID,
               B.C6_MISDEMEANOR_FLAG,
               B.C6_OFFN_WITNESSED_FLAG,
               B.C6_INSPECTOR_NAME,
               B.C6_ENFORCE_DEPT,
               B.C6_INSPECTOR_DEPT,
               B.APP_STATUS_REASON,
               B.FIRST_ISSUED_DATE,
               B.UNDISTRIBUTED_JOB_COST,
               B.B1_VAL_MULTIPLIER,
               B.B1_VAL_EXTRA_AMT,
               G.EXPIRATION_CODE,
               G.EXPIRATION_STATUS,
               G.EXPIRATION_DATE,
               G.EXPIRATION_INTERVAL,
               G.EXPIRATION_INTERVAL_UNITS,
               G.GRACE_PERIOD_INTERVAL,
               G.GRACE_PERIOD_INTERVAL_UNITS,
               G.PENALTY_INTERVAL,
               G.PENALTY_INTERVAL_UNITS,
               G.NUM_PENALTY_PERIODS,
               G.PENALTY_PERIOD,
               G.RENEWAL_FEE_FUNCTION,
               G.RENEWAL_FEE_CODE,
               G.PENALTY_FEE_FUNCTION,
               G.PENALTY_FEE_CODE,
               G.PAY_PERIOD_GROUP,
               G.UDF1,
               G.UDF2,
               G.UDF3,
               G.UDF4,
               C.B1_WORK_DESC
          FROM B1PERMIT A
          LEFT OUTER JOIN BPERMIT_DETAIL B ON A.SERV_PROV_CODE =
                                              B.SERV_PROV_CODE
                                          AND A.B1_PER_ID1 =
B.B1_PER_ID1
                                          AND A.B1_PER_ID2 =
B.B1_PER_ID2
                                          AND A.B1_PER_ID3 =
B.B1_PER_ID3
          LEFT OUTER JOIN BWORKDES C ON A.SERV_PROV_CODE =
C.SERV_PROV_CODE
                                    AND A.B1_PER_ID1 = C.B1_PER_ID1
                                    AND A.B1_PER_ID2 = C.B1_PER_ID2
                                    AND A.B1_PER_ID3 = C.B1_PER_ID3
          LEFT OUTER JOIN B1_EXPIRATION G ON A.SERV_PROV_CODE =
                                             G.SERV_PROV_CODE
                                         AND A.B1_PER_ID1 =
G.B1_PER_ID1
                                         AND A.B1_PER_ID2 =
G.B1_PER_ID2
                                         AND A.B1_PER_ID3 =
G.B1_PER_ID3,
         B3CONTRA L
         WHERE A.REC_STATUS = 'A'
           AND A.B1_PER_ID3 NOT LIKE '#%'
           AND (A.B1_APPL_CLASS = 'COMPLETE' OR A.B1_APPL_CLASS IS
NULL)
           AND A.SERV_PROV_CODE = L.SERV_PROV_CODE
           AND A.B1_PER_ID1 = L.B1_PER_ID1
           AND A.B1_PER_ID2 = L.B1_PER_ID2
           AND A.B1_PER_ID3 = L.B1_PER_ID3
           AND A.SERV_PROV_CODE = :spc
           AND L.B1_LICENSE_NBR = :p1
           AND L.B1_LICENSE_TYPE = :p2
         ORDER BY A.B1_FILE_DD DESC)

 WHERE ROWNUM < 101
  • in 10g and 11.1.0.6 db The plan as below:
    | Id | Operation | Name | Rows | Bytes | Cost (%CPU)| Time |
    | 0 | SELECT STATEMENT | | 1 | 4157 | 6 (17)| 00:00:01 | |* 1 | COUNT STOPKEY | | | | | | | 2 | VIEW | | 1 | 4157 | 6 (17)| 00:00:01 | |* 3 | SORT ORDER BY STOPKEY | | 1 | 616 | 6 (17)| 00:00:01 | | 4 | NESTED LOOPS OUTER | | 1 | 616 | 5 (0)| 00:00:01 | | 5 | NESTED LOOPS OUTER | | 1 | 447 | 3 (0)| 00:00:01 | | 6 | NESTED LOOPS OUTER | | 1 | 319 | 2 (0)| 00:00:01 | | 7 | NESTED LOOPS | | 1 | 235 | 1 (0)| 00:00:01 | |* 8 | TABLE ACCESS BY INDEX ROWID| B3CONTRA | 1 | 48 | 0 (0)| 00:00:01 | |* 9 | INDEX RANGE SCAN | B3CONTRA_BUS_NAM2_IX | 1 | | 0 (0)| 00:00:01 | |* 10 | TABLE ACCESS BY INDEX ROWID| B1PERMIT | 1 | 187 | 1 (0)| 00:00:01 | |* 11 | INDEX UNIQUE SCAN | B1PERMIT_PK | 1 | | 0 (0)| 00:00:01 | | 12 | TABLE ACCESS BY INDEX ROWID | BWORKDES | 4 | 336 | 1 (0)| 00:00:01 | |* 13 | INDEX UNIQUE SCAN | BWORKDES_PK | 1 | | 0 (0)| 00:00:01 | | 14 | TABLE ACCESS BY INDEX ROWID | BPERMIT_DETAIL | 1 | 128 | 1 (0)| 00:00:01 | |* 15 | INDEX UNIQUE SCAN | BPERMIT_DETAIL_PK | 1 | | 0 (0)| 00:00:01 | | 16 | TABLE ACCESS BY INDEX ROWID | B1_EXPIRATION | 2 | 338 | 2 (0)| 00:00:01 | |* 17 | INDEX RANGE SCAN | B1_EXPIRATION_PK | 1 | | 1 (0)| 00:00:01 |
  • in 11.2.0.1 db The plan as below:
    | Id | Operation | Name | Rows | Bytes | Cost (%CPU)| Time |
    | 0 | SELECT STATEMENT | | 75 | 304K| 246 (1)| 00:00:03 | |* 1 | COUNT STOPKEY | | | | | | | 2 | VIEW | | 75 | 304K| 246 (1)| 00:00:03 | |* 3 | SORT ORDER BY STOPKEY | | 75 | 44025 | 246 (1)| 00:00:03 | | 4 | NESTED LOOPS OUTER | | 75 | 44025 | 245 (0)| 00:00:03 | |* 5 | HASH JOIN RIGHT OUTER | | 75 | 32175 | 96 (2)| 00:00:02 | |* 6 | TABLE ACCESS FULL | B1_EXPIRATION | 52 | 7592 | 3 (0)| 00:00:01 | | 7 | NESTED LOOPS OUTER | | 75 | 21225 | 92 (0)| 00:00:02 | | 8 | NESTED LOOPS | | 75 | 15300 | 6 (0)| 00:00:01 | |* 9 | TABLE ACCESS BY INDEX ROWID| B3CONTRA | 1 | 48 | 4 (0)| 00:00:01 | |* 10 | INDEX RANGE SCAN | B3CONTRA_LIC_NBR1_IX | 2 | | 3 (0)| 00:00:01 | |* 11 | TABLE ACCESS BY INDEX ROWID| B1PERMIT | 1374 | 209K| 2 (0)| 00:00:01 | |* 12 | INDEX UNIQUE SCAN | B1PERMIT_PK | 1 | | 1 (0)| 00:00:01 | | 13 | TABLE ACCESS BY INDEX ROWID | BWORKDES | 1 | 79 | 2 (0)| 00:00:01 | |* 14 | INDEX UNIQUE SCAN | BWORKDES_PK | 1 | | 1 (0)| 00:00:01 | | 15 | TABLE ACCESS BY INDEX ROWID | BPERMIT_DETAIL | 1 | 158 | 2 (0)| 00:00:01 | |* 16 | INDEX UNIQUE SCAN | BPERMIT_DETAIL_PK | 1 | | 1 (0)| 00:00:01 |

Thanks
lsllcm Received on Sun Nov 08 2009 - 10:15:57 CST

Original text of this message