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–>

January 26, 2011

Plan stability through Upgrade to 11G-Introduction

Filed under: Performance, Plan Stability, Upgrade — coskan @ 12:31 am

What are the common reasons to upgrade a database ?

1- Version Support is ending or already ended
2- You hit a bug and support does not give you one-off patch solution and ask you to upgrade
3- There are new features, you think you may benefit from (reduced storage, new dr options, new development/management features)
4- Your management feels like they are dynamic and they should adapt new versions asap
5- You/End users are not happy with the current performance of DB and marketing of new version “guarantees” %XX better performance

Apart from the number 5, which always depends on architecture of your application, none of them is something users of your database really care. They don’t care what level of support you have,how much compression ration you have, how fast and how small your backups are, how solid your HA solution is, how easy you develop the code with new features,how easy DBAs manage the database, how shiny the management tool , how many bugs been sorted with new version or what your manager thinks, it is and it will always be the response time they experience is, what they only care. If it is fast enough they will be happy, if it is slow they are not and they won’t be happy.

When I search on web for the experiences people had after Oracle version upgrades, it was always performance what they most complained. From 8i to 9i , 8i to 10g, 9i to 10g people always been promised by marketing that the performance would be better but they usually experienced the opposite. Performance degradation was usually related with the enhancements for sql execution plan optimizations. Sometimes it was because of bugfixes,sometimes, it was plan enhancements for better optimizations, sometimes it was new features oracle intruduced (CBO,automatic statistics gatherin, system stats etc) or sometimes it was because of lack of understanding of optimizer (thanks Jonathan Lewis for his perfect book – Cost Based Oracle Fundamentals and his blog for letting readers understand how it works) there was always something and some of your plans was changed and performance of your db went down right after upgrade.

For plan stability users tried using hints which needs maintenance, high level of understanding and code changes or outlines which were a bit complex to use.
To sort this plan stability complexity, Guys at Oracle first came up with a solution called sql profiles in 10G but but it was cost option and not everybody had chance to use it.
Oracle needed a license free, easy to use and solid solution for plan stability and with 11G Oracle finally managed to give these options to users by  addition of  new “sql plan baselines” feature.

I recently did a major DB upgrade from 10.2.4 to 11.2.0.1 and despite all the performance problems we had during the testing phase, apart from 2 issues which are sorted in 10 minutes time we did not have any issue after the actual production upgrade. How did we managed to do this ?

1- we planned the upgrade in detail
2- we tested good and long enough
3- we caught all the problems during the test phase and sorted them all by plan baselines and with some of the techniques I will explain later.
4- We react quick enough on the first day after the upgrade. By help of plan baselines , We did not waste seconds to sort the problem.

Are sql plan baselines perfect solution ? Like all the software it is not perfect sometimes can get very hard to track down, but it is good enough to give what your end users want at first place, which is “same level of performance they experienced 1 day ago”. As I said before, they don’t care what you did that Saturday so you should put “giving them same level of performance they had and paid before upgrade” to the top of your priority list,

Using plan baselines looks like a bit like cheating for a DBA who likes to understand what the problem is, however with magical parameter optimizer_features_enable, (which is like a time machine that lets you have a journey between versions) you will always have time to understand what the problem was, so instead of becoming obsessive about sorting/understanding the actual problem at first place, it is better first creating the plan baseline to stabilize the system then start investigating.

By this way you could also avoid pressure of managers hanging around your des trying to understand “what the hell is going on”. (they won’t understand what is going on when you tell them anyway, so why bother explaining. ) the only thing they care is the number of calls reporting performance issues from end-users and big bosses. if the number of calls goes down they will be happy so give them what they want to see/hear. A stabile, upgraded database.

As you already understood from the topic and  reading nothing technical in the post , this post was an intruduction to plan stability through upgrade series I am starting.
During the series, I will try to explain how you can avoid upgrade related performance problems to make your dream upgrade and become hero :)

Current outline is like below. When I have time I will write them down one by one and link them here.

1-Introduction
2-Building the test
3-Why is my plan changed?-bugfixes : how you can find which bug fix may caused your plan change
4-Why is my plan changed?-new optimizer parameters : how you can find which parameter change/addition may caused your plan change
5-Why is my plan changed?-extra nested loop : what is the new nested loop step you will see after 11G upgrade
6-Why is my plan changed?-Auto adjusted Dynamic Sampling : I will try to explain how auto adjusted dynamic sampling can effect stability of your parallel queries
7-Why is my plan changed?-adaptive cursor sharing : I will talk a “little” about adaptive cursor sharing which may cause different plans for binded sqls after upgrade
8-Opening plan change case on MOS-SQLT : I will try to save the time you spend with Oracle Support when you raise a call for post upgrade performance degredation
9-Plan Baselines-Introduction : What are plan baselines they how they work
10-Plan Baselines-Using SQL Tuning sets : How to create plan baselines from tuning set ?
11-Plan Baselines-Using SQL Cache : How to create plan baselines from SQL Cache ?
12-Plan Baselines-Moving Baselines : How to move your plan baselines between database ?
13-Plan Baselines-Faking Baselines : How to fake the plan baseline?s
14-Plan Baselines-Capturing Baselines : How to capture baselines?
15-Plan Baselines-Management : How to manage your baselines?
16-Testing Statistics with Pending Stats : I’ll go through how you can use pending statistics during upgrades
17-Comparing Statistics : I’ll explain comparing the statistics
18-Cardinality Feedback Feature : I’ll go through new built in cardinality feedback feature which may cause problems
19-Where is the sqlid of active session ? : I’ll show you how you can find what your sql_id when it is null
20-Testing hintless database : I’ll explain how you can get rid of hints
21-Upgrade Day/Week : What needs to be ready for smooth upgrade ?
22-Before after analysis-mining problems : How you can spot possible problems comparing tuning sets
23-Before after analysis-graphs to sell : Using perfsheet to sell your work
24-Further Reading : Compilation of References I used during series and some helpfull links
25-Tools used : Index of the tools I used during series

I hope, I can write at least 3 post each week and finish series in 8-6 weeks. I nearly have all the material ready, which need a bit more polishing, I hope I won’t be to exhausted by lovely wordpress gui which is very annoying when it comes formatting.

January 24, 2011

Analysing Temp usage on 11GR2 when Temp space is not released

Filed under: Bugs — coskan @ 2:47 pm

We had an interesting issue on our 3 node cluster about the temp usage. One night one of the critical batch operation which never used high temp suddenly hit “ORA-01652: unable to extend temp segment by string in tablespace string tips”. Once we check the system we saw some “inactive sessions” were using very high amount of temp like below which were allocating most of the temp space causing batch operations fail even with very small temp request.

—The picture of temp usage right after the issue

PROD1> @temp_usageg

#####################################################################
#######################GLOBAL TEMP USAGE#############################
#####################################################################

   INST_ID TABLESPACE         MB_TOTAL     MB_USED    MB_FREE
---------- --------------- ----------- ----------- ----------
         3 TEMP              22528.000       7.000      22521
         2 TEMP              22528.000      56.000      22472
         1 TEMP              22528.000   19102.000       3426

#####################################################################
#######################GLOBAL TEMP USERS-over 10MB ##################
#####################################################################

   INST_ID SID_SERIAL USERNAME     OSUSER     SPID   SERVICE            MB_USED TABLESPACE
---------- ---------- ------------ ---------- ------ -------------------------- ---------------
         1 620,4322   USER_1      osusr1   21712  WEB_USER_SERVICE         16.000 TEMP
         1 41,35454   USER_1      osusr1   20334  WEB_USER_SERVICE         19.000 TEMP
         1 529,21034  USER_1      osusr1   5776   WEB_USER_SERVICE         20.000 TEMP
         1 538,54672  USER_1      osusr1   30383  WEB_USER_SERVICE         27.000 TEMP
         1 1258,36144 USER_1      osusr1   5745   WEB_USER_SERVICE         31.000 TEMP
         1 1351,56539 USER_2       root      29910  WEB_USER_SERVICE         67.000 TEMP
         1 1113,59480 USER_2       root      11397  WEB_USER_SERVICE         78.000 TEMP
         1 30,4102    USER_2       root      15244  WEB_USER_SERVICE         78.000 TEMP
         1 892,14168  USER_2       root      19971  WEB_USER_SERVICE         79.000 TEMP
         1 699,56288  USER_1      osusr1   11240  WEB_USER_SERVICE        668.000 TEMP
         1 1501,55691 USER_1      osusr1   11236  WEB_USER_SERVICE        685.000 TEMP
         1 1396,7154  USER_1      osusr1   12526  WEB_USER_SERVICE        808.000 TEMP
         1 233,46662  USER_1      osusr1   11334  WEB_USER_SERVICE        810.000 TEMP
         1 1004,14127 USER_1      osusr1   24287  WEB_USER_SERVICE        832.000 TEMP
         1 1196,820   USER_1      osusr1   12530  WEB_USER_SERVICE        868.000 TEMP
         1 1121,1990  USER_1      osusr1   24290  WEB_USER_SERVICE        893.000 TEMP
         1 297,2940   USER_1      osusr1   8910   WEB_USER_SERVICE        903.000 TEMP
         1 294,39051  USER_1      osusr1   15116  WEB_USER_SERVICE        924.000 TEMP
         1 37,46739   USER_1      osusr1   15118  WEB_USER_SERVICE        932.000 TEMP
         1 414,31439  USER_1      osusr1   8877   WEB_USER_SERVICE        935.000 TEMP
         1 913,40598  USER_1      osusr1   9710   WEB_USER_SERVICE       1064.000 TEMP
         1 710,44883  USER_1      osusr1   9703   WEB_USER_SERVICE       1115.000 TEMP
         1 147,16701  USER_1      osusr1   9295   WEB_USER_SERVICE       1137.000 TEMP
         1 1446,25613 USER_1      osusr1   12372  WEB_USER_SERVICE       1139.000 TEMP
         1 721,5152   USER_1      osusr1   12728  WEB_USER_SERVICE       1183.000 TEMP
         1 1295,31011 USER_1      osusr1   32078  WEB_USER_SERVICE       1208.000 TEMP
         1 14,60566   USER_1      osusr1   8236   WEB_USER_SERVICE       1209.000 TEMP
         1 29,64998   USER_1      osusr1   9292   WEB_USER_SERVICE       1318.000 TEMP

28 rows selected.

PROD1> check active sessions

PROD1> @swact

    SID STATE   EVENT                                     SEQ# SEC_IN_STATE         P1         P2         P3 SQL_ID         CHN
------- ------- ---------------------------------------- ----- ------------ ---------- ---------- ---------- ------------- ----
   1082 WAITING Streams AQ: waiting for messages in the  34587            1       8560 2.2692E+10          5
    390 WAITING wait for unread message on broadcast cha 52505            0 2.2570E+10 2.3036E+10          0 2b064ybzkwf1y    0
    888 WORKING On CPU / runqueue                        10058            0 1413697536          1          0 dgcp1b9y4h89a    0

PROD1> --none of the sessions were active

According to my Oracle knowledge, this should not has happened once the operation finishes (commit rollback) ,Oracle should has released the space. All of these sessions were all specific to one product group and service. Question was if this was a permanent problem which we never realized or something was going wrong ?
I checked back my old spool files for temporary checks (thanks to Tanel Poder who thought us how to spool every action- check init.sql from his script library) and saw that sessions with same username and service name were also holding big temp back in september and November like below. (These checks were probably done when we hit temp issue on node-1 or when I was checking the script so I did not pay attention if those sessions were active or not (this can be counted as invalid dba exception for me :))

