Coskan’s Approach to Oracle

January 31, 2011

Plan stability through Upgrade to 11G- Building a test case

Filed under: Basics, Plan Stability — coskan @ 6:16 pm

This will be the first post of plan stability through 11G upgrade series.
I initially planned to write about bugfixes as second post but change my mind and add some common steps to find the sqls I need to investigate and build a test case for.
The scripts I use here are mostly modified versions of Kerry Osborne and Tanel Poder, so just to avoid taking time of some of you who already knows this stuff, the only interesting part can be a bit further down in the post. I also did not add sqls problematic sqls yet, I kept them for related posts :)

Before I start, I have some assumptions for this and upcoming posts
I am assuming that you took the actions below on the test system as a DBA who knows what he is doing.

1- you cloned/snapped/duplicated the database from production so data is same
2- if you have a cutdown version of prod then you copied all the stats from production (both system and object stats)
3- you did not overwrite the statistics by gathering new stats after step 1 or 2
4- you have the same parameter settings apart from the version related ones.
5- You have optimizer_features_enable parameter set to the version you upgraded
(this is very important and I got my own invalid DBA exception and set this parameter at system level during my own test and caused tester test on the wrong optimizer environment)

You took the actions above, started the database and testing began then you start to get calls from testing/development groups that some of the tasks are running slower than SLAs for that spesific task
Since you are on testing phase you have time to sort the problems and understand what is the cause of the problem.

First things first, we will start by checking what is going on in terms of plans. Here is how “I” do it. For ease of read I did not put content of the scripts. They are all at the bottom of the post

1-Find/get the sqlid or sqltext for the task from developers.

1a-If developer provide sqlid then I call sqlid.sql- modified version of sqlid from Tanel Poder. This script gives the statistics of cursors in memory.

SQL> @sqlid cp7cg4db39a8z

SQL_ID        HASH_VALUE SQL_TEXT
------------- ---------- ------------------------------------------------------------------------------------------------------------------------------------------------------
cp7cg4db39a8z 1446291743 select from USER.TEST where ID =:1

 CH# PARENT_HANDLE    OBJECT_HANDLE     PLAN_HASH OPT_COST     PARSES   H_PARSES EXECUTIONS    FETCHES ROWS_PROCESSED     CPU_MS     ELA_MS    AVG_ELA       LIOS       PIOS      SORTS USERS_EXECUTING
---- ---------------- ---------------- ---------- -------- ---------- ---------- ---------- ---------- -------------- ---------- ---------- ---------- ---------- ---------- ---------- ---------------
   0 0000000A16BA1338 000000072A73FE20 1026121647        3     117859          3     117858          0         117858    4223100 6820106.35  .57867148  279018595     408403          0               1

1b- If you got the sqltext but not sqlid but the process is reported as still running check with swact.sql script which is calling modified version of Tanel Poders sw.sql for active foreground processes.

Run the sqlid.sql script for the active sql_ids and double check the sqltext

SQL> @swact

    SID USERN STATE   EVENT              SEQ# SEC_IN_STATE         P1         P2         P3 P1TRANSL   SQL_ID         CHN BLCKNG_SID BLCKNG_SID_S BLCKNG_INST
------- ----- ------- ----------------------- ------------ ---------- ---------- ---------- ---------- ------------- ---- ---------- ------------ -----------
    401       WAITING jobq slave wait      32            0          0          0          0                             0            NO HOLDER
    553       WAITING jobq slave wait      32            0          0          0          0                             0            NO HOLDER
    402 COSKA WORKING On CPU / runqueue   145            0 1413697536          1          0            f5cqythck1gfz    0            NOT IN WAIT
    481 COSKA WORKING On CPU / runqueue   271            2          1      51202          1            fuws9wt9d16fq    0            NOT IN WAIT

SQL> @sqlid fuws9wt9d16fq

SQL_ID        HASH_VALUE SQL_TEXT
------------- ---------- ------------------------------------------------------------------------------------------------------------------------------------------------------
fuws9wt9d16fq 1389402582 select count(*) from dba_source,dba_objects

 CH# PARENT_HANDLE    OBJECT_HANDLE     PLAN_HASH OPT_COST     PARSES   H_PARSES EXECUTIONS    FETCHES ROWS_PROCESSED     CPU_MS     ELA_MS    AVG_ELA       LIOS       PIOS      SORTS USERS_EXECUTING
---- ---------------- ---------------- ---------- -------- ---------- ---------- ---------- ---------- -------------- ---------- ---------- ---------- ---------- ---------- ---------- ---------------
   0 00000002A9B90758 00000002A9C55DF8 2265727165 99999999          1          1          1          0              0  18539.182  20075.237  20.075237      32172       3619          1               1

1c- If session is not active and you could not get the sqlid from developer and start searching for the sqlid in v$sqlarea or dba_hist_sqltext

For this I usually use find_sql.sql from Kerry Osborne.

I needed to edit it to just find the sqlid of the given search key to avoid massive screen output for sqls with multiple child cursors


COSKANDBA@WHQAINT> @find_sql
Enter value for sql_text: select count(*) from v$parameter
Enter value for sql_id: %

