Plan stability through Upgrade to 11G- Building a test case
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.
1
2
3
4
5
6
7
8
9
| SQL> @sqlid cp7cg4db39a8zSQL_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
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
| 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 WAITSQL> @sqlid fuws9wt9d16fqSQL_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
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
| COSKANDBA@WHQAINT> @find_sqlEnter value for sql_text: select count(*) from v$parameterEnter 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_sqlidEnter value for sql_text: select count(*) from v$parameterSQL_ID SQL_TEXT------------- ----------------------------------------------------------------------------------------------------89f82uh6x612p select count(*) from v$parameter where name = 'cpu_count' and (isdefault = 'FALSE' or ismodified ! = 'FALSE') |
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
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
| SQL> @awr_plan_changeEnter 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.716 rows selected.SQL> |
which are not captured for dba_hist_sqlstats.
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
| 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 038 rows selected.SQL> |
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 10GYou 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 below1- 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
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
55
56
57
58
59
60
61
62
63
64
65
66
67
68
69
70
71
72
73
74
75
76
77
78
79
80
81
82
83
84
85
86
| SQL> @sqlid 6asfnp4v15rg3SQL_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 = :3Elapsed: 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 06 rows selected.Elapsed: 00:00:00.01SQL> @e5Enter value for sql_id: 6asfnp4v15rg3Enter value for child_number: 18PLAN_TABLE_OUTPUT-----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------EXPLAINED SQL STATEMENT:------------------------ SELECTDISTINCT TABLE_1.ID FROM USER_1.TABLE_1 TABLE_1, USER_1.TABLE_2TABLE_2 WHERE TABLE_1.ID = TABLE_2.ID ANDTABLE_2.SOURCEID = :1 AND TABLE_1.MARKETID = :2 ANDTABLE_1.TYPEID = :3Plan 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): 12527 rows selected.Elapsed: 00:00:00.06SQL> l 1* SELECT * FROM table(DBMS_XPLAN.DISPLAY_CURSOR(('&sql_id'),&child_number,'BASIC +PEEKED_BINDS'))SQL> @build_bind_varsEnter SQL ID ==> 6asfnp4v15rg3Enter Child Number ==> 18variable N1 NUMBERvariable N2 NUMBERvariable N3 NUMBERbegin:N1 := 66;:N2 := 1281;:N3 := 125;end;/select /* test_6asfnp4v15rg3 */ /*+ gather_plan_statistics */ DISTINCT TABLE_1.IDFROM USER_1.TABLE_1 TABLE_1, USER_1.TABLE_2 TABLE_2WHERE TABLE_1.ID = TABLE_2.IDAND TABLE_2.SOURCEID = :N1AND TABLE_1.MARKETID = :N2AND TABLE_1.TYPEID = :N3; |
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
| SQL> @build_bind_vars2Enter SQL ID ==> 6asfnp4v15rg3Enter Child Number ==> 18variable N1 NUMBERvariable N2 NUMBERvariable N3 NUMBERbegin:N1 := 66;:N2 := 1661;:N3 := 1;end;/select /* test_6asfnp4v15rg3 */ /*+ gather_plan_statistics */ DISTINCT TABLE_1.IDFROM USER_1.TABLE_1 TABLE_1, USER_1.TABLE_2 TABLE_2WHERE TABLE_1.ID = TABLE_2.IDAND TABLE_2.SOURCEID = :N1AND TABLE_1.MARKETID = :N2AND TABLE_1.TYPEID = :N3; |
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.
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
| SQL> @sqlid 1m7wy721qytx3no rows selectedno rows selectedSQL> @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 35610517868 rows selected.SQL> @build_bind_vars_hEnter SQL ID ==> 1m7wy721qytx3Enter Plan Hash Value ==> 2266344041variable B1 NUMBERbegin: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 BYSTARTTIMESTAMP) AS LAST, MAX (CLOSESPREAD) KEEP (DENSE_RANK LAST ORDER BY STARTTIMESTAMP) AS LASTSPREAD, MAX (CLOSEUPFRONT) KEEP (DENSE_RANKLAST ORDER BY STARTTIMESTAMP) AS LASTUPFRONT FROM USER_1.TABLE_1, USER_1.TABLE_2, USER_1.TABLE_3 WHERE TABLE_1.TICKERID = TABLE_2.TICKERIDAND 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 BYTABLE_1.TICKERID, TABLE_1.SOURCEID; |
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
1
2
3
4
5
6
7
8
9
| variable N1 NUMBERbegin:N1 := 100;end;/select /*+gather_plan_statistics*/ /*test_0jvvdaw4kxpqw*/*from T1,T2 where t1.id=t2.id and t1.id<=:N1; |
different than explain plans for sqls with bind variables.
Sample test_e.sql
1
2
| explain plan for select /*+gather_plan_statistics*/ /*test_0jvvdaw4kxpqw*/*from T1,T2 where t1.id=t2.id and t1.id<=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
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
| undefine base_optimizer_versionset heading offset feedback offdefine optimizer_feature="&base_optimizer_version"set term offspool optimizer_features_test.sqlselect '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_controlwhereto_number(replace(optimizer_feature_enable,'.',''))>=to_number(replace('&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 offset term onset heading onset feedback on |
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
| set timing onset echo offspool optimizer_features_test_results.logtiming start time_for_ofe_11.2.0.1set echo onalter session set optimizer_features_enable='11.2.0.1';set echo offset term off@test.sql/set term ontiming stop time_for_ofe_11.2.0.1select * from table(dbms_xplan.display_cursor(null,null,'ALLSTATS LAST'));timing start time_for_ofe_11.1.0.7set echo onalter session set optimizer_features_enable='11.1.0.7';set echo offset term off@test.sql/set term ontiming stop time_for_ofe_11.1.0.7select * from table(dbms_xplan.display_cursor(null,null,'ALLSTATS LAST'));set timing offspool off |
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
55
56
57
58
59
60
61
62
63
64
65
66
67
68
69
70
71
72
73
74
75
76
77
78
79
80
81
82
83
84
85
86
87
88
89
90
91
92
93
94
95
96
97
98
99
100
101
102
103
104
105
106
107
108
109
110
111
112
113
114
115
116
117
118
119
120
121
122
123
124
125
126
127
128
129
130
131
132
133
134
135
136
137
138
139
140
141
142
143
144
145
146
147
148
149
150
151
152
153
154
155
156
157
158
159
160
161
162
163
164
165
166
167
168
169
170
171
172
173
174
175
176
177
178
179
180
181
182
183
184
| SQL> ------------------------------SQL> ----- BUILD THE TEST CASE ----SQL> ------------------------------SQL> @build_optimizer_features_testEnter value for base_optimizer_version: 10.2.0.4SQL> ------------------------------SQL> ----- TEST THE TEST CASE -----SQL> ------------------------------SQL> @optimizer_features_testSQL> alter session set optimizer_features_enable='11.2.0.1';Session altered.Elapsed: 00:00:00.02SQL> set echo offtiming for: time_for_ofe_11.2.0.1Elapsed: 00:00:00.03PLAN_TABLE_OUTPUT-----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------SQL_ID 1hs7jn4tshzqa, child number 0-------------------------------------select /*+gather_plan_statistics*/ /*test_0jvvdaw4kxpqw*/* from T1,T2where t1.id=t2.id and t1.id<=:N1Plan 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.01SQL> set echo offtiming for: time_for_ofe_11.1.0.7Elapsed: 00:00:00.02PLAN_TABLE_OUTPUT-----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------SQL_ID 1hs7jn4tshzqa, child number 1-------------------------------------select /*+gather_plan_statistics*/ /*test_0jvvdaw4kxpqw*/* from T1,T2where t1.id=t2.id and t1.id<=:N1Plan 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.01SQL> set echo offtiming for: time_for_ofe_11.1.0.6Elapsed: 00:00:00.02PLAN_TABLE_OUTPUT-----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------SQL_ID 1hs7jn4tshzqa, child number 2-------------------------------------select /*+gather_plan_statistics*/ /*test_0jvvdaw4kxpqw*/* from T1,T2where t1.id=t2.id and t1.id<=:N1Plan 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.02SQL> set echo offtiming for: time_for_ofe_10.2.0.5Elapsed: 00:00:00.03PLAN_TABLE_OUTPUT-----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------SQL_ID 1hs7jn4tshzqa, child number 3-------------------------------------select /*+gather_plan_statistics*/ /*test_0jvvdaw4kxpqw*/* from T1,T2where t1.id=t2.id and t1.id<=:N1Plan 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.02SQL> set echo offtiming for: time_for_ofe_10.2.0.4Elapsed: 00:00:00.03PLAN_TABLE_OUTPUT-----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------SQL_ID 1hs7jn4tshzqa, child number 4-------------------------------------select /*+gather_plan_statistics*/ /*test_0jvvdaw4kxpqw*/* from T1,T2where t1.id=t2.id and t1.id<=:N1Plan 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 1hs7jn4tshzqaSQL_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> |
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
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
| undefine base_optimizer_versionset heading offset feedback offdefine optimizer_feature="&base_optimizer_version"set term offspool optimizer_features_test_e.sqlselect '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_controlwhereto_number(replace(optimizer_feature_enable,'.',''))>=to_number(replace('&optimizer_feature','.',''))order by to_number(replace(optimizer_feature_enable,'.','')) desc );select 'set echo off' from dual;select 'spool off' from dual;spool offset term onset heading onset feedback on |
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
55
56
57
58
59
60
61
62
63
64
65
66
67
68
69
70
71
72
73
| SQL> @build_optimizer_features_test_eEnter value for base_optimizer_version: 11.1.0.6SQL> @optimizer_features_test_eSQL> alter session set optimizer_features_enable='11.2.0.1';Elapsed: 00:00:00.02SQL> set echo offElapsed: 00:00:00.10Plan 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.01SQL> set echo offElapsed: 00:00:00.01Plan 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.02SQL> set echo offElapsed: 00:00:00.01Plan 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> |
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