From november – before 11.2.0.1 upgrade from 10.2.0.4


PROD3> @temp_usageg

#####################################################################
#######################GLOBAL TEMP USAGE#############################
#####################################################################

   INST_ID TABLESPACE         MB_TOTAL     MB_USED    MB_FREE
---------- --------------- ----------- ----------- ----------
         1 TEMP              20480.000     119.000      20361
         2 TEMP              20480.000        .000      20480
         3 TEMP              20480.000    8029.000      12451 ==>right node

#####################################################################
#######################GLOBAL TEMP USERS-over 10MB ##################
#####################################################################

   INST_ID SID_SERIAL USERNAME   OSUSER     SPID   PROGRAM             MB_USED TABLESPACE
---------- ---------- ---------- ---------- ------ --------------------------- ------------

         3 484,26686  USER_1       osusr1   6798    WEB_USER_SERVICE        109.000 TEMP
         3 898,53562  USER_1       osusr1   7272    WEB_USER_SERVICE        127.000 TEMP
         3 986,27409  USER_1       osusr1   5644    WEB_USER_SERVICE        147.000 TEMP
         3 771,4399   USER_1       osusr1   23613   WEB_USER_SERVICE        148.000 TEMP
         3 946,18709  USER_1       osusr1   12065   WEB_USER_SERVICE        163.000 TEMP
         3 378,20452  USER_1       osusr1   5646    WEB_USER_SERVICE        163.000 TEMP
         3 1007,23777 USER_1       osusr1   23413   WEB_USER_SERVICE        200.000 TEMP
         3 391,37179  USER_1       osusr1   9245    WEB_USER_SERVICE        701.000 TEMP
	 3 768,23493  USER_1       osusr1   12829   WEB_USER_SERVICE        904.000 TEMP
         3 607,13902  USER_1       osusr1   26307   WEB_USER_SERVICE       1000.000 TEMP
         3 475,32196  USER_1       osusr1   8460    WEB_USER_SERVICE       1010.000 TEMP
         3 593,58443  USER_1       osusr1   31126   WEB_USER_SERVICE       1063.000 TEMP
         3 879,51688  USER_1       osusr1   12831   WEB_USER_SERVICE       1113.000 TEMP
         3 664,40877  USER_1       osusr1   8470    WEB_USER_SERVICE       1136.000 TEMP

18 rows selected.

From October – before 11.2.0.1 upgrade from 10.2.0.4


PROD3> @temp_usage

TABLESPACE         MB_TOTAL     MB_USED    MB_FREE
--------------- ----------- ----------- ----------
TEMP              20480.000    7899.000      12581

#####################################################################
#######################GLOBAL TEMP USERS-over 10MB ##################
#####################################################################

SID_SERIAL USERNAME        OSUSER          SPID    PROGRAM             MB_USED TABLESPACE
---------- --------------- --------------- ------- --------------------------- -----------

463,42814  USER_1            osusr1        1447     WEB_USER_SERVICE         17.000 TEMP
1008,59864 USER_1            osusr1        16932    WEB_USER_SERVICE         17.000 TEMP
594,37070  USER_1            osusr1        6451     WEB_USER_SERVICE         20.000 TEMP
512,40923  USER_1            osusr1        16934    WEB_USER_SERVICE         25.000 TEMP
789,37294  USER_1            osusr1        9483     WEB_USER_SERVICE        731.000 TEMP
893,63174  USER_1            osusr1        6018     WEB_USER_SERVICE        815.000 TEMP
583,54040  USER_1            osusr1        23859    WEB_USER_SERVICE        933.000 TEMP
675,37736  USER_1            osusr1        9487     WEB_USER_SERVICE        984.000 TEMP
737,58648  USER_1            osusr1        25274    WEB_USER_SERVICE       1035.000 TEMP
831,46843  USER_1            osusr1        25272    WEB_USER_SERVICE       1062.000 TEMP
973,64549  USER_1            osusr1        10270    WEB_USER_SERVICE       1109.000 TEMP
774,18708  USER_1            osusr1        6625     WEB_USER_SERVICE       1133.000 TEMP

As you can see USER_1 from WEB_USER_SERVICE on the 3th (preferred) node was always using high temp.

Next question is why we did not have this issue before on Node-1? Once we check in detail we saw services of this product group were running on the wrong node (relocated due to a failure just before change freeze) which is our main OLTP and batch node. We already knew the issue (thanks to our service check script) but it was change freeze time and we did not have chance to move service to the right nodes. When I check with the product developer, I have been told they usually reboot their web servers every 3 weeks for maintenance. This was the obvious answer to the question why we did not have the issue before. We never run this service on the OLTP node and we never let web servers hit the limits even when they are running on their own node.

Since we gave answer to our curiosity questions, now it was time for the real question “Why was Oracle not releasing the temp space back ?” On 11GR2 we have a nice column called temp_space_allocated in V$ACTIVE_SESSION_HISTORY and DBA_HIST_ACTIVE_SESS_HISTORY tables and I am lucky that we have diagnostics pack license.

Let see what the trend is and see if some sqls are the main cause. The output below is taken when the issue happened.


SQL> select sample_time,event,sql_id,is_sqlid_current,temp_space_allocated/1024/1024 TEMP_MB
 1 from v$active_session_history where session_id=29;

SAMPLE_TIME             EVENT                     SQL_ID        I TEMP_MB
----------------------- ------------------------- ------------- - -----
04-JAN-11 10.18.09.591                            akgmrn2bww2p5 Y  1319
04-JAN-11 09.50.31.125  db file sequential read   73adfqhtsd909 Y  1319
04-JAN-11 09.46.29.488                            0gaghgkkb4qyc Y  1318
04-JAN-11 08.58.14.930  db file sequential read   73adfqhtsd909 Y  1318
04-JAN-11 08.13.09.845                            0gaghgkkb4qyc Y  1318
04-JAN-11 07.46.01.586  db file sequential read   ds7zkf3vhtms0 Y  1318
04-JAN-11 07.33.05.592  row cache lock            4tcbsv32h1xh9 Y  1317
04-JAN-11 06.49.49.772  db file sequential read   9s48k84m7kt36 Y  1317
04-JAN-11 06.49.48.772  db file sequential read   734fasjm6rfu8 Y  1316
04-JAN-11 06.49.47.762  db file sequential read   734fasjm6rfu8 Y  1316
04-JAN-11 06.49.45.762  db file sequential read   9s48k84m7kt36 Y  1315
04-JAN-11 06.49.44.762  log file sync                           Y  1314
04-JAN-11 06.18.09.894                            0gaghgkkb4qyc Y  1314
04-JAN-11 06.03.21.508                            akgmrn2bww2p5 Y  1314
04-JAN-11 04.18.20.232                            11chc5v8rkusd Y  1313
04-JAN-11 02.28.14.858                            73adfqhtsd909 Y  1312
04-JAN-11 02.08.13.726                            54hw5asg19hpt Y  1312
04-JAN-11 01.00.25.381                            akgmrn2bww2p5 Y  1312
04-JAN-11 00.58.15.042  db file sequential read   9s48k84m7kt36 Y  1312
04-JAN-11 00.00.02.040  direct path read temp     9tgtnsr31xsv5 Y  1312
03-JAN-11 23.52.33.856                            ds7zkf3vhtms0 Y  1301
03-JAN-11 22.33.14.607                            g7sy7a6ynn9r1 Y  1295
03-JAN-11 22.30.07.101  direct path read          9tgtnsr31xsv5 Y  1295

Because we did not sort the issue yet I also have the current picture of our system with a better script which accepts session sid and serial and uses lag function for the temp_space_allocated differences between sample times. (output is truncated)


PROD3> set echo on
PROD3> @temp_hist 603 8375
DBA_HIST_ACTIVE_SESS_HISTORY

PROD3>  select sample_time,session_id,session_serial#,sql_id,temp_space_allocated/1024/1024 temp_mb,
  2   temp_space_allocated/1024/1024-lag(temp_space_allocated/1024/1024,1,0) over (order by sample_time) as temp_diff
  3   from dba_hist_active_sess_history
  4   --from v$active_session_history
  5   where
  6   session_id=&1
  7   and session_serial#=&2
  8   order by sample_time asc
  9   /

SAMPLE_TIME               SESSION_ID SESSION_SERIAL# SQL_ID          TEMP_MB  TEMP_DIFF
------------------------- ---------- --------------- ------------- --------- ----------
22-JAN-11 13.00.51.214           603            8375                       1          1
22-JAN-11 15.14.29.430           603            8375 29kz43xq2s5xc         1          0
22-JAN-11 15.14.39.450           603            8375 734fasjm6rfu8         3          2
22-JAN-11 15.14.49.470           603            8375 734fasjm6rfu8         8          5
22-JAN-11 15.14.59.490           603            8375 734fasjm6rfu8        13          5
22-JAN-11 15.15.09.520           603            8375 9s48k84m7kt36        18          5
22-JAN-11 15.15.19.540           603            8375 734fasjm6rfu8        23          5
22-JAN-11 15.15.29.567           603            8375 9s48k84m7kt36        29          6
22-JAN-11 16.35.50.566           603            8375 bx5zxp1a5wb55        29          0
22-JAN-11 19.45.45.831           603            8375 73adfqhtsd909        32          3
22-JAN-11 21.40.40.613           603            8375 g7sy7a6ynn9r1        32          0
23-JAN-11 06.30.35.544           603            8375 ds7zkf3vhtms0        33          1
23-JAN-11 15.18.37.539           603            8375 9d618ka6h2hvz        35          2
23-JAN-11 15.18.47.583           603            8375 2du821ps20a4c        35          0
23-JAN-11 15.18.57.593           603            8375 29kz43xq2s5xc        35          0
23-JAN-11 15.19.07.623           603            8375                      39          4
23-JAN-11 15.19.17.643           603            8375 734fasjm6rfu8        44          5
23-JAN-11 15.19.27.663           603            8375 ds7zkf3vhtms0        49          5
23-JAN-11 15.19.37.683           603            8375 734fasjm6rfu8        55          6
23-JAN-11 15.19.47.713           603            8375 9s48k84m7kt36        61          6
23-JAN-11 15.19.57.733           603            8375 7902sa7n37sv9        62          1
23-JAN-11 22.00.39.071           603            8375 basj9jchbmu4q        63          1
24-JAN-11 05.00.45.895           603            8375 apmkt8bvrpyk0        70          7
24-JAN-11 13.00.11.180           603            8375 9tgtnsr31xsv5        86         16

24 rows selected.

ACTIVE_SESS_HIST

PROD3>  select sample_time,session_id,session_serial#,sql_id,temp_space_allocated/1024/1024 temp_mb,
  2   temp_space_allocated/1024/1024-lag(temp_space_allocated/1024/1024,1,0) over (order by sample_time) as temp_diff
  3   --from dba_hist_active_sess_history
  4   from v$active_session_history
  5   where
  6   session_id=&1
  7   and session_serial#=&2
  8   order by sample_time asc
  9   /