SQL_ID         CHILD  PLAN_HASH      EXECS         ETIME     AVG_ETIME SQL_TEXT
------------- ------ ---------- ---------- ------------- ------------- -----------------------------------------
89f82uh6x612p      0  322934900          2           .01           .00 select count(*) from v$parameter where na
                                                                       me = 'cpu_count' and   (isdefault = 'FALS
                                                                       E' or ismodified != 'FALSE')
COSKANDBA@WHQAINT> @find_sqlid
Enter value for sql_text: select count(*) from v$parameter

SQL_ID        SQL_TEXT
------------- ----------------------------------------------------------------------------------------------------
89f82uh6x612p select count(*) from v$parameter where name = 'cpu_count' and   (isdefault = 'FALSE' or ismodified !
              = 'FALSE')

If the sql is not active then I use find_sqlid_h which check dba_hist_sqltext
for historic check which can be dramatically slow if your AWR retention is high or number of unique sqls

2-Check the plan changes for this spesific sql

2a-If you have diagnostics pack license then you can use awr to check the historic plans

I use two scripts for getting the plan changes from awr.

awr_plan_changes.sql from Kerry Osborne which uses dba_hist_sqlstats for given sql_id. The good part of this script is that you can see the average elapsed time and
avg logical io. Take average into consideration but know that they are also dangerous and misleading

SQL> @awr_plan_change
Enter value for sql_id: 2h5nub7zqkj5q

   SNAP_ID   NODE BEGIN_INTERVAL_TIME            SQL_ID        PLAN_HASH_VALUE        EXECS    AVG_ETIME        AVG_LIO
---------- ------ ------------------------------ ------------- --------------- ------------ ------------ --------------
     24906      1 15-JAN-11 14.30.49.673         2h5nub7zqkj5q      3435162931            3       60.352       75,163.0
     24936      1 16-JAN-11 05.30.36.765         2h5nub7zqkj5q                            3      135.858       25,870.0
     24954      1 16-JAN-11 14.30.26.315         2h5nub7zqkj5q      3125217954            3       20.494       74,416.7
     25246      1 22-JAN-11 16.30.05.775         2h5nub7zqkj5q      1903048315            4        4.289       73,862.0
     25273      1 23-JAN-11 06.00.55.152         2h5nub7zqkj5q                            3       77.159      160,780.7
     25280      1 23-JAN-11 09.30.03.439         2h5nub7zqkj5q                            3       23.366       73,862.0
     25283      1 23-JAN-11 11.00.06.489         2h5nub7zqkj5q                            3        5.612       73,862.0
     25292      1 23-JAN-11 15.30.15.880         2h5nub7zqkj5q                            1       11.525       73,862.0
     25321      1 24-JAN-11 06.00.02.214         2h5nub7zqkj5q                            7       11.784       73,862.0
     25328      1 24-JAN-11 09.30.10.651         2h5nub7zqkj5q                            3       24.208       73,869.0
     25417      1 26-JAN-11 06.00.31.983         2h5nub7zqkj5q                            7       17.478       74,686.0
     25475      1 27-JAN-11 11.00.55.155         2h5nub7zqkj5q                            3       25.786       74,845.3
     25523      1 28-JAN-11 11.00.35.584         2h5nub7zqkj5q                            3       24.190       74,947.0
     25561      1 29-JAN-11 06.00.55.227         2h5nub7zqkj5q                            7       99.244       74,902.0
     25568      1 29-JAN-11 09.30.08.835         2h5nub7zqkj5q                            3       18.939       74,914.3
     25571      1 29-JAN-11 11.00.12.085         2h5nub7zqkj5q                            3       26.258       74,922.7

16 rows selected.

SQL>

sqlhist.sql which check uses dba_hist_active_sess_history for given sql_id. This does not have sql statistics for the plan_hash_value but it gives information for the sqls
which are not captured for dba_hist_sqlstats.


SQL> @sqlhist 2h5nub7zqkj5q

   SNAP_ID BEGIN_INTERVAL_TIME            SQL_ID          CHILD_NO PLAN_HASH_VALUE
---------- ------------------------------ ------------- ---------- ---------------
     24891 15-JAN-11 06.00.14.552         2h5nub7zqkj5q          0      3125217954   ****
     24906 15-JAN-11 14.30.49.673         2h5nub7zqkj5q          0      3435162931
     24937 16-JAN-11 06.00.38.585         2h5nub7zqkj5q          0
     24954 16-JAN-11 14.30.26.315         2h5nub7zqkj5q          0      3125217954
     25003 17-JAN-11 15.00.01.148         2h5nub7zqkj5q          0      4093460156
     25051 18-JAN-11 15.00.18.035         2h5nub7zqkj5q          1
     25099 19-JAN-11 15.00.44.108         2h5nub7zqkj5q          0
     25147 20-JAN-11 15.00.53.100         2h5nub7zqkj5q          0
     25225 22-JAN-11 06.00.09.902         2h5nub7zqkj5q          0
     25227 22-JAN-11 07.00.14.473         2h5nub7zqkj5q          0
     25230 22-JAN-11 08.30.19.472         2h5nub7zqkj5q          0
     25231 22-JAN-11 09.00.20.496         2h5nub7zqkj5q          0      1903048315
     25244 22-JAN-11 15.30.03.874         2h5nub7zqkj5q          0
     25246 22-JAN-11 16.30.05.775         2h5nub7zqkj5q          0
     25273 23-JAN-11 06.00.55.152         2h5nub7zqkj5q          0
     25280 23-JAN-11 09.30.03.439         2h5nub7zqkj5q          0
     25283 23-JAN-11 11.00.06.489         2h5nub7zqkj5q          0
     25292 23-JAN-11 15.30.15.880         2h5nub7zqkj5q          0
     25321 24-JAN-11 06.00.02.214         2h5nub7zqkj5q          0
     25328 24-JAN-11 09.30.10.651         2h5nub7zqkj5q          0
     25331 24-JAN-11 11.00.14.273         2h5nub7zqkj5q          0
     25369 25-JAN-11 06.00.56.648         2h5nub7zqkj5q          0
     25376 25-JAN-11 09.30.12.066         2h5nub7zqkj5q          0
     25379 25-JAN-11 11.00.15.482         2h5nub7zqkj5q          0
     25388 25-JAN-11 15.30.32.502         2h5nub7zqkj5q          0
     25417 26-JAN-11 06.00.31.983         2h5nub7zqkj5q          0
     25427 26-JAN-11 11.00.47.332         2h5nub7zqkj5q          0
     25436 26-JAN-11 15.30.07.648         2h5nub7zqkj5q          0
     25465 27-JAN-11 06.00.35.469         2h5nub7zqkj5q          0
     25472 27-JAN-11 09.30.51.194         2h5nub7zqkj5q          0
     25475 27-JAN-11 11.00.55.155         2h5nub7zqkj5q          0
     25484 27-JAN-11 15.30.09.941         2h5nub7zqkj5q          0
     25520 28-JAN-11 09.30.31.090         2h5nub7zqkj5q          0
     25523 28-JAN-11 11.00.35.584         2h5nub7zqkj5q          0
     25532 28-JAN-11 15.30.49.332         2h5nub7zqkj5q          0
     25561 29-JAN-11 06.00.55.227         2h5nub7zqkj5q          0
     25568 29-JAN-11 09.30.08.835         2h5nub7zqkj5q          0
     25571 29-JAN-11 11.00.12.085         2h5nub7zqkj5q          0

38 rows selected.

SQL>

When you look carefully you will see why I needed to check dba_hist_active_sess_stats with another script. The first line is not in awr_plan_change which can be misleading!!!!.

2b-If you have statspack configured to be taken at “Level 6″

then you can write scripts on STATS$SQL_PLAN_USAGE table in the similar manner. The difference is that since statspack does not store sql_id you need to use hash_value for instead of sql_id and in addition to this after 10G
You need to use V$SQL.OLD_HASH_VALUE for the given SQL_ID. I may write a version and put here but not this time because I don’t have it configured:(

3- You found out that your plan is changed after upgrade or you could not find that information due to lack of awr data or statspack but you suspect that it is changed. Now is the time to build the test case.

3a-Build the test case :

To create the test case I choose one of the options below
1- Manual: I use this option when I don’t have sqlid but sqltext to generate a case, which is painful if it has binds. Better ask the case from developer

2- build_bind_vars script from Kerry Osborne: Once you have/find the sqlid then you have a perfect option from Kerry Osborne which “nearly” does everything for you
he has two scripts called build_bind_vars and build_bind_vars2 one is using v$sql_bind_capture for the binded value the other one is using other_xml column for peeked binds from v$sql_plan table . Downside of build_bind_vars is that it uses display_raw function of Greg Rahn which means creating a function in the DB because this function is not there by default

SQL> @sqlid 6asfnp4v15rg3

SQL_ID        HASH_VALUE SQL_TEXT
------------- ---------- ------------------------------------------------------------------------------------------------------------------------------------------------------
6asfnp4v15rg3  907206115  SELECT DISTINCT TABLE_1.ID FROM USER_1.TABLE_1 TABLE_1, USER_1.TABLE_2
                         TABLE_2 WHERE TABLE_1.ID = TABLE_2.ID AND TABLE_2.SOURCEID = :1 AND TABLE_1.MARKETID = :2 AND TABLE_1.TYPEID
                         = :3

Elapsed: 00:00:00.01

 CH# PARENT_HANDLE    OBJECT_HANDLE     PLAN_HASH OPT_COST     PARSES   H_PARSES EXECUTIONS    FETCHES ROWS_PROCESSED     CPU_MS     ELA_MS    AVG_ELA       LIOS       PIOS      SORTS USERS_EXECUTING
---- ---------------- ---------------- ---------- -------- ---------- ---------- ---------- ---------- -------------- ---------- ---------- ---------- ---------- ---------- ---------- ---------------
   1 000000082DF6FB88 00000009498BCE50 2222075559        6          2         12          1        130           1295     16.997     69.267    .069267       1562         13          0               0
   4 000000082DF6FB88 000000084D6B6808 2222075559       15          1         10          1        995           9946     55.993    1168.99    1.16899       6497         63          0               0
   6 000000082DF6FB88 00000009F2DB4B98 2222075559        6          2          7          1        504           5039     22.996     188.12     .18812       3877         34          0               0
   7 000000082DF6FB88 00000006D3B821A0 2222075559        7          1         10          1          9             86      6.999     15.825    .015825        151          2          0               0
   8 000000082DF6FB88 00000006EC670138 2222075559       39        144         11        105      33458         334050   1797.724    7692.61 .073262952     262247        999          0               0
  18 000000082DF6FB88 00000008AED02378 1994644346      176        768          3        804     233085        2326441  12999.013 119810.985 .149018638    2624167      12429          0               0

6 rows selected.

Elapsed: 00:00:00.01
SQL> @e5
Enter value for sql_id: 6asfnp4v15rg3
Enter value for child_number: 18

PLAN_TABLE_OUTPUT
-----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
EXPLAINED SQL STATEMENT:
------------------------
 SELECT
DISTINCT TABLE_1.ID FROM USER_1.TABLE_1 TABLE_1, USER_1.TABLE_2
TABLE_2 WHERE TABLE_1.ID = TABLE_2.ID AND
TABLE_2.SOURCEID = :1 AND TABLE_1.MARKETID = :2 AND
TABLE_1.TYPEID = :3

Plan hash value: 1994644346

---------------------------------------------------
| Id  | Operation           | Name                |
---------------------------------------------------
|   0 | SELECT STATEMENT    |                     |
|   1 |  SORT UNIQUE NOSORT |                     |
|   2 |   NESTED LOOPS      |                     |
|   3 |    INDEX RANGE SCAN | IDX_TABLE1_09       |
|   4 |    INDEX UNIQUE SCAN| PK_TABLE_2 |
---------------------------------------------------

Peeked Binds (identified by position):
--------------------------------------

   1 - :1 (NUMBER): 66
   2 - :2 (NUMBER): 1281
   3 - :3 (NUMBER): 125

27 rows selected.

Elapsed: 00:00:00.06

SQL> l
  1* SELECT * FROM table(DBMS_XPLAN.DISPLAY_CURSOR(('&sql_id'),&child_number,'BASIC +PEEKED_BINDS'))

SQL> @build_bind_vars
Enter SQL ID ==> 6asfnp4v15rg3
Enter Child Number ==> 18

variable N1 NUMBER
variable N2 NUMBER
variable N3 NUMBER

begin

:N1 := 66;
:N2 := 1281;
:N3 := 125;

end;

/

select /* test_6asfnp4v15rg3 */ /*+ gather_plan_statistics */ DISTINCT TABLE_1.ID
FROM USER_1.TABLE_1 TABLE_1, USER_1.TABLE_2 TABLE_2
WHERE TABLE_1.ID = TABLE_2.ID
AND TABLE_2.SOURCEID = :N1
AND TABLE_1.MARKETID = :N2
AND TABLE_1.TYPEID = :N3;

As you see build_bind_vars uses actual peeked binds however build_bind_vars2 uses v$sql_bind_capture which maybe misleading due to the bind peeking.

SQL> @build_bind_vars2
Enter SQL ID ==> 6asfnp4v15rg3
Enter Child Number ==> 18

variable N1 NUMBER
variable N2 NUMBER
variable N3 NUMBER

begin

:N1 := 66;
:N2 := 1661;
:N3 := 1;

end;

/

select /* test_6asfnp4v15rg3 */ /*+ gather_plan_statistics */ DISTINCT TABLE_1.ID
FROM USER_1.TABLE_1 TABLE_1, USER_1.TABLE_2 TABLE_2
WHERE TABLE_1.ID = TABLE_2.ID
AND TABLE_2.SOURCEID = :N1
AND TABLE_1.MARKETID = :N2
AND TABLE_1.TYPEID = :N3;

Challenge is that these two script use active cursors in the shared pool. what if you need something which is not in the cache but in history.
To sort this problem I also add one more script called build_bind_vars_h to build test case using dba_hist_* tables and again other_xml column of those tables for peeked binds.
For the example below I will use build_bind_vars_h script because our query is not in memory.


SQL> @sqlid 1m7wy721qytx3

no rows selected

no rows selected

SQL> @sqlhist 1m7wy721qytx3

   SNAP_ID BEGIN_INTERVAL_TIME            SQL_ID          CHILD_NO PLAN_HASH_VALUE
---------- ------------------------------ ------------- ---------- ---------------
     24981 17-JAN-11 04.00.28.416         1m7wy721qytx3          0      2266344041
     24982 17-JAN-11 04.30.32.884         1m7wy721qytx3          0      2266344041
     24987 17-JAN-11 07.00.03.043         1m7wy721qytx3          0      2266344041
     24988 17-JAN-11 07.30.10.114         1m7wy721qytx3          0      2266344041
     25029 18-JAN-11 04.00.07.227         1m7wy721qytx3          0      2266344041
     25030 18-JAN-11 04.30.10.894         1m7wy721qytx3          0      2266344041
     25077 19-JAN-11 04.00.56.483         1m7wy721qytx3          0      3561051786 =>after the upgrade
     25078 19-JAN-11 04.31.00.422         1m7wy721qytx3          0      3561051786

8 rows selected.

SQL> @build_bind_vars_h
Enter SQL ID ==> 1m7wy721qytx3
Enter Plan Hash Value ==> 2266344041

variable B1 NUMBER

begin

:B1 := 14544;

end;

/

select /* test 1m7wy721qytx3 */ /*+gather_plan_statistics*/TABLE_1.TICKERID,
TABLE_1.SOURCEID, NVL (MAX (CLOSETIMESTAMP), MAX (STARTTIMESTAMP)) LASTTIMESTAMP, MAX (CLOSE) KEEP (DENSE_RANK LAST ORDER BY
STARTTIMESTAMP) AS LAST, MAX (CLOSESPREAD) KEEP (DENSE_RANK LAST ORDER BY STARTTIMESTAMP) AS LASTSPREAD, MAX (CLOSEUPFRONT) KEEP (DENSE_RANK
LAST ORDER BY STARTTIMESTAMP) AS LASTUPFRONT FROM USER_1.TABLE_1, USER_1.TABLE_2, USER_1.TABLE_3 WHERE TABLE_1.TICKERID = TABLE_2.TICKERID
AND TABLE_2.MARKETID = TABLE_3.MARKETID AND TABLE_2.MARKETID IN :B1 AND TABLE_1.SOURCEID = TABLE_3.SOURCEID AND DURATION =
NUMTODSINTERVAL (1, 'DAY') AND STARTTIMESTAMP < TRUNC (SYSDATE, 'YEAR') - 1 AND STARTTIMESTAMP > TRUNC (SYSDATE, 'YEAR') - 7 GROUP BY
TABLE_1.TICKERID, TABLE_1.SOURCEID;

Once I have the test content available , I copy the test case content two sql files to ease and generalize my tests.

test.sql sql file with /*+gather_plan_statistics*//*identifier*/ hints+comments added so I can gather the runtime statistics and easily find my sql
Sample test.sql

variable N1 NUMBER

begin
:N1 :=  100;
end;
/

select /*+gather_plan_statistics*/ /*test_0jvvdaw4kxpqw*/*
from T1,T2 where t1.id=t2.id and t1.id&lt;=:N1;

test_e.sql same as test but this time I replace binds with literals and run explain plan for the sql. I put literals because runtime plans can be
different than explain plans for sqls with bind variables.

Sample test_e.sql

explain plan for select /*+gather_plan_statistics*/ /*test_0jvvdaw4kxpqw*/*
from T1,T2 where t1.id=t2.id and t1.id&lt;=100;

4-Testing the test case with different optimizer_features_enable (OFE) settings

There can be couple of major minor releases between the release you are upgrading from and the release you are upgrading to.
For example If you want to upgrade from 10.2.0.4 to 11.2.0.2 and your plans are changed, it may not be because something is changed on 11.2.0.2 because there are 4 base releases between these two which are 10.2.0.5, 11.1.0.6, 11.2.0.7 and 11.2.0.1. Your plan characteristics may actually changed on one of these releases.

To understand which release my problems actually start I need to test the sqls for all the releases, to automate this process
I wrote two simple scripst like below

build_optimizer_features_test.sql : this script accepts base release as parameter and builds a test environment for all releases by generating another sql called
optimizer_features_test.sql which is just a spool file which sets OFE and runs test.sql (the one you created on step 3b) for each OFE from base and till last value
in v$system_fix_control.optimizer_feature_enable column.

Source of the build_optimizer_features_test.sql

undefine base_optimizer_version
set heading off
set feedback off
define optimizer_feature="&amp;base_optimizer_version"
set term off
spool optimizer_features_test.sql
select 'set timing on' from dual;
select 'set echo off' from dual;
--select 'set autotrace traceonly  statistics' from dual;
select 'spool optimizer_features_test_results.log' from dual;
select
'timing start time_for_ofe_'||optimizer_feature_enable||chr(10)||'set echo on'||chr(10)||'alter session set optimizer_features_enable='''||optimizer_feature_enable||''';'
||chr(10)||'set echo off'||chr(10)||'set term off'||chr(10)
||'@test.sql'||chr(10)||'/'||chr(10)||'set term on'
||chr(10)||'timing stop  time_for_ofe_'||optimizer_feature_enable||chr(10)
||chr(10)||'select * from table(dbms_xplan.display_cursor(null,null,''ALLSTATS LAST''));'||chr(10)
from
(select distinct optimizer_feature_enable from v$system_fix_control
where
to_number(replace(optimizer_feature_enable,'.',''))&gt;=to_number(replace('&amp;optimizer_feature','.',''))
order by to_number(replace(optimizer_feature_enable,'.','')) desc );
select 'set echo off' from dual;
select 'set feedback on' from dual;
select 'set heading on' from dual;
select 'set timing off' from dual;
select 'spool off' from dual;
--select 'set autotrace off' from dual;
spool off
set term on
set heading on
set feedback on

and output from this sql is optimizer_features_test.sql which is like below for base version is 11.1.0.7 and database is running with 11.2.0.1 binary

set timing on

set echo off

spool optimizer_features_test_results.log

timing start time_for_ofe_11.2.0.1
set echo on
alter session set optimizer_features_enable='11.2.0.1';
set echo off
set term off
@test.sql
/
set term on
timing stop  time_for_ofe_11.2.0.1

select * from table(dbms_xplan.display_cursor(null,null,'ALLSTATS LAST'));

timing start time_for_ofe_11.1.0.7
set echo on
alter session set optimizer_features_enable='11.1.0.7';
set echo off
set term off
@test.sql
/
set term on
timing stop  time_for_ofe_11.1.0.7

select * from table(dbms_xplan.display_cursor(null,null,'ALLSTATS LAST'));

set timing off

spool off

For this example I want to see if my plan is changing behaviour when I upgrade from 10.2.0.4 to 11.2.0.1


SQL> ------------------------------
SQL> ----- BUILD THE TEST CASE ----
SQL> ------------------------------
SQL> @build_optimizer_features_test
Enter value for base_optimizer_version: 10.2.0.4
SQL> ------------------------------
SQL> ----- TEST THE TEST CASE -----
SQL> ------------------------------
SQL> @optimizer_features_test
SQL> alter session set optimizer_features_enable='11.2.0.1';

Session altered.

Elapsed: 00:00:00.02
SQL> set echo off
timing for: time_for_ofe_11.2.0.1
Elapsed: 00:00:00.03

PLAN_TABLE_OUTPUT
-----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
SQL_ID  1hs7jn4tshzqa, child number 0
-------------------------------------
select /*+gather_plan_statistics*/ /*test_0jvvdaw4kxpqw*/* from T1,T2
where t1.id=t2.id and t1.id<=:N1

Plan hash value: 1143140472

----------------------------------------------------------------------------------------------------------------------------
| Id  | Operation                    | Name   | Starts | E-Rows | A-Rows |   A-Time   | Buffers |  OMem |  1Mem | Used-Mem |
----------------------------------------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT             |        |      1 |        |    100 |00:00:00.01 |      10 |       |       |          |
|*  1 |  HASH JOIN                   |        |      1 |     99 |    100 |00:00:00.01 |      10 |   751K|   751K| 1268K (0)|
|   2 |   TABLE ACCESS BY INDEX ROWID| T1     |      1 |    100 |    100 |00:00:00.01 |       4 |       |       |          |
|*  3 |    INDEX RANGE SCAN          | PAR_I1 |      1 |    100 |    100 |00:00:00.01 |       2 |       |       |          |
|   4 |   TABLE ACCESS BY INDEX ROWID| T2     |      1 |    100 |    100 |00:00:00.01 |       6 |       |       |          |
|*  5 |    INDEX RANGE SCAN          | CHI_I1 |      1 |    100 |    100 |00:00:00.01 |       3 |       |       |          |
----------------------------------------------------------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------

   1 - access("T1"."ID"="T2"."ID")
   3 - access("T1"."ID"<=:N1)
   5 - access("T2"."ID"<=:N1) 25 rows selected. Elapsed: 00:00:00.02 SQL> alter session set optimizer_features_enable='11.1.0.7';

Session altered.

Elapsed: 00:00:00.01
SQL> set echo off
timing for: time_for_ofe_11.1.0.7
Elapsed: 00:00:00.02

PLAN_TABLE_OUTPUT
-----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
SQL_ID  1hs7jn4tshzqa, child number 1
-------------------------------------
select /*+gather_plan_statistics*/ /*test_0jvvdaw4kxpqw*/* from T1,T2
where t1.id=t2.id and t1.id<=:N1

Plan hash value: 1143140472

----------------------------------------------------------------------------------------------------------------------------
| Id  | Operation                    | Name   | Starts | E-Rows | A-Rows |   A-Time   | Buffers |  OMem |  1Mem | Used-Mem |
----------------------------------------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT             |        |      1 |        |    100 |00:00:00.01 |      10 |       |       |          |
|*  1 |  HASH JOIN                   |        |      1 |     99 |    100 |00:00:00.01 |      10 |   751K|   751K| 1254K (0)|
|   2 |   TABLE ACCESS BY INDEX ROWID| T1     |      1 |    100 |    100 |00:00:00.01 |       4 |       |       |          |
|*  3 |    INDEX RANGE SCAN          | PAR_I1 |      1 |    100 |    100 |00:00:00.01 |       2 |       |       |          |
|   4 |   TABLE ACCESS BY INDEX ROWID| T2     |      1 |    100 |    100 |00:00:00.01 |       6 |       |       |          |
|*  5 |    INDEX RANGE SCAN          | CHI_I1 |      1 |    100 |    100 |00:00:00.01 |       3 |       |       |          |
----------------------------------------------------------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------

   1 - access("T1"."ID"="T2"."ID")
   3 - access("T1"."ID"<=:N1)
   5 - access("T2"."ID"<=:N1) 25 rows selected. Elapsed: 00:00:00.01 SQL> alter session set optimizer_features_enable='11.1.0.6';

Session altered.

Elapsed: 00:00:00.01
SQL> set echo off
timing for: time_for_ofe_11.1.0.6
Elapsed: 00:00:00.02

PLAN_TABLE_OUTPUT
-----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
SQL_ID  1hs7jn4tshzqa, child number 2
-------------------------------------
select /*+gather_plan_statistics*/ /*test_0jvvdaw4kxpqw*/* from T1,T2
where t1.id=t2.id and t1.id<=:N1

Plan hash value: 1143140472

----------------------------------------------------------------------------------------------------------------------------
| Id  | Operation                    | Name   | Starts | E-Rows | A-Rows |   A-Time   | Buffers |  OMem |  1Mem | Used-Mem |
----------------------------------------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT             |        |      1 |        |    100 |00:00:00.01 |      10 |       |       |          |
|*  1 |  HASH JOIN                   |        |      1 |     99 |    100 |00:00:00.01 |      10 |   751K|   751K| 1258K (0)|
|   2 |   TABLE ACCESS BY INDEX ROWID| T1     |      1 |    100 |    100 |00:00:00.01 |       4 |       |       |          |
|*  3 |    INDEX RANGE SCAN          | PAR_I1 |      1 |    100 |    100 |00:00:00.01 |       2 |       |       |          |
|   4 |   TABLE ACCESS BY INDEX ROWID| T2     |      1 |    100 |    100 |00:00:00.01 |       6 |       |       |          |
|*  5 |    INDEX RANGE SCAN          | CHI_I1 |      1 |    100 |    100 |00:00:00.01 |       3 |       |       |          |
----------------------------------------------------------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------

   1 - access("T1"."ID"="T2"."ID")
   3 - access("T1"."ID"<=:N1)
   5 - access("T2"."ID"<=:N1) 25 rows selected. Elapsed: 00:00:00.02 SQL> alter session set optimizer_features_enable='10.2.0.5';

Session altered.

Elapsed: 00:00:00.02
SQL> set echo off
timing for: time_for_ofe_10.2.0.5
Elapsed: 00:00:00.03

PLAN_TABLE_OUTPUT
-----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
SQL_ID  1hs7jn4tshzqa, child number 3
-------------------------------------
select /*+gather_plan_statistics*/ /*test_0jvvdaw4kxpqw*/* from T1,T2
where t1.id=t2.id and t1.id<=:N1

Plan hash value: 1143140472

----------------------------------------------------------------------------------------------------------------------------
| Id  | Operation                    | Name   | Starts | E-Rows | A-Rows |   A-Time   | Buffers |  OMem |  1Mem | Used-Mem |
----------------------------------------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT             |        |      1 |        |    100 |00:00:00.01 |      10 |       |       |          |
|*  1 |  HASH JOIN                   |        |      1 |     99 |    100 |00:00:00.01 |      10 |   751K|   751K| 1250K (0)|
|   2 |   TABLE ACCESS BY INDEX ROWID| T1     |      1 |    100 |    100 |00:00:00.01 |       4 |       |       |          |
|*  3 |    INDEX RANGE SCAN          | PAR_I1 |      1 |    100 |    100 |00:00:00.01 |       2 |       |       |          |
|   4 |   TABLE ACCESS BY INDEX ROWID| T2     |      1 |    100 |    100 |00:00:00.01 |       6 |       |       |          |
|*  5 |    INDEX RANGE SCAN          | CHI_I1 |      1 |    100 |    100 |00:00:00.01 |       3 |       |       |          |
----------------------------------------------------------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------

   1 - access("T1"."ID"="T2"."ID")
   3 - access("T1"."ID"<=:N1)
   5 - access("T2"."ID"<=:N1) 25 rows selected. Elapsed: 00:00:00.01 SQL> alter session set optimizer_features_enable='10.2.0.4';

Session altered.

Elapsed: 00:00:00.02
SQL> set echo off
timing for: time_for_ofe_10.2.0.4
Elapsed: 00:00:00.03

PLAN_TABLE_OUTPUT
-----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
SQL_ID  1hs7jn4tshzqa, child number 4
-------------------------------------
select /*+gather_plan_statistics*/ /*test_0jvvdaw4kxpqw*/* from T1,T2
where t1.id=t2.id and t1.id<=:N1

Plan hash value: 1143140472

----------------------------------------------------------------------------------------------------------------------------
| Id  | Operation                    | Name   | Starts | E-Rows | A-Rows |   A-Time   | Buffers |  OMem |  1Mem | Used-Mem |
----------------------------------------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT             |        |      1 |        |    100 |00:00:00.01 |      10 |       |       |          |
|*  1 |  HASH JOIN                   |        |      1 |     99 |    100 |00:00:00.01 |      10 |   751K|   751K| 1252K (0)|
|   2 |   TABLE ACCESS BY INDEX ROWID| T1     |      1 |    100 |    100 |00:00:00.01 |       4 |       |       |          |
|*  3 |    INDEX RANGE SCAN          | PAR_I1 |      1 |    100 |    100 |00:00:00.01 |       2 |       |       |          |
|   4 |   TABLE ACCESS BY INDEX ROWID| T2     |      1 |    100 |    100 |00:00:00.01 |       6 |       |       |          |
|*  5 |    INDEX RANGE SCAN          | CHI_I1 |      1 |    100 |    100 |00:00:00.01 |       3 |       |       |          |
----------------------------------------------------------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------

   1 - access("T1"."ID"="T2"."ID")
   3 - access("T1"."ID"<=:N1)
   5 - access("T2"."ID"<=:N1) 25 rows selected. Elapsed: 00:00:00.02 SQL> @sqlid 1hs7jn4tshzqa

SQL_ID        HASH_VALUE SQL_TEXT
------------- ---------- ------------------------------------------------------------------------------------------------------------------------------------------------------
1hs7jn4tshzqa  864583370 select /*+gather_plan_statistics*/ /*test_0jvvdaw4kxpqw*/* from T1,T2 where t1.id=t2.id and t1.id<=:N1 1 row selected.  CH# PARENT_HANDLE    OBJECT_HANDLE     PLAN_HASH OPT_COST     PARSES   H_PARSES EXECUTIONS    FETCHES ROWS_PROCESSED     CPU_MS     ELA_MS    AVG_ELA       LIOS       PIOS      SORTS USERS_EXECUTING ---- ---------------- ---------------- ---------- -------- ---------- ---------- ---------- ---------- -------------- ---------- ---------- ---------- ---------- ---------- ---------- ---------------    0 00000000926F6F90 00000000926F6B90 1143140472        9          2          5          2          4            200         10      3.435   .0017175         20          0          0               0    1 00000000926F6F90 00000000926F3E90 1143140472        9          2          5          2          4            200          0      3.278    .001639         20          0          0               0    2 00000000926F6F90 0000000094936D28 1143140472        9          2          5          2          4            200         10      3.931   .0019655         20          0          0               0    3 00000000926F6F90 00000000926F1EF0 1143140472        9          2          5          2          4            200          0      3.644    .001822         20          0          0               0    4 00000000926F6F90 00000000926C3148 1143140472        9          2          5          2          4            200          0       2.61    .001305         20          0          0               0 5 rows selected. SQL>

With this test you call test.sql for 2 times for each available OFE value since the given base OFE. There are 5 different cursors for 5 different CBO environment variable and
they all used the same plan. By calling 2 times you see the caching effect and also on 11.2.0.1 and onward you can see the cardinality feedback effect if it kicks in (we will see about that later)

build_optimizer_features_test_e.sql : The only difference is that this scripts calls test_e.sql (the one you create on step 3b) and runs dbms_xplan.display
for the explained plan. I use this one when the sql runs very long time, even I still test with the runtime plan generation
explaining the plan sometimes gives me the rough idea on which OFE my plan may change

sourcecode of the build_optimizer_features_test_e is below

undefine base_optimizer_version
set heading off
set feedback off
define optimizer_feature="&amp;base_optimizer_version"
set term off
spool optimizer_features_test_e.sql
select 'set timing on' from dual;
select 'set echo off' from dual;
select 'spool optimizer_features_test_2_results.log' from dual;
select   'set echo on'||chr(10)||'alter session set optimizer_features_enable='''||optimizer_feature_enable||''';'
||chr(10)||'set echo off'||chr(10)||'@test_e.sql'||chr(10)||
'select * from table(dbms_xplan.display);'||chr(10)
from
(select distinct optimizer_feature_enable from v$system_fix_control
where
to_number(replace(optimizer_feature_enable,'.',''))&gt;=to_number(replace('&amp;optimizer_feature','.',''))
order by to_number(replace(optimizer_feature_enable,'.','')) desc );
select 'set echo off' from dual;
select 'spool off' from dual;
spool off
set term on
set heading on
set feedback on

Same example with the previous one this time assuming I am moving from 11.1.0.6 to 11.2.0.1


SQL> @build_optimizer_features_test_e
Enter value for base_optimizer_version: 11.1.0.6
SQL> @optimizer_features_test_e
SQL> alter session set optimizer_features_enable='11.2.0.1';
Elapsed: 00:00:00.02
SQL> set echo off
Elapsed: 00:00:00.10

Plan hash value: 1143140472

---------------------------------------------------------------------------------------
| Id  | Operation                    | Name   | Rows  | Bytes | Cost (%CPU)| Time     |
---------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT             |        |    99 | 24156 |     9  (12)| 00:00:01 |
|*  1 |  HASH JOIN                   |        |    99 | 24156 |     9  (12)| 00:00:01 |
|   2 |   TABLE ACCESS BY INDEX ROWID| T1     |   100 | 12200 |     4   (0)| 00:00:01 |
|*  3 |    INDEX RANGE SCAN          | PAR_I1 |   100 |       |     2   (0)| 00:00:01 |
|   4 |   TABLE ACCESS BY INDEX ROWID| T2     |   100 | 12200 |     4   (0)| 00:00:01 |
|*  5 |    INDEX RANGE SCAN          | CHI_I1 |   100 |       |     2   (0)| 00:00:01 |
---------------------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------

   1 - access("T1"."ID"="T2"."ID")
   3 - access("T1"."ID"<=100)
   5 - access("T2"."ID"<=100) Elapsed: 00:00:00.08 SQL> alter session set optimizer_features_enable='11.1.0.7';
Elapsed: 00:00:00.01
SQL> set echo off
Elapsed: 00:00:00.01

Plan hash value: 1143140472

---------------------------------------------------------------------------------------
| Id  | Operation                    | Name   | Rows  | Bytes | Cost (%CPU)| Time     |
---------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT             |        |    99 | 24156 |     9  (12)| 00:00:01 |
|*  1 |  HASH JOIN                   |        |    99 | 24156 |     9  (12)| 00:00:01 |
|   2 |   TABLE ACCESS BY INDEX ROWID| T1     |   100 | 12200 |     4   (0)| 00:00:01 |
|*  3 |    INDEX RANGE SCAN          | PAR_I1 |   100 |       |     2   (0)| 00:00:01 |
|   4 |   TABLE ACCESS BY INDEX ROWID| T2     |   100 | 12200 |     4   (0)| 00:00:01 |
|*  5 |    INDEX RANGE SCAN          | CHI_I1 |   100 |       |     2   (0)| 00:00:01 |
---------------------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------

   1 - access("T1"."ID"="T2"."ID")
   3 - access("T1"."ID"<=100)
   5 - access("T2"."ID"<=100) Elapsed: 00:00:00.01 SQL> alter session set optimizer_features_enable='11.1.0.6';
Elapsed: 00:00:00.02
SQL> set echo off
Elapsed: 00:00:00.01

Plan hash value: 1143140472

---------------------------------------------------------------------------------------
| Id  | Operation                    | Name   | Rows  | Bytes | Cost (%CPU)| Time     |
---------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT             |        |    99 | 24156 |     9  (12)| 00:00:01 |
|*  1 |  HASH JOIN                   |        |    99 | 24156 |     9  (12)| 00:00:01 |
|   2 |   TABLE ACCESS BY INDEX ROWID| T1     |   100 | 12200 |     4   (0)| 00:00:01 |
|*  3 |    INDEX RANGE SCAN          | PAR_I1 |   100 |       |     2   (0)| 00:00:01 |
|   4 |   TABLE ACCESS BY INDEX ROWID| T2     |   100 | 12200 |     4   (0)| 00:00:01 |
|*  5 |    INDEX RANGE SCAN          | CHI_I1 |   100 |       |     2   (0)| 00:00:01 |
---------------------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------

   1 - access("T1"."ID"="T2"."ID")
   3 - access("T1"."ID"<=100)
   5 - access("T2"."ID"<=100) Elapsed: 00:00:00.02 SQL>

In summary without building a test case and testing it yourself it is hard to find out what is going on and this post was all about having everything ready before you start the
actual diagnose. Next posts I will only put an output of the these steps and won’t explain what they are.

References Used:
http://kerryosborne.oracle-guy.com/2009/07/creating-test-scripts-with-bind-variables/
http://kerryosborne.oracle-guy.com/2008/10/unstable-plans/

Scripts used in this post

All in one as a zip file- build_test_case.zip

Scipts shared as txt for availability on google docs. (I think I need to move my own domain)
build_bind_vars2

build_bind_vars2 Kerry Osborne version
build_bind_vars
build_bind_vars2 Kerry Osborne version
build_bind_vars_h
build_optimizer_features_test
build_optimizer_features_test_e
find_sqlid
find_sqlid_h
sqlhist
sqlid
sw
sw Tanel Poder version
awr_plan_change

<-Previous Post in Series————————————–  Next Post in Series–>

The Silver is the New Black Theme. Create a free website or blog at WordPress.com.

Follow

Get every new post delivered to your Inbox.

Join 203 other followers