SAMPLE_TIME               SESSION_ID SESSION_SERIAL# SQL_ID          TEMP_MB  TEMP_DIFF
------------------------- ---------- --------------- ------------- --------- ----------
23-JAN-11 05.30.39.251           603            8375                      33         33
23-JAN-11 06.00.35.429           603            8375 73adfqhtsd909        33          0
23-JAN-11 06.10.45.871           603            8375 g7sy7a6ynn9r1        33          0
23-JAN-11 06.30.35.544           603            8375 ds7zkf3vhtms0        33          0
23-JAN-11 06.40.50.971           603            8375                      33          0
23-JAN-11 07.00.40.613           603            8375 g7sy7a6ynn9r1        33          0
23-JAN-11 07.01.21.713           603            8375 ds7zkf3vhtms0        33          0
23-JAN-11 07.10.45.941           603            8375 1rsg7wva9pyxd        33          0
23-JAN-11 08.00.45.805           603            8375 73adfqhtsd909        33          0
23-JAN-11 08.15.35.931           603            8375 ds7zkf3vhtms0        33          0
23-JAN-11 09.15.39.009           603            8375                      34          1
23-JAN-11 14.15.50.763           603            8375 g7sy7a6ynn9r1        34          0
23-JAN-11 14.20.35.388           603            8375 g7sy7a6ynn9r1        34          0
23-JAN-11 14.45.45.800           603            8375 4awcvxgvdauy6        35          1
23-JAN-11 15.15.39.123           603            8375 6ubavp8u2k7xa        35          0
23-JAN-11 15.18.36.539           603            8375 d042b4z3hnra4        35          0
23-JAN-11 15.18.37.539           603            8375 9d618ka6h2hvz        35          0
23-JAN-11 15.18.38.539           603            8375 4vwy3jp3wmmz5        35          0
23-JAN-11 15.18.39.539           603            8375 4vwy3jp3wmmz5        35          0
23-JAN-11 15.18.40.549           603            8375 5jf1jgqnp993z        35          0
23-JAN-11 15.18.41.549           603            8375 5jf1jgqnp993z        35          0
23-JAN-11 15.18.42.549           603            8375 37fxhfs1p44p6        35          0
23-JAN-11 15.18.43.549           603            8375 29kz43xq2s5xc        35          0
23-JAN-11 15.18.44.559           603            8375 2du821ps20a4c        35          0
23-JAN-11 15.18.45.573           603            8375 5jf1jgqnp993z        35          0
23-JAN-11 15.18.46.573           603            8375 5jf1jgqnp993z        35          0
23-JAN-11 15.18.47.583           603            8375 2du821ps20a4c        35          0
23-JAN-11 15.18.48.583           603            8375 67kpwgzpd4qam        35          0
23-JAN-11 15.18.49.583           603            8375 5jf1jgqnp993z        35          0
23-JAN-11 15.18.50.583           603            8375 7htn6x6s336f7        35          0
23-JAN-11 15.18.51.583           603            8375 29kz43xq2s5xc        35          0
23-JAN-11 15.18.52.593           603            8375 29kz43xq2s5xc        35          0
23-JAN-11 15.18.53.593           603            8375 29kz43xq2s5xc        35          0
23-JAN-11 15.18.54.593           603            8375 29kz43xq2s5xc        35          0
23-JAN-11 15.18.55.593           603            8375 29kz43xq2s5xc        35          0
23-JAN-11 15.18.56.593           603            8375 29kz43xq2s5xc        35          0
23-JAN-11 15.18.57.593           603            8375 29kz43xq2s5xc        35          0
23-JAN-11 15.18.58.603           603            8375 2du821ps20a4c        35          0
23-JAN-11 15.18.59.603           603            8375 9s48k84m7kt36        35          0
23-JAN-11 15.19.00.603           603            8375 9s48k84m7kt36        36          1

.....
.....
.....
129 rows selected.

PROD3>

Bear in mind relying on DBA_HIST data, for detecting the sqls which caused big jumps, will not be that realistic because of the sample frequency so it is better to focus on v$active_session_history.

When we look at the v$active_session_history it like there is no obvious reason. There are some sqlids which certainly increase the temp usage but not big jumps.I did one more check before I raise the question to Oracle support and checked what type of segments these TEMP segments are ? To do this I tweaked the temp_usage.sql and add segtype column to the scripts.


PROD1> @temp_usageg

#####################################################################
#######################GLOBAL TEMP USAGE#############################
#####################################################################

   INST_ID TABLESPACE         MB_TOTAL     MB_USED    MB_FREE
---------- --------------- ----------- ----------- ----------
         3 TEMP              22528.000       7.000      22521
         2 TEMP              22528.000      56.000      22472
         1 TEMP              22528.000   19102.000       3426

#####################################################################
#######################GLOBAL TEMP USERS-over 10MB###################
#####################################################################

   INST_ID SID_SERIAL USERNAME        OSUSER          SPID   SERVICE		   SEGTYPE	MB_USED TABLESPACE
---------- ---------- --------------- --------------- ------ ---------------------------------- ---------------
         1 620,4322   USER_1         osusr1        21712  WEB_USER_SERVICE       LOB_DATA     16.000 TEMP
         1 41,35454   USER_1         osusr1        20334  WEB_USER_SERVICE       LOB_DATA     19.000 TEMP
         1 529,21034  USER_1         osusr1        5776   WEB_USER_SERVICE       LOB_DATA     20.000 TEMP
         1 538,54672  USER_1         osusr1        30383  WEB_USER_SERVICE       LOB_DATA     27.000 TEMP
         1 1258,36144 USER_1         osusr1        5745   WEB_USER_SERVICE       LOB_DATA     31.000 TEMP
         1 1351,56539 USER_2          root           29910  WEB_USER_SERVICE       LOB_DATA     67.000 TEMP
         1 1113,59480 USER_2          root           11397  WEB_USER_SERVICE       LOB_DATA     78.000 TEMP
         1 30,4102    USER_2          root           15244  WEB_USER_SERVICE       LOB_DATA     78.000 TEMP
         1 892,14168  USER_2          root           19971  WEB_USER_SERVICE       LOB_DATA     79.000 TEMP
         1 699,56288  USER_1         osusr1        11240  WEB_USER_SERVICE       LOB_DATA    668.000 TEMP
         1 1501,55691 USER_1         osusr1        11236  WEB_USER_SERVICE       LOB_DATA    685.000 TEMP
         1 1396,7154  USER_1         osusr1        12526  WEB_USER_SERVICE       LOB_DATA    808.000 TEMP
         1 233,46662  USER_1         osusr1        11334  WEB_USER_SERVICE       LOB_DATA    810.000 TEMP
         1 1004,14127 USER_1         osusr1        24287  WEB_USER_SERVICE       LOB_DATA    832.000 TEMP
         1 1196,820   USER_1         osusr1        12530  WEB_USER_SERVICE       LOB_DATA    868.000 TEMP
         1 1121,1990  USER_1         osusr1        24290  WEB_USER_SERVICE       LOB_DATA    893.000 TEMP
         1 297,2940   USER_1         osusr1        8910   WEB_USER_SERVICE       LOB_DATA    903.000 TEMP
         1 294,39051  USER_1         osusr1        15116  WEB_USER_SERVICE       LOB_DATA    924.000 TEMP
         1 37,46739   USER_1         osusr1        15118  WEB_USER_SERVICE       LOB_DATA    932.000 TEMP
         1 414,31439  USER_1         osusr1        8877   WEB_USER_SERVICE       LOB_DATA    935.000 TEMP
         1 913,40598  USER_1         osusr1        9710   WEB_USER_SERVICE       LOB_DATA   1064.000 TEMP
         1 710,44883  USER_1         osusr1        9703   WEB_USER_SERVICE       LOB_DATA   1115.000 TEMP
         1 147,16701  USER_1         osusr1        9295   WEB_USER_SERVICE       LOB_DATA   1137.000 TEMP
         1 1446,25613 USER_1         osusr1        12372  WEB_USER_SERVICE       LOB_DATA   1139.000 TEMP
         1 721,5152   USER_1         osusr1        12728  WEB_USER_SERVICE       LOB_DATA   1183.000 TEMP
         1 1295,31011 USER_1         osusr1        32078  WEB_USER_SERVICE       LOB_DATA   1208.000 TEMP
         1 14,60566   USER_1         osusr1        8236   WEB_USER_SERVICE       LOB_DATA   1209.000 TEMP
         1 29,64998   USER_1         osusr1        9292   WEB_USER_SERVICE       LOB_DATA   1318.000 TEMP

28 rows selected.

My initial thought was temp tablespaces but I was wrong, it looks like all temp allocators which do not release the space are LOB segments. I also checked the sqls in the ash trend and it reveals sql_id’s which has got lob operations (some of them are packages). Double checked with developer and got the answer that they use dbms_lob.

Now it is time to look for bug, First hit on metalink “How to Release the Temp LOB Space and Avoid Hitting ORA-1652 [ID 802897.1]“. It says issue is for releases 8.1.5.0 to 11.1.0.7 but we are on 11.2.0.1. This document says there are 2 workarounds for versions above 10.2.0.4, first workaround is basically use
dbms_lob.freetemporary(a) but still drop the connection which is not a workaround at all.

Second solution is using the event 60025 to force session to freed space. The event information is like below

Cause
Temp LOB segments used for temporary LOBs are deleted only on session exit which may lead to large amounts of memory being held across multiple sessions.

Action
Setting this event will cause temporary LOB segments to be freed when there are no active temporary LOBs in the session. Setting this event will have a significant performance impact as it can cause temporary lob segments to be allocated and deleted many times during a session rather than once per session. Use this event only when temporary LOB segment memory use is an issue.

When I try the event it works (not immediately but when you call the allocation again) like below. I raised a call with Oracle before we implement the event change (probably with logon trigger) and still working with them to see if there is a one-off patch for the issue. If Oracle could not come up with one-off patch we will use the event.


---Before the session runs

14:23:00 SYS@ORACOS> @temp_usage

#####################################################################
#######################LOCAL TEMP USAGE#############################
#####################################################################

TABLESPACE         MB_TOTAL     MB_USED    MB_FREE
--------------- ----------- ----------- ----------
TEMP               2697.000        .000       2697

#####################################################################
#######################LOCAL TEMP USERS#############################
#####################################################################

no rows selected

---Session runs the dbms_lob

HR@ORACOS> @temp_test
14:23:10 HR@ORACOS>
14:23:10 HR@ORACOS> DECLARE
14:23:10   2  a clob;
14:23:10   3  BEGIN
14:23:10   4  dbms_lob.createtemporary(a, TRUE,dbms_lob.call);
14:23:10   5  END;
14:23:10   6  /

PL/SQL procedure successfully completed.

14:23:10 HR@ORACOS>
14:23:10 HR@ORACOS> commit;

Commit complete.

14:23:10 HR@ORACOS>
14:23:10 HR@ORACOS> ---check the temp usage on another session
14:23:10 HR@ORACOS> exec dbms_lock.sleep(15);

---monitoring session

14:23:01 SYS@ORACOS> @temp_usage

#####################################################################
#######################LOCAL TEMP USAGE#############################
#####################################################################

TABLESPACE         MB_TOTAL     MB_USED    MB_FREE
--------------- ----------- ----------- ----------
TEMP               2697.000       1.000       2696

#####################################################################
#######################LOCAL TEMP USERS#############################
#####################################################################

SID_SERIAL USERNAME          OSUSER          SPID  SERVICE_NAME        MB_USED TABLESPACE      STATEMENTS
---------- ----------------- --------------- --------------------- ----------- --------------- ----------
200,7236   HR                coskan          22101 SYS$USERS             1.000 TEMP                     1

---session activates the event

14:23:25 HR@ORACOS> ---enable the event
14:23:25 HR@ORACOS> alter session set events '60025 trace name context forever';

Session altered.

14:23:25 HR@ORACOS>
14:23:25 HR@ORACOS> ---check the temp usage on another session
14:23:25 HR@ORACOS> exec dbms_lock.sleep(15);

---monitoring session

14:23:15 SYS@ORACOS> @temp_usage

#####################################################################
#######################LOCAL TEMP USAGE#############################
#####################################################################

TABLESPACE         MB_TOTAL     MB_USED    MB_FREE
--------------- ----------- ----------- ----------
TEMP               2697.000       1.000       2696

#####################################################################
#######################LOCAL TEMP USERS#############################
#####################################################################

SID_SERIAL USERNAME          OSUSER          SPID   SERVICE_NAME        MB_USED TABLESPACE      STATEMENTS
---------- ----------------- --------------- ------ --------------- ----------- --------------- ----------
200,7236   HR                coskan          22101  SYS$USERS             1.000 TEMP                     1

---session activates the event and run the dbms_lob again

14:23:40 HR@ORACOS> ---re run the procedure
14:23:40 HR@ORACOS> DECLARE
14:23:40   2  a clob;
14:23:40   3  BEGIN
14:23:40   4  dbms_lob.createtemporary(a, TRUE,dbms_lob.call);
14:23:40   5  END;
14:23:40   6  /

PL/SQL procedure successfully completed.

14:23:40 HR@ORACOS>
14:23:40 HR@ORACOS> commit;

Commit complete.

14:23:40 HR@ORACOS>
14:23:40 HR@ORACOS> ---check the temp usage on another session
14:23:40 HR@ORACOS> exec dbms_lock.sleep(15);

--monitoring session
14:23:29 SYS@ORACOS> @temp_usage

#####################################################################
#######################LOCAL TEMP USAGE#############################
#####################################################################

TABLESPACE         MB_TOTAL     MB_USED    MB_FREE
--------------- ----------- ----------- ----------
TEMP               2697.000        .000       2697

#####################################################################
#######################LOCAL TEMP USERS#############################
#####################################################################

no rows selected

no rows selected

14:23:44 SYS@ORACOS>

In summary With this post I walk through how you can diagnose a temp issue and how new temp_allocated column of v$session and history tables can be very helpful during your diagnose.
Hope it will help some of you guys.

Scripts I used for this post

temp_usageg.sql for global temp usage info in RAC
temp_usage.sql for global temp usage info
temp_history.sqlto get historic information for a spesific sid,serial

Information about bug for sqlid column of V$TEMPSEG_USAGE / v$sort_usage by Kerry Osborne

Update 08/10/2012

Related info on another blog is also here for usage of WMSYS.WM_CONCAT and temp allocation

 

http://asanga-pradeep.blogspot.co.uk/2012/10/use-of-wmconcat-can-exhaust-temporary.html

January 17, 2011

11.2.0.2 performance stories

Filed under: Bugs, Performance — coskan @ 12:52 pm

As you might remember from the previous post this Saturday we upgraded one of our databases from 11.2.0.1 to 11.2.0.2. The performance of this DB was not always stable but it was running fine before the upgrade.

As usual we came on Monday and start post upgrade firefighting. server seems to use more CPU then it was using. When I checked the queries which were on CPU, they were nearly all changed their plans (I have awr option to check the plan changes) and interestingly Oracle suddenly decided not to use unique primary keys but other indexes with skip scan option.

What could be done to understand the problem ?

1- build a test case
2- run the test case with 11.2.0.1 and 11.2.0.2 optimizer_features_enable
3- If the behaviour is different then find the bottom of the problem by digging which optimizer_fix could have caused the problem ?

Building a test case is very easy thanks to Kerry Osborne and his amazingly useful (I have no idea how many times it made my day) build_bind_vars script. Normally building a test case for a sql which has 100 bind variables is a nightmare but with that script its just a second.

Once I build the test case I run the sql with different optimizer_features_enable settings and found out that sql goes back to its previous good plan when we run it with 11.2.0.1 optimizer settings

Since we found out what caused the problem in general, we can either move forward to 3th step to find bottom of the problem or change optimizer_features_enable to 11.2.0.1 system wide. We chose the first option to see if it is our main problem and it gave us stability across the system.

Was this acceptable workaround ? Not for me or for business. We upgraded the database and now why not using the 11.2.0.2 features. We needed to find out what fix actually caused.

To find out the actual problem we have two brilliant view called v$system_fix_control and v$session_fix_control.

Looks like we have 105 options to check

SQL> select optimizer_feature_enable,count(*) from v$system_fix_control group by optimizer_feature_enable order by 1 asc;

OPTIMIZER_FEATURE_ENABLE    COUNT(*)
------------------------- ----------
10.1.0                             3
10.1.0.3                           1
10.1.0.5                           2
10.2.0.1                           7
10.2.0.2                          12
10.2.0.3                          11
10.2.0.4                          73
10.2.0.5                         111
11.1.0.6                          39
11.1.0.7                          19
11.2.0.1                          65
11.2.0.2                         105
8.0.0                             52
8.1.6                              1
8.1.7                              2
9.2.0                              8
9.2.0.8                            3
                                  37

Lets see what they are

SQL>  select * from v$system_fix_control where optimizer_feature_enable='11.2.0.2';

     BUGNO      VALUE SQL_FEATURE                        DESCRIPTION                                                      OPTIMIZER_FEATURE
---------- ---------- ---------------------------------- ---------------------------------------------------------------- -----------------
   8602840          1 QKSFM_CBO_8602840                  kkeRangeJoinSel should avoid using collapsed min/max column stat 11.2.0.2
   8725296          1 QKSFM_OR_EXPAND_8725296            try non-driver predicate only if advanced check requested        11.2.0.2
   8628970          1 QKSFM_CBO_8628970                  group  predicates like col op const  of 1 NDV col                11.2.0.2
   6754080          1 QKSFM_ACCESS_PATH_6754080          enable expression replacement thru views                         11.2.0.2
   8767442          1 QKSFM_DYNAMIC_SAMPLING_8767442     compute NDV for all columns in a multi-column join key using DS  11.2.0.2
   8760135          1 QKSFM_CBO_8760135                  allow compile-time peeking of CURRENT_DATE / CURRENT_TIMESTAMP   11.2.0.2
   8644935          1 QKSFM_PQ_8644935                   new parallelization of concat                                    11.2.0.2
   8352378          1 QKSFM_CBO_8352378                  Allow virtual columns in OR expansion index access               11.2.0.2
   8685327          1 QKSFM_ACCESS_PATH_8685327          Heuristic to enable full index scan used if table & index analyz 11.2.0.2
   8763472          1 QKSFM_PARTITION_8763472            enable parallel nested loop PWJ for ref-part tables              11.2.0.2
   8773324          1 QKSFM_CBO_8773324                  better recognition of index only plans with virtual columns      11.2.0.2
   8813674          1 QKSFM_TRANSFORMATION_8813674       relax restriction for non-nullness check                         11.2.0.2
   8629716          1 QKSFM_CBO_8629716                  enable early replacement for virtual columns                     11.2.0.2
   7277732          1 QKSFM_CBO_7277732                  allow skip scan costing for NL with non-join predicate           11.2.0.2
   8692170          1 QKSFM_TRANSFORMATION_8692170       do not apply JF if it prevents JPPD                              11.2.0.2
   8900973          1 QKSFM_TRANSFORMATION_8900973       relax restriction on inequality join for group-by placement (GBP 11.2.0.2
   8919133          1 QKSFM_CBO_8919133                  correct nested OR costing bug                                    11.2.0.2
   8551880          1 QKSFM_CBO_8551880                  Rewrite decode predicate to join                                 11.2.0.2
   8901237          1 QKSFM_TRANSFORMATION_8901237       correct search of state-space for group-by placement (GBP)       11.2.0.2
   6236862          1 QKSFM_FIRST_ROWS_6236862           account for partition-extended names in first rows optimization  11.2.0.2
   8528517          1 QKSFM_TRANSFORMATION_8528517       early query edit checks use weak typecheck expression comparison 11.2.0.2
   7215982          1 QKSFM_UNNEST_7215982               unnest subquery embedded inside an expression                    11.2.0.2
   8214022          1 QKSFM_UNNEST_8214022               perform additional CBQT phase for subquery unnesting             11.2.0.2
   8595392          1 QKSFM_CBO_8595392                  reject join predicate pushdown if parallel access path selected  11.2.0.2
   8890233          1 QKSFM_PQ_8890233                   enable pushing bloom filter through NLJ                          11.2.0.2
   8999317          1 QKSFM_UNNEST_8999317               correct cost comparison for the additional phase for JPPD        11.2.0.2
   8986163          1 QKSFM_PQ_8986163                   align partition-wise gby DOP requirements with partition-wise jo 11.2.0.2
   8855396          1 QKSFM_ACCESS_PATH_8855396          sanity check for skip scan costing                               11.2.0.2
   8800514         20 QKSFM_JPPD_8800514                 threshold of table count to disable extended JPPD                11.2.0.2
   9007859          1 QKSFM_CBO_9007859                  Context index to be picked on XMLType Columns                    11.2.0.2
   9053879          1 QKSFM_CBO_9053879                  search all query blocks for replacement candidates               11.2.0.2
   6086930          1 QKSFM_ACCESS_PATH_6086930          correct skip scan selectivity evaluation for BETWEEN predicate   11.2.0.2
   7641601          1 QKSFM_CARDINALITY_7641601          treat a single value column as having a frequency histogram      11.2.0.2
   9052506          1 QKSFM_UNNEST_9052506               Allow NAAJ for UPDATE and DELETE                                 11.2.0.2
   9047975          1 QKSFM_CBO_9047975                  improve selectivity for truncated character strings              11.2.0.2
   8893626          0 QKSFM_ACCESS_PATH_8893626          apply index filter selectivity during skip scan costing          11.2.0.2
   9111170          1 QKSFM_TRANSFORMATION_9111170       allow subquery to appear on left side when generating inline vie 11.2.0.2
   8971829          1 QKSFM_ACCESS_PATH_8971829          set KKEGIXSL for unpartitioned global index                      11.2.0.2
   9125151          1 QKSFM_STATS_9125151                produce more accurate stats for olap when stats has not been run 11.2.0.2
   9106224          1 QKSFM_PQ_9106224                   allow range distribution in create of global partitioned index   11.2.0.2
   9185228          1 QKSFM_UNNEST_9185228               move correlated filters from subquery to outer query             11.2.0.2
   9206747          1 QKSFM_CBO_9206747                  share metadata for virtual columns when making copy              11.2.0.2
   9088510          1 QKSFM_TRANSFORMATION_9088510       compress predicate tree before cost-based query transformation   11.2.0.2
   9143856          1 QKSFM_TRANSFORMATION_9143856       uncorrelated OR-ed unary predicates are OK for unnesting         11.2.0.2
   8949971          1 QKSFM_STATS_8949971                make stats for leaf level data appear very large in COTs         11.2.0.2
   9148171          1 QKSFM_TRANSFORMATION_9148171       allow distinct elim & distinct aggr transform for non-select stm 11.2.0.2
   8706652          1 QKSFM_CBO_8706652                  fix for 7449971 not complete                                     11.2.0.2
   9245114          1 QKSFM_TABLE_ELIM_9245114           eliminate redundant join predicates in join elimination          11.2.0.2
   9011016          1 QKSFM_ACCESS_PATH_9011016          use 1/NDV+1/NROWS for col1 LIKE col2 selectivities (index driver 11.2.0.2
   9265681          1 QKSFM_CARDINALITY_9265681          sanity check for derived ndv/cdn for inner join on range         11.2.0.2
   7284269          1 QKSFM_CURSOR_SHARING_7284269       extended cursor sharing for like predicates                      11.2.0.2
   9272549          1 QKSFM_DYNAMIC_SAMPLING_9272549     do not sample columns which have statistics                      11.2.0.2
   8531463          1 QKSFM_ACCESS_PATH_8531463          cost cutoff for bitmap OR chains based on best table access cost 11.2.0.2
   9263333          1 QKSFM_CBO_9263333                  generate transitive predicates for virtual column expressions    11.2.0.2
   8896955          1 QKSFM_TRANSFORMATION_8896955       interleave TE with ST and JF                                     11.2.0.2
   9041934          1 QKSFM_EXECUTION_9041934            use selected measures for AW LOOP OPTIMIZED looping strategy     11.2.0.2
   9344709          1 QKSFM_PQ_9344709                   disable parallel execution for a qb with a constant false pred   11.2.0.2
   9024933          1 QKSFM_JPPD_9024933                 Do not allow Old JPPD for OJ view with window function           11.2.0.2
   9033718          1 QKSFM_TABLE_EXPANSION_9033718      remove restriction on bind variables for table expansion         11.2.0.2
   9081848          1 QKSFM_CBO_9081848                  don't use fake index stats as extended stats                     11.2.0.2
   5982893          1 QKSFM_SQL_CODE_GENERATOR_5982893   compact row vector of colocated join                             11.2.0.2
   9287401          1 QKSFM_TRANSFORMATION_9287401       full outer join to outer join conversion                         11.2.0.2
   8590021          1 QKSFM_CBO_8590021                  using col stats for pred NVL()  const selectivity estimation 11.2.0.2
   9340120          1 QKSFM_CBO_9340120                  derive stats for sys generated UA view selectivity estimation    11.2.0.2
   9355794          1 QKSFM_CBO_9355794                  clear sort merge joins paths noted in apafjo                     11.2.0.2
   9385634          1 QKSFM_EXECUTION_9385634            always return error for null end point expression                11.2.0.2
   9069046          1 QKSFM_CBO_9069046                  amend histogram column tracking for multicolumn stats            11.2.0.2
   9239337          1 QKSFM_CBO_9239337                  eliminate unreferenced subqueries after view merging             11.2.0.2
   9298010          1 QKSFM_PARTITION_9298010            enable pruning for partitioned IOT rowid predicates              11.2.0.2
   8836806          1 QKSFM_CBO_8836806                  push rownum predicate into sortable domain index                 11.2.0.2
   9344055          1 QKSFM_CBO_9344055                  Control the memory used during query optimization                11.2.0.2
   9203723          1 QKSFM_SQL_CODE_GENERATOR_9203723   allow bloom pruning and bloom filtering on the same join         11.2.0.2
   9443476          1 QKSFM_CBO_9443476                  set OPNF2NOSEL bit for auto generated virtual column predicates  11.2.0.2
   9195582          1 QKSFM_ACCESS_PATH_9195582          leaf blocks as upper limit for skip scan blocks                  11.2.0.2
   9433490          1 QKSFM_CBO_9433490                  enable VC replacement for nest operator                          11.2.0.2
   9303766          1 QKSFM_ACCESS_PATH_9303766          use 1/NDV+1/NROWS for col1 LIKE col2 selectivities (table access 11.2.0.2
   9437283          1 QKSFM_CBO_9437283                  Do not consider NLJ from JPPD when checking for FCP              11.2.0.2
   9116214          1 QKSFM_ACCESS_PATH_9116214          index filter ordering                                            11.2.0.2
   9456688          1 QKSFM_ACCESS_PATH_9456688          account for to_number/to_char cost after temp conversion         11.2.0.2
   9342979          1 QKSFM_CURSOR_SHARING_9342979       disable cardinality feedback for old JPPD                        11.2.0.2
   9465425          1 QKSFM_CURSOR_SHARING_9465425       correct hint for index join from cardinality feedback            11.2.0.2
   9092442          1 QKSFM_DML_9092442                  equi-partition load                                              11.2.0.2
   4926618          1 QKSFM_EXECUTION_4926618            do not use hash unique for subqueries in update-set expression   11.2.0.2
   8792846          1 QKSFM_STAR_TRANS_8792846           use _optimizer_star_trans_min_ratio even if ST not hinted        11.2.0.2
   9474259          1 QKSFM_CBO_9474259                  use cdn sanity check when unique colgroup on both sides of join  11.2.0.2
   6472966          1 QKSFM_PARTITION_6472966            load and use statistics for hash sub-partitions                  11.2.0.2
   6408301          1 QKSFM_DYNAMIC_SAMPLING_6408301     use recursive idx selectivity for partitioned table as well      11.2.0.2
   8500130          1 QKSFM_EXECUTION_8500130            enable rownum optimization without partition pushup              11.2.0.2
   9584723          1 QKSFM_INDEX_JOIN_9584723           enable functional indexes for index join                         11.2.0.2
   9593680          1 QKSFM_CBO_9593680                  fix typo in cost computation of subquery filters                 11.2.0.2
   9309281          1 QKSFM_JPPD_9309281                 outer join JPPD allowed for function-based index access path     11.2.0.2
   8693158          1 QKSFM_JPPD_8693158                 consider pushing if only shared predicates to push               11.2.0.2
   9381638          1 QKSFM_PQ_9381638                   Treat CP differently from NLJ for parallel optimizations         11.2.0.2
   9383967          1 QKSFM_COMPILATION_9383967          Allow unique (ie. select distinct) pushdown                      11.2.0.2
   7711900          1 QKSFM_CBQT_7711900                 copy query block text position fields in copy service            11.2.0.2
   9218587          1 QKSFM_CARDINALITY_9218587          Don't use column density for selectivity with 1-bucket histogram 11.2.0.2
   9728438          1 QKSFM_CBO_9728438                  don't go parallel if no operations are expensive enough          11.2.0.2
   9577300          1 QKSFM_CBO_9577300                  Improve range join selectivity for predicates with round         11.2.0.2
   9171113          1 QKSFM_CBO_9171113                  consider parallel cost for partition bitmap table access by rowi 11.2.0.2
   8973745          1 QKSFM_SQL_PLAN_MANAGEMENT_8973745  auto-capture only if literal replaced SQL parses recursively     11.2.0.2
   9102474          1 QKSFM_CBO_9102474                  use IO calibrate statistics to estimate time from cost           11.2.0.2
   9243499          1 QKSFM_CBO_9243499                  relax conditions for logical antijoin                            11.2.0.2
   9912503          1 QKSFM_TRANSFORMATION_9912503       Remove having clause subquery at all levels                      11.2.0.2
   9153459          1 QKSFM_TABLE_ELIM_9153459           allow loading of rely constraints for all statement types        11.2.0.2
   9762592          3 QKSFM_PQ_9762592                   fold bloom filter when offload to storage                        1

Lets shoot in the dark

SQL>  select * from v$system_fix_control where optimizer_feature_enable='11.2.0.2' and description like '%skip%';

     BUGNO      VALUE SQL_FEATURE                                                      DESCRIPTION                                                      OPTIMIZER_FEATURE_ENABLE
---------- ---------- ---------------------------------------------------------------- ---------------------------------------------------------------- -------------------------
   7277732          1 QKSFM_CBO_7277732                                                allow skip scan costing for NL with non-join predicate           11.2.0.2
   8855396          1 QKSFM_ACCESS_PATH_8855396                                        sanity check for skip scan costing                               11.2.0.2
   6086930          1 QKSFM_ACCESS_PATH_6086930                                        correct skip scan selectivity evaluation for BETWEEN predicate   11.2.0.2
   8893626          1 QKSFM_ACCESS_PATH_8893626                                        apply index filter selectivity during skip scan costing          11.2.0.2
   9195582          1 QKSFM_ACCESS_PATH_9195582                                        leaf blocks as upper limit for skip scan blocks                  11.2.0.2

Lets focus on those fixes

In the stack below test4.sql has got the sql causing problem and what I do is altering the session to disable the fix in question and keep it disabled while my current session is under 11.2.0.2 . (For data security I could not add the sql and table names. )

SQL> alter session set optimizer_features_enable='11.2.0.2';

Session altered.

SQL> alter session set "_fix_control"='8855396:OFF';

Session altered.

SQL> @test4.sql

Plan hash value: 2840796242

-----------------------------------------------------------------------------------------------------------------------
| Id  | Operation                     | Name                        | Starts | E-Rows | A-Rows |   A-Time   | Buffers |
-----------------------------------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT              |                             |      1 |        |      0 |00:00:01.09 |    5404 |
|   1 |  NESTED LOOPS OUTER           |                             |      1 |      1 |      0 |00:00:01.09 |    5404 |
|   2 |   NESTED LOOPS                |                             |      1 |      1 |      0 |00:00:01.09 |    5404 |
|*  3 |    TABLE ACCESS BY INDEX ROWID| TABLE_XXXXXXXXXXXXXX        |      1 |      1 |      0 |00:00:01.09 |    5404 |
|*  4 |     INDEX SKIP SCAN           | IDX_TABLE_XXXXXXXXXXXXXX_02 |      1 |      1 |     50 |00:00:00.07 |    5317 |
|   5 |    TABLE ACCESS BY INDEX ROWID| TABLE_YYYYYYYYYYYYYYYYYY    |      0 |      1 |      0 |00:00:00.01 |       0 |
|*  6 |     INDEX UNIQUE SCAN         | PK_ZZZZZZZZZZZZZZZZZZZ      |      0 |      1 |      0 |00:00:00.01 |       0 |
|   7 |   TABLE ACCESS BY INDEX ROWID | TABLE_TTTTTTTTTTTT          |      0 |      1 |      0 |00:00:00.01 |       0 |
|*  8 |    INDEX UNIQUE SCAN          | PK_TABLE_TTTTTTTTTTTT       |      0 |      1 |      0 |00:00:00.01 |       0 |
-----------------------------------------------------------------------------------------------------------------------

48 rows selected.

SQL>
SQL> alter session set "_fix_control"='6086930:OFF';

Session altered.

SQL> @test4.sql

PL/SQL procedure successfully completed.

Plan hash value: 2840796242

-----------------------------------------------------------------------------------------------------------------------
| Id  | Operation                     | Name                        | Starts | E-Rows | A-Rows |   A-Time   | Buffers |
-----------------------------------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT              |                             |      1 |        |      0 |00:00:01.11 |    5404 |
|   1 |  NESTED LOOPS OUTER           |                             |      1 |      1 |      0 |00:00:01.11 |    5404 |
|   2 |   NESTED LOOPS                |                             |      1 |      1 |      0 |00:00:01.11 |    5404 |
|*  3 |    TABLE ACCESS BY INDEX ROWID| TABLE_XXXXXXXXXXXXXX        |      1 |      1 |      0 |00:00:01.11 |    5404 |
|*  4 |     INDEX SKIP SCAN           | IDX_TABLE_XXXXXXXXXXXXXX_02 |      1 |      1 |     50 |00:00:00.07 |    5317 |
|   5 |    TABLE ACCESS BY INDEX ROWID| TABLE_YYYYYYYYYYYYYYYYYY    |      0 |      1 |      0 |00:00:00.01 |       0 |
|*  6 |     INDEX UNIQUE SCAN         | PK_ZZZZZZZZZZZZZZZZZZZ      |      0 |      1 |      0 |00:00:00.01 |       0 |
|   7 |   TABLE ACCESS BY INDEX ROWID | TABLE_TTTTTTTTTTTT          |      0 |      1 |      0 |00:00:00.01 |       0 |
|*  8 |    INDEX UNIQUE SCAN          | PK_TABLE_TTTTTTTTTTTT       |      0 |      1 |      0 |00:00:00.01 |       0 |
-----------------------------------------------------------------------------------------------------------------------

SQL>
SQL> alter session set "_fix_control"='8893626:OFF';

Session altered.

SQL> @test4.sql

PL/SQL procedure successfully completed.

Plan hash value: 3290908244

------------------------------------------------------------------------------------------------------------------------------
| Id  | Operation                      | Name                     | Starts | E-Rows | A-Rows |   A-Time   | Buffers | Reads  |
------------------------------------------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT               |                          |      1 |        |      0 |00:00:00.08 |     178 |     15 |
|   1 |  NESTED LOOPS OUTER            |                          |      1 |      1 |      0 |00:00:00.08 |     178 |     15 |
|   2 |   NESTED LOOPS                 |                          |      1 |      1 |      0 |00:00:00.08 |     178 |     15 |
|   3 |    INLIST ITERATOR             |                          |      1 |        |      0 |00:00:00.08 |     178 |     15 |
|*  4 |     TABLE ACCESS BY INDEX ROWID| TABLE_XXXXXXXXXXXXXX     |     50 |      1 |      0 |00:00:00.08 |     178 |     15 |
|*  5 |      INDEX UNIQUE SCAN         | PK_TABLE_XXXXXXXXXXXXXX  |     50 |     50 |     50 |00:00:00.08 |      91 |     15 |
|   6 |    TABLE ACCESS BY INDEX ROWID | TABLE_YYYYYYYYYYYYYYYYYY |      0 |      1 |      0 |00:00:00.01 |       0 |      0 |
|*  7 |     INDEX UNIQUE SCAN          | PK_ZZZZZZZZZZZZZZZZZZZ   |      0 |      1 |      0 |00:00:00.01 |       0 |      0 |
|   8 |   TABLE ACCESS BY INDEX ROWID  | TABLE_TTTTTTTTTTTT       |      0 |      1 |      0 |00:00:00.01 |       0 |      0 |
|*  9 |    INDEX UNIQUE SCAN           | PK_TABLE_TTTTTTTTTTTT    |      0 |      1 |      0 |00:00:00.01 |       0 |      0 |
------------------------------------------------------------------------------------------------------------------------------

SQL>
SQL> alter session set "_fix_control"='9195582:OFF';

Session altered.

SQL> @test4.sql

---------------------------------------------------------------------------------------------------------------------
| Id  | Operation                      | Name                     | Starts | E-Rows | A-Rows |   A-Time   | Buffers |
---------------------------------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT               |                          |      1 |        |      0 |00:00:00.01 |     178 |
|   1 |  NESTED LOOPS OUTER            |                          |      1 |      1 |      0 |00:00:00.01 |     178 |
|   2 |   NESTED LOOPS                 |                          |      1 |      1 |      0 |00:00:00.01 |     178 |
|   3 |    INLIST ITERATOR             |                          |      1 |        |      0 |00:00:00.01 |     178 |
|*  4 |     TABLE ACCESS BY INDEX ROWID| TABLE_XXXXXXXXXXXXXX     |     50 |      1 |      0 |00:00:00.01 |     178 |
|*  5 |      INDEX UNIQUE SCAN         | PK_TABLE_XXXXXXXXXXXXXX  |     50 |     50 |     50 |00:00:00.01 |      91 |
|   6 |    TABLE ACCESS BY INDEX ROWID | TABLE_YYYYYYYYYYYYYYYYYY |      0 |      1 |      0 |00:00:00.01 |       0 |
|*  7 |     INDEX UNIQUE SCAN          | PK_ZZZZZZZZZZZZZZZZZZZ   |      0 |      1 |      0 |00:00:00.01 |       0 |
|   8 |   TABLE ACCESS BY INDEX ROWID  | TABLE_TTTTTTTTTTTT       |      0 |      1 |      0 |00:00:00.01 |       0 |
|*  9 |    INDEX UNIQUE SCAN           | PK_TABLE_TTTTTTTTTTTT    |      0 |      1 |      0 |00:00:00.01 |       0 |
---------------------------------------------------------------------------------------------------------------------

As you can see we hit the jackpot when we disabled the fix 8893626. Our Table called TABLE_XXXXXXXXXXXXXX started to use PK_TABLE_XXXXXXXXXXXXXX instead of IDX_TABLE_XXXXXXXXXXXXXX_02 and ran faster.

this was a quick teaser post I will talk about this technique (you may think dodgy) further in the future

I may also add test case if I have time.

FootNote: This fix was for immediate action. Gathering stats is not helping us so we needed to apply it. I am not the big fun of these changes and as you see they are undocumented please do it with asking Oracle as we are doing at the moment.

For more about the bug

Bug 8893626 – Index Skip Scan with selective index filter predicate has high cost [ID 8893626.8]

For more about the optimizer_fix_control
Init.ora Parameter “_FIX_CONTROL” [Hidden] Reference Note [ID 567171.1]

http://el-caro.blogspot.com/2007/06/fix-control.html

http://jonathanlewis.wordpress.com/2009/12/22/optimizer-features/

Update – 24/01/11 - We now have an official bug for our issue
Bug 11672675: INDEX SKIP SCAN IS USED INAPPROPR. AFTER UPGR. FROM 11.2.0.1 -> 11.2.0.2

Beware of Deferred Segment during 11.2.0.2 upgrade from 11.2.0.1

Filed under: Bugs — coskan @ 12:38 am

We recently upgraded one of our biggest databases to 11.2.0.2 from 11.2.0.1 due to the library cache mutex related bugs on 11.2.0.1. Since I wasn’t the one who did the upgrade I have nothing to say about the process but I was the on call DBA on the next day after the upgrade.

Users started to report the ORA-00600 for the statement below

delete from TABLE_1 where id=49;

ERROR at line 1:
ORA-00600: internal error code, arguments: [kkpo_rcinfo_defstg:objnotfound], [1002300], [], [], [], [], [], [], [], [], [], []

Checked for the error and found 3 bugs (9774817 10322768 10373381) related with the issue and not just none of them seems to have a workaround but all of them also says restore is the option which was the last choice for us (database server financial markets and we were close to the opening of markets ). It looks like we had some issues with deferred segments.

The table we try to delete from has got segments so it should not be the problem however it has got on delete trigger doing a merge on other tables and looks like one of those tables were causing the issue.

We first raised the Severity 1 ticket. while the engineer was reviewing the SR we decided to trace all the delete operation and see what is actually failing and once again 10046 trace revealed everything

When the error raised last operation was below

select /*+ all_rows */ count(1) from TABLE_2 where id=49

We run the statement manually, issue repeated again and when I check if the table has got any segment in dba_segments table it did not return anything.

Updated the SR with the new information. Support engineer asked us to try to regenerate the objects but he wasn’t hopeful. He suggested probably we needed to restore the db to before upgrade state.

I wasn’t as hopeful as ORacle support so to see which tables are affected I ran the output of the query below

select 'select count(*) from '||owner||'.'||table_name||' ;' from dba_tables where segment_created = 'NO';

All of the segmentless tables were raising the ORA-00600 so we decided to re-create them.

After recreation of all of the tables and their indexes I ran the same output again and none of the tables raised the error. Our workaround worked fine and we got away from restoring the DB and 2 more standbys which would be a nightmare just for tables which never used before. Interesting part is that we did not see the error on our QA db which I am not so sure what was the difference in terms of upgrade.

Hope you won’t hit this problem but better you check your deferred segments before and after 11.2.0.2 upgrade.

Note: I also check the LOB segments but we did not have any so no action taken for them.

select count(*) from dba_lobs where segment_created = 'NO';

January 5, 2011

What was wrong?

Filed under: Performance — coskan @ 1:01 pm

This is a tiny quiz like post, to see how people diagnose to sort the problem/problems here

This is when I check around 11:30Am on 27th (please open it from “view source button” to see better- button appears right hand side when you go over the code)

 SQL> @swact

    SID STATE   EVENT                                          SEQ# SEC_IN_STATE         P1         P2         P3 P1TRANSL                                   SQL_ID         CHN BLCKNG_SID BLCKNG_SID_S BLCKNG_INST
------- ------- ---------------------------------------- ---------- ------------ ---------- ---------- ---------- ------------------------------------------ ------------- ---- ---------- ------------ -----------
   1157 WAITING Streams AQ: waiting for messages in the       31559            0     169722 4.4438E+10          5                                                                          UNKNOWN
    390 WAITING db file scattered read                         8831            4        122    3402637          3                                            49xfrap6ytmsz    0            NO HOLDER
   1059 WAITING db file scattered read                         2575            0         18    3540987          2                                            6sy5x0dnyq7gp    1            NO HOLDER
    780 WAITING db file scattered read                        10509            0         54    3104110          3                                            903wwaubvn68k    4            NO HOLDER
    777 WAITING db file scattered read                        43294            0          8    3525609          3                                            96b6hrt8csw55    1            NO HOLDER
    393 WAITING db file scattered read                        53359            4        122    1311756          3                                            96b6hrt8csw55    1            NO HOLDER
    293 WAITING db file scattered read                         2563            0        182    2370423          3                                            96b6hrt8csw55    1            NO HOLDER
    584 WAITING db file sequential read                        8068            0        116    2224706          1                                            1hx317q49q07d    1            NO HOLDER
    487 WAITING db file sequential read                        6848            0         98    3399221          1                                            6ug9z3tm0udpa    0            NO HOLDER
    297 WAITING db file sequential read                        1997            0         12    3694453          1                                            903wwaubvn68k    5            NO HOLDER
    203 WAITING db file sequential read                       57138            0        137    3774888          1                                            903wwaubvn68k    4            NO HOLDER
   1068 WAITING db file sequential read                       55082            0        180     457872          1                                            92qxw78kqu645    0            NO HOLDER
    102 WAITING db file sequential read                       15928            0         18    3421028          1                                            96b6hrt8csw55    1            NO HOLDER
   1161 WAITING db file sequential read                       50477            0         24    3597877          1                                            96b6hrt8csw55    1            NO HOLDER
    586 WAITING db file sequential read                       30187            0         99    2827261          1                                            96b6hrt8csw55    1            NO HOLDER
   1351 WAITING db file sequential read                       36501            0        143    3528249          1                                            96b6hrt8csw55    1            NO HOLDER
   1061 WAITING db file sequential read                       14914            0        176    2339005          1                                            96b6hrt8csw55    1            NO HOLDER
   1162 WAITING db file sequential read                       34251            0        182    1609635          1                                            96b6hrt8csw55    1            NO HOLDER
    580 WAITING db file sequential read                       59341            0        182    1736561          1                                            96b6hrt8csw55    1            NO HOLDER
   1255 WAITING db file sequential read                       14584            0        182    2002050          1                                            96b6hrt8csw55    1            NO HOLDER
    292 WAITING db file sequential read                       12400            0        182    2728806          1                                            96b6hrt8csw55    1            NO HOLDER
   1451 WAITING db file sequential read                         743            0        182    3028810          1                                            96b6hrt8csw55    1            NO HOLDER
    106 WAITING db file sequential read                       60750            0        183    1701508          1                                            96b6hrt8csw55    1            NO HOLDER
     10 WAITING db file sequential read                       55193            0        184    1736937          1                                            96b6hrt8csw55    1            NO HOLDER
      9 WAITING db file sequential read                       10210            0        184    2309535          1                                            96b6hrt8csw55    1            NO HOLDER
    488 WAITING db file sequential read                       64865            0        184    2343479          1                                            96b6hrt8csw55    1            NO HOLDER
    391 WAITING db file sequential read                       64588            0          4    1555731          1                                            grh2sp5vv6p52    1            NO HOLDER
    871 WAITING db file sequential read                         954            0         24    3316869          1                                            grh2sp5vv6p52    1            NO HOLDER
    774 WAITING db file sequential read                       11105            0         24    3398637          1                                            grh2sp5vv6p52    1            NO HOLDER
   1446 WAITING db file sequential read                       41035            0        116    2763511          1                                            grh2sp5vv6p52    0            NO HOLDER
      7 WAITING db file sequential read                       41212            0        149    3192125          1                                            grh2sp5vv6p52    0            NO HOLDER
      5 WAITING db file sequential read                       52224            0        153    2657271          1                                            grh2sp5vv6p52    0            NO HOLDER
    394 WAITING db file sequential read                       17441            0        180    2937987          1                                            grh2sp5vv6p52    1            NO HOLDER
    200 WAITING db file sequential read                        4817            0        184    3616064          1                                            grh2sp5vv6p52    1            NO HOLDER
    779 WAITING direct path read                              37544            4        122     824944         16                                            49wv7fcafp592    0            UNKNOWN
    677 WAITING direct path read                              48106            4        122     824960         16                                            49wv7fcafp592    0            UNKNOWN
    582 WAITING direct path read                              62850            4        122     825520         16                                            49wv7fcafp592    0            UNKNOWN
   1256 WAITING direct path read                              21726            4        122    1141296         16                                            49wv7fcafp592    0            UNKNOWN
    392 WAITING direct path read                              52383            4        122    1141312         16                                            49wv7fcafp592    0            UNKNOWN
    589 WAITING direct path read                              57288            4        122     477936         16                                            6kbpsc2jb91dq    1            UNKNOWN
    204 WAITING enq: KO - fast object checkpoint              27274         3140 1263468550      65650          1 0x4B4F0006: KO mode6                       0qvw20ptvsq4b    1       1249 VALID         ##########
    301 WAITING enq: KO - fast object checkpoint              63459         8232 1263468550      65667          1 0x4B4F0006: KO mode6                       1t4r0r70xg5nw    0       1249 VALID         ##########
   1259 WAITING enq: KO - fast object checkpoint               4170          594 1263468550      65661          1 0x4B4F0006: KO mode6                       49wv7fcafp592    0       1249 VALID         ##########
   1258 WAITING enq: KO - fast object checkpoint               1200          594 1263468550      65677          1 0x4B4F0006: KO mode6                       49wv7fcafp592    0       1249 VALID         ##########
    684 WAITING enq: TX - row lock contention                 32955       146961 1415053318    1703962    7965635 0x54580006: TX mode6                       903wwaubvn68k    4       1256 VALID         ##########
    104 WAITING enq: TX - row lock contention                 60635       174744 1415053318    2686999    2493927 0x54580006: TX mode6                       903wwaubvn68k    2       1259 VALID         ##########
   1357 WAITING enq: TX - row lock contention                  1018        15106 1415053318    2949135    1686270 0x54580006: TX mode6                       903wwaubvn68k    5        297 VALID         ##########
   1450 WAITING enq: TX - row lock contention                    34       141454 1415053318    3014687    1597677 0x54580006: TX mode6                       903wwaubvn68k    1       1067 VALID         ##########
   1444 WAITING enq: TX - row lock contention                 12087       135239 1415053318    3473432    1523820 0x54580006: TX mode6                       903wwaubvn68k    4        779 VALID         ##########
   1454 WAITING enq: TX - row lock contention                 34927          799 1415053318    1441817   14075933 0x54580006: TX mode6                       drjnqxby1927s    0         12 VALID         ##########
    964 WAITING free buffer waits                             15050            4         26     684518         47                                            1ayvhx1yt4zxp    0        961 VALID         ##########
    103 WAITING free buffer waits                             50435           53        116    2224095         43                                            1hx317q49q07d    0        961 VALID         ##########
    195 WAITING free buffer waits                             37827           15        116    2224095         43                                            1hx317q49q07d    1        961 VALID         ##########
    496 WAITING free buffer waits                              4599           53        116    2224095         43                                            1hx317q49q07d    0        961 VALID         ##########
    678 WAITING free buffer waits                             30372           53        116    2224100         43                                            1hx317q49q07d    1        961 VALID         ##########
   1160 WAITING free buffer waits                             12865           53        116    2224100         43                                            1hx317q49q07d    1        961 VALID         ##########
    874 WAITING free buffer waits                              1391           10        116    2224100         45                                            1hx317q49q07d    1        961 VALID         ##########
    683 WAITING free buffer waits                             64898           20        116    2224515         47                                            1hx317q49q07d    1        961 VALID         ##########
    490 WAITING free buffer waits                             61840            9        116    2224565         45                                            1hx317q49q07d    1        961 VALID         ##########
    295 WAITING free buffer waits                             58320            9        116    2224565         45                                            1hx317q49q07d    1        961 VALID         ##########
    194 WAITING free buffer waits                             27899            9        116    2224565         46                                            1hx317q49q07d    1       1057 VALID         ##########
    399 WAITING free buffer waits                             46190            4        116    3431484         46                                            49wv7fcafp592    0       1057 VALID         ##########
      3 WAITING free buffer waits                             28122           64        185    2793836         43                                            4wztt7u8md4f5    0        961 VALID         ##########
     98 WAITING free buffer waits                             10526           20        186    3286834         47                                            4wztt7u8md4f5    0        961 VALID         ##########
   1154 WAITING free buffer waits                             28834           10        188    2931858         43                                            4wztt7u8md4f5    0        961 VALID         ##########
   1155 WAITING free buffer waits                             22844            0        116    3593900         43                                            6sy5x0dnyq7gp    1        961 VALID         ##########
    870 WAITING free buffer waits                             28946           14         18    3925826         43                                            903wwaubvn68k    4        961 VALID         ##########
   1067 WAITING free buffer waits                             29816           20        181    3274463         43                                            903wwaubvn68k    1        961 VALID         ##########
    681 WAITING free buffer waits                             35443            0         21    3478189         43                                            96b6hrt8csw55    1        961 VALID         ##########
     12 WAITING free buffer waits                              8879            2        168      46071         35                                            drjnqxby1927s    0        961 VALID         ##########
   1165 WAITING free buffer waits                             11974            0         99    3293378         42                                            gj05bqfb8sgda    0       1057 VALID         ##########
   1158 WAITING free buffer waits                             60839           14        153    3876852         33                                            grh2sp5vv6p52    0        961 VALID         ##########
    491 WAITING free buffer waits                             49412           24        122    3402617         47                                                                      961 VALID         ##########
    300 WAITING free buffer waits                             53971           20        122    3402618         47                                                                      961 VALID         ##########
   1448 WAITING read by other session                         53882            0          8    3525609          1 data block  obj=TABLE_XXXXXXX type=TABLE  96b6hrt8csw55    1        777 VALID         ##########
                                                                                                                  SUBPARTITION

    873 WAITING read by other session                         44573            0        184    1736937          1 data block  obj=TABLE_XXXXXXX type=TABLE  96b6hrt8csw55    1         10 VALID         ##########
                                                                                                                  SUBPARTITION

   1442 WAITING write complete waits                          18271           10         95      10722          0                                            0dhchmc8q926g    0        961 VALID         ##########
    778 WORKING On CPU / runqueue                             32331            0 1413697536          1          0                                            dgcp1b9y4h89a    1            NOT IN WAIT

78 rows selected.


Questions :

1- What would you check first ?

2- What would you check for free-buffer event ?

3- What might be wrong for free buffer event for me to get the picture below ?

 


This is free buffer events graph when I sorted that event only around 12:30  on 27th ( I only show graph of free buffer events because our problem was different which was caused by a missing index on the main table which also caused a free buffer waits after the problem sorted but it is not the point of this topic so please ignore for the 28th :) )

 

Update 18:44 05-01-11: Think about this system as brand new system for you. You only knew main 500GB table partitioned by dbms_redefinition and partitioning finished. You got call that everything is slow and the main DBA was on holiday.

Update 10:46 07-01-11 I got very impressive and very interesting answers. I really like Charles way of thinking and Radoslavs approach.

When it comes to what I did, I checked what session 961 and 1057 doing

here is what I see when I checked 961 and 1057

SQL> @usid 961

 SID             PROGRAM              SPID      LASTCALL STATUS
 --------------  -------------------- ------------------ --------
  '961,1'        (DBW0)               26636       255137 ACTIVE
                                 


SQL> @usid 1057

 SID             PROGRAM              SPID        LASTCALL STATUS
 --------------  -------------------- --------  ---------- --------
  '1057,1'       (DBW1)               26638         255143 ACTIVE
                

I saw dbwriter then I decided to do another check.

I already did a research on free buffer wait event before and as doc says it could be that DBWR could not catch up writing the dirty buffers to disk.

Because I am completely new to this system I could not just assume system is a good design.

SQL> show parameter io

NAME                                 TYPE        VALUE
------------------------------------ ----------- ----------------------------------------------------------------------------------------------------
O7_DICTIONARY_ACCESSIBILITY          boolean     FALSE
audit_sys_operations                 boolean     FALSE
backup_tape_io_slaves                boolean     FALSE
cell_offload_compaction              string      ADAPTIVE
cell_offload_decryption              boolean     TRUE
cursor_bind_capture_destination      string      memory+disk
db_flashback_retention_target        integer     1440
dbwr_io_slaves                       integer     0
deferred_segment_creation            boolean     TRUE
disk_asynch_io                       boolean     TRUE
fast_start_io_target                 integer     0
fileio_network_adapters              string
filesystemio_options                 string      directio
java_max_sessionspace_size           integer     0
java_soft_sessionspace_limit         integer     0
license_max_sessions                 integer     0
license_sessions_warning             integer     0
parallel_execution_message_size      integer     16384
parallel_io_cap_enabled              boolean     FALSE
replication_dependency_tracking      boolean     TRUE
resource_manager_cpu_allocation      integer     16
result_cache_remote_expiration       integer     0
sec_protocol_error_further_action    string      CONTINUE
sec_protocol_error_trace_action      string      TRACE
session_cached_cursors               integer     50
session_max_open_files               integer     10
sessions                             integer     1536
shared_server_sessions               integer
star_transformation_enabled          string      FALSE
tape_asynch_io                       boolean     TRUE
transactions                         integer     1689
transactions_per_rollback_segment    integer     5
undo_retention                       integer     10800

Do you see something wrong with the parameters ?

filesystemio_options string directio
disk_asynch_io boolean TRUE

and number of dbwriters are 2 and this is asnych i/o supported linux system

I asked business to change the parameter filesystemio_options to SETALL followed by outage. Since it was qa they accepted to do that and we restarted.

After the restart no more free buffer waits left.

 
SQL> @swact

    SID STATE   EVENT                                          SEQ# SEC_IN_STATE         P1         P2         P3 P1TRANSL                                   SQL_ID         CHN BLCKNG_SID BLCKNG_SID_S BLCKNG_INST
------- ------- ---------------------------------------- ---------- ------------ ---------- ---------- ---------- ------------------------------------------ ------------- ---- ---------- ------------ -----------
    394 WAITING PX Deq: Execute Reply                         20003            9        200          5          0                                            dtz7d985utg6z    0       1063 VALID         ##########
    200 WAITING PX Deq: Execution Msg                             4          110  268566527         56 4.4291E+10                                            dtz7d985utg6z    0            UNKNOWN
   1259 WAITING PX Deq: Execution Msg                             3          110  268566527         56 4.4291E+10                                            dtz7d985utg6z    0            UNKNOWN
    493 WAITING PX Deq: Execution Msg                             4          110  268566527         56 4.4291E+10                                            dtz7d985utg6z    0            UNKNOWN
    587 WAITING PX Deq: Execution Msg                             3          110  268566527         56 4.4291E+10                                            dtz7d985utg6z    0            UNKNOWN
    297 WAITING PX Deq: Execution Msg                             7          110  268566527         56 4.4291E+10                                            dtz7d985utg6z    0            UNKNOWN
     14 WAITING PX Deq: Execution Msg                             3          110  268566527         56 4.4291E+10                                            dtz7d985utg6z    0            UNKNOWN
    684 WAITING PX Deq: Execution Msg                             6          110  268566527         56 4.4291E+10                                            dtz7d985utg6z    0            UNKNOWN
   1353 WAITING PX Deq: Execution Msg                             4          110  268566527         56 4.4291E+10                                            dtz7d985utg6z    0            UNKNOWN
   1450 WAITING PX Deq: Execution Msg                             5          110  268566527         56 4.4291E+10                                            dtz7d985utg6z    0            UNKNOWN
    204 WAITING PX Deq: Execution Msg                             3          110  268566527         56 4.4291E+10                                            dtz7d985utg6z    0            UNKNOWN
    398 WAITING PX Deq: Execution Msg                             4          110  268566527         56 4.4291E+10                                            dtz7d985utg6z    0            UNKNOWN
    107 WAITING PX Deq: Execution Msg                             5          110  268566527         56 4.4291E+10                                            dtz7d985utg6z    0            UNKNOWN
   1062 WAITING Streams AQ: waiting for messages in the        8517            4     169722 4.3499E+10          5                                                                          UNKNOWN
    291 WAITING Streams AQ: waiting for messages in the        1399            4     847866 4.3499E+10        120                                                                          UNKNOWN
    388 WAITING db file scattered read                        35689            0          8    3290683         14                                            1hx317q49q07d    0            NO HOLDER
      5 WAITING db file scattered read                        55938            1          8    3472309         16                                            1hx317q49q07d    0            NO HOLDER
    776 WAITING db file scattered read                        47950            0         12    3240101         16                                            1hx317q49q07d    0            NO HOLDER
    775 WAITING db file scattered read                        59251            1         78    3408813         16                                            1hx317q49q07d    0            NO HOLDER
    198 WAITING db file scattered read                          944            1         84    3308877         16                                            1hx317q49q07d    1            NO HOLDER
   1252 WAITING db file scattered read                         2141            0        110    3330992          3                                            1hx317q49q07d    0            NO HOLDER
    967 WAITING db file scattered read                        15594            1        116    2182344          8                                            1hx317q49q07d    0            NO HOLDER
      6 WAITING db file scattered read                        48153            1        116    2220207          2                                            1hx317q49q07d    0            NO HOLDER
    486 WAITING db file scattered read                        45281            1        122    2126792         16                                            1hx317q49q07d    0            NO HOLDER
   1065 WAITING db file scattered read                        51433            1        136    3369917         16                                            1hx317q49q07d    0            NO HOLDER
    871 WAITING db file scattered read                         3933            1        146    3731624         16                                            1hx317q49q07d    0            NO HOLDER
    295 WAITING db file scattered read                        47880            0        153    1968132         16                                            1hx317q49q07d    0            NO HOLDER
   1060 WAITING db file scattered read                        41096            0        138    3568753         16                                            6sy5x0dnyq7gp    0            NO HOLDER
   1156 WAITING db file scattered read                        18820            2        146    3510936         16                                            6sy5x0dnyq7gp    0            NO HOLDER
   1164 WAITING db file scattered read                          537            0        102    3364814          2                                            6ug9z3tm0udpa    0            NO HOLDER
   1354 WAITING db file scattered read                         5085            0         12    2617077         16                                            96b6hrt8csw55    7            NO HOLDER
     13 WAITING db file scattered read                         1911            0         18     840859         16                                            96b6hrt8csw55    7            NO HOLDER
   1351 WAITING db file scattered read                        20606            1         21    3732633         16                                            96b6hrt8csw55    5            NO HOLDER
    872 WAITING db file scattered read                        62586            1         29    3725313         16                                            96b6hrt8csw55    6            NO HOLDER
    494 WAITING db file scattered read                        48400            1        108    3670313         16                                            96b6hrt8csw55    7            NO HOLDER
    389 WAITING db file scattered read                        34973            1        109    3891273         16                                            96b6hrt8csw55    4            NO HOLDER
    290 WAITING db file scattered read                        63299            1        116    2766680         16                                            96b6hrt8csw55    3            NO HOLDER
    102 WAITING db file scattered read                        13642            1        116    3749032         16                                            96b6hrt8csw55    2            NO HOLDER
   1162 WAITING db file scattered read                         4001            0        120     897310          6                                            96b6hrt8csw55    7            NO HOLDER
    586 WAITING db file scattered read                        12395            1        126    3309519         16                                            96b6hrt8csw55    7            NO HOLDER
    397 WAITING db file scattered read                          227            0        136    1142460          3                                            96b6hrt8csw55    7            NO HOLDER
    676 WAITING db file scattered read                         6794            0        136    2014799          3                                            96b6hrt8csw55    7            NO HOLDER
    582 WAITING db file scattered read                        28366            1        176    1541000         16                                            96b6hrt8csw55    1            NO HOLDER
      3 WAITING db file scattered read                        42306            1        177    2842776         16                                            96b6hrt8csw55    0            NO HOLDER
    683 WAITING db file scattered read                        61960            1        181     804168         16                                            96b6hrt8csw55    0            NO HOLDER
   1352 WAITING db file scattered read                         5107            0          4    3380200         14                                            amhsjrzs5hyg5    0            NO HOLDER
   1449 WAITING db file scattered read                         1108            1        143    2164525         16                                            amhsjrzs5hyg5    0            NO HOLDER
    103 WAITING db file scattered read                         3890            0        149    2324484         16                                            amhsjrzs5hyg5    0            NO HOLDER
      8 WAITING db file scattered read                        13835            1        137    2316749         16                                            bcftaq4qw1ur7    0            NO HOLDER
   1254 WAITING db file scattered read                        61829            1        177     405028         16                                            bcftaq4qw1ur7    0            NO HOLDER
    490 WAITING db file scattered read                        42588            1        183     816616         16                                            bcftaq4qw1ur7    0            NO HOLDER
    681 WAITING db file scattered read                        39165            1        102    3670249         16                                            grh2sp5vv6p52    0            NO HOLDER
    583 WAITING db file scattered read                        44055            1        137    2171469         16                                            grh2sp5vv6p52    0            NO HOLDER
   1257 WAITING db file scattered read                        55597            1        176    3778728         16                                            grh2sp5vv6p52    0            NO HOLDER
   1444 WAITING db file scattered read                        41804            1        181    2407576         16                                            grh2sp5vv6p52    0            NO HOLDER
    488 WAITING db file scattered read                          169            1        182    1705576         16                                            grh2sp5vv6p52    0            NO HOLDER
    392 WAITING db file scattered read                        16649            1        135    3641393         16                                                                          NO HOLDER
    197 WAITING db file sequential read                       12387            1        124     513458          1                                            0dhchmc8q926g    0            NO HOLDER
    964 WAITING db file sequential read                         676            1        146     848005          1                                            5cusvg17sxdmg    0            NO HOLDER
   1063 WAITING db file sequential read                        3840            0        102    3840206          1                                            dtz7d985utg6z    0            NO HOLDER
    777 WAITING db file sequential read                         698            0          4    3689548          1                                            gj05bqfb8sgda    0            NO HOLDER
   1253 WAITING direct path read                              58341            1        136    3460480         16                                            49wv7fcafp592    0            UNKNOWN
   1161 WAITING direct path read                                367            0          4    3478432         16                                            dtz7d985utg6z    0            UNKNOWN
   1451 WAITING direct path read                                815            1         12    3331904         16                                            dtz7d985utg6z    0            UNKNOWN
    782 WAITING direct path read                                334            1         29    3472256         16                                            dtz7d985utg6z    0            UNKNOWN
    202 WAITING direct path read                                365            1         99    2874528         16                                            dtz7d985utg6z    0            UNKNOWN
   1260 WAITING direct path read                                461            0        126    3345856         16                                            dtz7d985utg6z    0            UNKNOWN
    873 WAITING direct path read                                734            1        135    3370016         16                                            dtz7d985utg6z    0            UNKNOWN
     11 WAITING direct path read                                807            0        136    3426896         16                                            dtz7d985utg6z    0            UNKNOWN
   1067 WAITING direct path read                                718            2        146    2682512         16                                            dtz7d985utg6z    0            UNKNOWN
    778 WAITING direct path read                                558            1        153    1912836         12                                            dtz7d985utg6z    0            UNKNOWN
    875 WAITING direct path read                                349            0        181    1457568         16                                            dtz7d985utg6z    0            UNKNOWN
    292 WAITING enq: KO - fast object checkpoint              59339         8529 1263468550      65619          1 0x4B4F0006: KO mode6                                                1249 VALID         ##########
   1058 WAITING read by other session                          2358            0         12    2617077          1 data block  obj=TABLE_XXX type=TABLE	     96b6hrt8csw55    7       1354 VALID         ##########

Was free buffer waits our problem ? Obviously not :) In my opinion and understanding Our real problem which was missing index, caused pressure in buffer cache and revealed this wrong parameter setting on the system.

FYI: The secondary free buffer waits on 28th was caused by attempt to create the index in restricted mode with parallel 10 to sort the real problem which revealed these wrong setting.

I think I did not ask the question right and should have given more clues. Hope next reader challenge will be more clear :)

January 2, 2011

2010 in review from wordpress

Filed under: Basics — coskan @ 10:22 am

–Below is the mail I got from wordpress explaining how this blog performed in  2010 . Thank you all for visiting

 

 

The stats helper monkeys at WordPress.com mulled over how this blog did in 2010, and here’s a high level summary of its overall blog health:

Healthy blog!

The Blog-Health-o-Meter™ reads Wow.

Crunchy numbers

Featured image

The Louvre Museum has 8.5 million visitors per year. This blog was viewed about 140,000 times in 2010. If it were an exhibit at The Louvre Museum, it would take 6 days for that many people to see it.

 

In 2010, there were 27 new posts, growing the total archive of this blog to 145 posts. There were 13 pictures uploaded, taking up a total of 449kb. That’s about a picture per month.

The busiest day of the year was February 3rd with 731 views. The most popular post that day was Working with statspack-part-1a-Diagnosis.

Where did they come from?

The top referring sites in 2010 were blog.tanelpoder.com, forums.oracle.com, google.co.in, google.com, and pythian.com.

Some visitors came searching, mostly for io exception: the network adapter could not establish the connection, the network adapter could not establish the connection, and the network adapter could not establish the connection oracle.

Attractions in 2010

These are the posts and pages that got the most views in 2010.

1

Working with statspack-part-1a-Diagnosis January 2010
14 comments

2

Io Exception: the network adapter could not establish the connection (Enterprise Manager) April 2007
19 comments

3

ORA-01031: insufficient privileges April 2007
16 comments

4

Setting , Resetting/Unsetting Database Parameters March 2007
3 comments

5

Changing the Current Schema March 2007
1 comment

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