Coskan’s Approach to Oracle

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

December 29, 2010

How to monitor services on 11GR2 ?

Filed under: Monitoring, RAC — coskan @ 8:10 pm

It is very important to have our services run on the preferred nodes for the stability of our system (as long as all nodes are available)  and we sometimes see some of our services move between nodes without any good reason on 11GR2 grid. It was a big shame we discover it after business realizes the situation so we decided to have a check on service availability. At first I think about using DB to check the info but oracle does not keep the preferred node information in the DB itself :( remaining option is to use srvctl output which means coding needed. Time was limited to write it from scratch with  my coding coding speed so  I asked the question on Oracle-L and get a very good response from Yong Huang . His script was written in perl and running well on 10G and 11GR1 but not giving the expected results on our 11GR2 cluster,  for this reason, I modified the script a bit to use 11GR2 output (did I mention I’m better modifying codes than writing them :) ).

Below is the actual perl script to check the service availability.
Nothing rocket science here , It first gets the service names from crs_stat (I know it is deprecated please do not mention ) and in a for loop it checks the output if srvctl config and srvctl status for the services and than mails the problem services in a single mail.

We are calling perl script in a bash script (bottom of the page) which could also be optimized to run everything in the perl and I am again lazy not doing it and I find current way easier to move it between servers. only tiny bash script needs to be modified. I configure it to run every hour and job is done.

I hope it helps somebody. Thank you very much to Yong for sharing his work with me.

—Actual Script

#!/usr/bin/perl -w
# Modifier = Coskan Gundogar (original script is from YONG HUANG)
# Purpose = checking if services are running on the right node or not
# Maintenance needs
# CRS_HOME is hardcoded. Needs to be changed when CRS home changes
# Script needs to be called by a script which set env variables

$HOST=`hostname -a`;
$RECIPIENTEMAIL = 'yourdbagroup@yourdomain.com';
$ENV{PATH}="/usr/bin:/bin";
$CRS_HOME="/u01/crs/oracle/product/11.2.0/grid/bin/";
$ORASID=$ENV{'ORACLE_SID'};
$ORAHOME=$ENV{'ORACLE_HOME'};
$msg_run="";
$msg_none="";
$msg_all="";
$MSG_SUB = "";

                $_=`$CRS_HOME/crs_stat | awk -F. '/^NAME.*$ORASID.*\.svc\$/ {print \$3}' | sort | uniq`; #Get all service names (domain stripped) 11.2G

@line = split /\n/;

foreach (@line)
{
                 $service = "$_"; #Our domain names are guaranteed to be this.
                 $prefinst=`$ORAHOME/bin/srvctl config service -d $ORASID -s $service | grep -e Preferred | awk '{print \$3}'`;
                 $prefinst=~ s/\s+$//;
                 $statusline = `$ORAHOME/bin/srvctl status service -d $ORASID -s $service`;

                 if ($statusline =~ /is running on instance\(s\) (.*)$/)
                 {
                 $runinst = $1;
                 if ($prefinst ne $runinst)  # if service is running on the wrong node
                   {
                     $msg_avail = "Service \"$service \" preferred instance list differs from service running instance list: \n Preferred : $prefinst \n Running on: $runinst\n";
			         $msg_run=$msg_run . "\n" . $msg_avail;
		             $MSG_SUB = 'PRD-WARNING: ' . $HOST . ' DB: ' . $ORASID . ' Service Availability Problem'
		  }
                 }
                 else #This service is not even running.
                 {
		   			$msg_none=$msg_none . "\n" . $statusline . "\n";
					$MSG_SUB = "PRD-CRITICAL: " . $HOST . " DB: " . $ORASID . " Service Availability Problem"
		 }
                 @prefinst = ();
                 @runinst = ();
}
$msg_all=$msg_run . "\n" . $msg_none;

if ($msg_run ne "" or $msg_none ne "") {
system "mail -s \"$MSG_SUB\"  $RECIPIENTEMAIL <<EOF
$msg_all
EOF";
}
;

–Calling in an sh

export ORACLE_HOME=/u01/app/oracle/product/11.2.0/dbhome_2
export ORACLE_SID=DATABASE_NAME
export PATH=$PATH_BCK:$ORACLE_HOME/bin

/usr/bin/perl /home/oracle/bin/check_services.pl

Not : Problem with the actual script is when you set preferred and available node list in a non-ordered or reverse ordered way oracle uses the same order you gave in the output of srvctl config .Because The script compares srvctl config and srvctl status outputs it shows nodes are not running on the preferred node. I am sure this could be sorted but I prefer to set my services in the right order so I did not change anything to sort this problem.

December 6, 2010

Alert Log Monitoring script via ADRCI

Filed under: How To, Tips — coskan @ 4:47 pm

Before I start to write about the blog series in my mind which will be the base to my first presentation again in my mind, I would like to share simple alert log monitoring with adrci.

At first I was completely against Diagnostics Dest idea but after a bit of searching and learning new tips tricks of adrci command like I think I am a big fan of diagnostics dest. Below is the script I wrote to monitor alert log hourly and with a daily summary. Script is self explanatory, the only thing it does is gets ADRCI homes put them in a bash array and grep the ORA-, TNS- errors for the last hour or last day. It is not rocket since and it is based on a simple command which can also be added to your profiles as an alias.

--last day
adrci exec="set home ${adrci_home}; show alert -p \\\"message_text like '%ORA-%' and originating_timestamp > systimestamp-1\\\"" 
--last hour 
adrci exec="set home ${adrci_home}; show alert -p \\\"message_text like '%ORA-%' and originating_timestamp > systimestamp-1/24\\\"" 

I am pretty sure this could be shortened but I did not bother to shorten it so I leave it to your imagination:)

I did not add listener checks to hourly checks but to daily summary, because there can be many which will cause you to get mail every hour.

Good part of using ADRCI and hourly checks is you do not need to edit the file to get rid of the error because you will never see that alert again in the next hour slot.

Script will send the output to the files and read those files back to the mail content and I am sure there may be better way to do this.

Complete script

#################################################
###### ALERT LOG CHECKING VIA ADRCI #############
#################################################
# Author : Coskan Gundogar
# Version Date: 02/12/2010
# Usage :  
# To run for last 24 hours - ./check_alert.sh D
# To run for last hour - ./check_alert.sh 
# Edit variables below for moving between servers 
# Changes To the Script 
#

export ORACLE_SID=+ASM1
export ORACLE_HOME=/u01/crs/oracle/product/11.2.0/grid/
export PATH=$PATH:$ORACLE_HOME/bin
DAILY_LOG=/home/oracle/bin/alert_log_check_daily.txt
HOURLY_LOG=/home/oracle/bin/alert_log_check_hourly.txt
MAIL_SUBJ="PRD:WARNING HOST: " 
MAIL_RECIPIENT="your_dba_group@your_company.com"

HOST_NAME=`hostname -a`


if [ "$1" = "D" ]
then

		############################################
		###############DAILY CHECKS ################
		############DBMS AND ASM CHECK##############
		############################################

		adrci_homes=( $(adrci exec="show homes" | grep -e rdbms -e asm))

		echo '####################################################' > $DAILY_LOG 
		echo '####### ALERT LOG OUTPUT FOR LAST 24 HOURS #########' >> $DAILY_LOG
		echo '####################################################' >> $DAILY_LOG 
		echo ''  >> $DAILY_LOG 
		echo ''  >> $DAILY_LOG 
		echo ''  >> $DAILY_LOG 

		for adrci_home in ${adrci_homes[@]}
		do 
			echo $adrci_home' Alert Log' >> $DAILY_LOG 
			adrci exec="set home ${adrci_home}; show alert -p \\\"message_text like '%ORA-%' and originating_timestamp > systimestamp-1\\\"" -term >> $DAILY_LOG 
		done


		############################################
		############## DAILY CHECKS ################
		############# LISTENER  CHECK###############
		############################################


		adrci_lsnr_homes=( $(adrci exec="show homes" | grep -e tnslsnr))

		echo ''  >> $DAILY_LOG 
		echo ''  >> $DAILY_LOG 
		echo ''  >> $DAILY_LOG 
		echo '####################################################' >> $DAILY_LOG 
		echo '###### LISTENER LOG OUTPUT FOR LAST 24 Hours #######' >> $DAILY_LOG
		echo '####################################################' >> $DAILY_LOG 
		echo ''  >> $DAILY_LOG 
		echo ''  >> $DAILY_LOG 
		echo ''  >> $DAILY_LOG 


		for adrci_lsnr_home in ${adrci_lsnr_homes[@]}
		do 
			echo $adrci_lsnr_home' Listener Log' >> $DAILY_LOG 
			adrci exec="set home ${adrci_lsnr_home}; show alert -p \\\"message_text like '%TNS-%' and originating_timestamp > systimestamp-1\\\""  -term >> $DAILY_LOG 
		done
		

		num_errors=`grep -c -e 'TNS' -e 'ORA' $DAILY_LOG`
		if [ $num_errors != 0 ]
		then 
		MAIL_SUBJ=$MAIL_SUBJ$HOST_NAME" Errors Found in Daily Alert Summary"
		mailx -s "$MAIL_SUBJ" $MAIL_RECIPIENT  $HOURLY_LOG 
		echo ''  >> $HOURLY_LOG 
		echo ''  >> $HOURLY_LOG 
		echo '####################################################' >> $HOURLY_LOG 
		echo '######### ALERT LOG OUTPUT FOR LAST HOUR ###########' >> $HOURLY_LOG
		echo '####################################################' >> $HOURLY_LOG 
		echo ''  >> $HOURLY_LOG 
		echo ''  >> $HOURLY_LOG 
		echo ''  >> $HOURLY_LOG 

		for adrci_home in ${adrci_homes[@]}
		do 
			echo $adrci_home' Alert Log' >> $HOURLY_LOG 
			adrci exec="set home ${adrci_home}; show alert -p \\\"message_text like '%ORA-%' and originating_timestamp > systimestamp-1/24\\\"" -term >> $HOURLY_LOG 
		done


		num_errors=`grep -c -e 'TNS' -e 'ORA' $HOURLY_LOG`
		if [ $num_errors != 0 ]
		then 
		MAIL_SUBJ=$MAIL_SUBJ$HOST_NAME" Errors Found in Hourly Alert Summary"
		mailx -s "$MAIL_SUBJ" $MAIL_RECIPIENT < $HOURLY_LOG
		fi

fi

September 14, 2010

Easy/Fast Navigation with aliases in profiles

Filed under: Linux, Tips — coskan @ 8:45 pm

Because I am a lazy guy who wants to do everything fast I really like to have aliases in user profiles. When I login on a box different version of Oracle Homes and multiple ORacle databases on the same machine I feel naked without aliases. I am a guy who wants to tail alert log/any related log  while I am doing something and not having an alias for tailing not just slows me down it also makes me really annoyed in 5 seconds time. At current job I suffered for the first week and I immediately requested to have a “standard” profile and got acception from my manager and I wrote/modified the one below. Most of the ideas are taken from perfect blog entry of John Hallas, The use of functions in a .profile file . I needed to modify because we have 10G databases with 11GR2 GI for ASM and some more modifications for RAC. ( Probably most of you already realized that I am good with modifying a code but rubbish with my own, old habit from university never liked programming and needed to pass some classes:))

Here are the two functions I added to the profiles. First one (setsid) sets env settings of the database listed in /etc/oratab,  second one (showsid) shows the aliases you can use after you call setsid. Couple of things to bear in mind,  setsid assumes that you have $ORACLE_BASE which is hardcoded /u01/app/oracle in the script and it also assumes that you use ORACLE_SID for alert log directories. oradiag and ldiag aliases are default set because we use 11G diag home on all the boxes. You may also need to check ora_version variable it may not suit to your settings. (OFA is needed for everything run without modification)

SETSID

setsid ()
{
unset ORATAB
unset ORACLE_BASE
unset ORACLE_HOME
unset ORACLE_SID
ORACLE_BASE=/u01/app/oracle
ORATAB=/etc/oratab
if tty -s
then
        if [ -f $ORATAB ]
        then
                line_count=`cat $ORATAB | grep -v ^# | sed 's/:.*//' | wc -l`
                # check that the oratab file has some contents
                if [ $line_count -ge 1 ]
                        then
                        sid_selected=0
                        while [ $sid_selected -eq 0 ]
                        do
                                sid_available=0
                                for i in `cat $ORATAB | grep -v ^# | sed 's/:.*//'`
                                        do
                                        sid_available=`expr $sid_available + 1`
                                        sid[$sid_available]=$i
                                        done
                                # get the required SID
                                case ${SETSID_AUTO:-""} in
                                        YES) # Auto set use 1st entry
                                        sid_selected=1 ;;
                                        *)
                                        i=1
                                        while [ $i -le $sid_available ]
                                        do
                                                printf "%2d- %10s\n" $i ${sid[$i]}
                                                i=`expr $i + 1`
                                        done
                                        echo ""
                                        echo "Select the Oracle SID with given number [1]:"
                                        read entry
                                        if [ -n "$entry" ]
                                        then
                                                entry=`echo "$entry" | sed "s/[a-z,A-Z]//g"`
                                                if [ -n "$entry" ]
                                                then
                                                        entry=`expr $entry`
                                                        if [ $entry -ge 1 ] && [ $entry -le $sid_available ]
                                                        then
                                                                sid_selected=$entry
                                                        fi
                                                fi
                                                else
                                                sid_selected=1
                                        fi
                                esac
                        done
                        #
                        # SET ORACLE_SID
                        #
                        export ORACLE_SID=${sid[$sid_selected]}
                        echo "Your profile configured for $ORACLE_SID with information below:"
                        echo ""
			export PATH=/usr/kerberos/bin:/usr/local/bin:/bin:/usr/bin:/home/bin
                        unset LD_LIBRARY_PATH
                        ORAENV_ASK=NO
                        . oraenv
                        alias oh="cd ${ORACLE_HOME}"
                        ora_version=`echo $ORACLE_HOME | awk 'BEGIN {FS="/"} ; {print $6}' | awk 'BEGIN {FS="."} ; {print $1}'`
                        if [ $ora_version -lt 11 ]
			then
                        alias bdump="cd /u01/app/oracle/admin/${ORACLE_SID//[!A-Za-z]}/bdump"
                        alias talert="tail -f /u01/app/oracle/admin/${ORACLE_SID//[!A-Za-z]}/bdump/alert_${ORACLE_SID}.log"
			alias valert="view /u01/app/oracle/admin/${ORACLE_SID//[!A-Za-z]}/bdump/alert_${ORACLE_SID}.log"
                        fi
                        if [ $ora_version -ge  11 ]
                        then
			export ORACLE_UNQNAME=$ORACLE_SID
                        alias talert='tail -f $ORACLE_BASE/`adrci exec="show homes" | grep $ORACLE_SID`/trace/alert_${ORACLE_SID}.log'
			alias valert='view $ORACLE_BASE/`adrci exec="show homes" | grep $ORACLE_SID`/trace/alert_${ORACLE_SID}.log'
                        alias alasm='cd $ORACLE_BASE/`adrci exec="show homes" | grep ASM`/trace'
                        alias bdump='cd $ORACLE_BASE/`adrci exec="show homes" | grep $ORACLE_SID`/trace'
                        fi
                        alias pmon='ps -fu oracle | grep pmon | grep -v grep'
			alias tns='ps -fu oracle | grep tns | grep -v grep'
                        alias oradiag='cd $ORACLE_BASE/diag/'
			alias ldiag='cd $ORACLE_BASE/diag/tnslsnr/'
			unset ORAENV_ASK
                        echo
                        #
                        #GIVE MESSAGE
                        #
                        else
                        echo "No entries in $ORATAB. no environment set"
                fi
        fi
fi
}

SHOWSID

showsid()
{
echo ""
echo "ORACLE_SID=$ORACLE_SID"
echo "ORACLE_BASE=$ORACLE_BASE"
echo "ORACLE_HOME=$ORACLE_HOME"
echo "alias oh=cd ${ORACLE_HOME}"
echo "alias pmon='ps -fu oracle | grep pmon | grep -v grep'"
echo "alias tns='ps -fu oracle | grep tns | grep -v grep'"
ora_version=`echo $ORACLE_HOME | awk 'BEGIN {FS="/"} ; {print $6}' | awk 'BEGIN {FS="."} ; {print $1}'`
if [ $ora_version -ge  11 ]
then
echo "alias talert='tail -f $ORACLE_BASE/`adrci exec="show homes" | grep $ORACLE_SID`/trace/alert_${ORACLE_SID}.log'"
echo "alias valert='view $ORACLE_BASE/`adrci exec="show homes" | grep $ORACLE_SID`/trace/alert_${ORACLE_SID}.log'"
echo "alias bdump='cd $ORACLE_BASE/`adrci exec="show homes" | grep $ORACLE_SID`/trace'"
echo "alias alasm='cd $ORACLE_BASE/`adrci exec="show homes" | grep ASM`/trace'"
echo "alias ldiag='cd $ORACLE_BASE/diag/tnslsnr/'"
echo "alias oradiag='cd $ORACLE_BASE/diag/'"
fi
if [ $ora_version -lt 11 ]
then
echo "alias bdump=cd /u01/app/oracle/admin/${ORACLE_SID//[!A-Za-z]}/bdump"
echo "alias talert=tail -f \"/u01/app/oracle/admin/${ORACLE_SID//[!A-Za-z]}/bdump/alert_${ORACLE_SID}.log\""
echo "alias valert=\"view /u01/app/oracle/admin/${ORACLE_SID//[!A-Za-z]}/bdump/alert_${ORACLE_SID}.log\""
echo "alias ldiag='cd $ORACLE_BASE/diag/tnslsnr/'"
fi
echo ""
}

Usage : (no setting when showsid runs for the first time)

gundogar@SNOW:~#cosarac1
oracle@192.168.1.111's password:
Last login: Sun Sep 12 14:31:24 2010 from cosarac1.oel.com
[oracle@cosarac1 ~]$ showsid

ORACLE_SID=
ORACLE_BASE=
ORACLE_HOME=
alias oh=cd
alias pmon='ps -fu oracle | grep pmon | grep -v grep'
alias tns='ps -fu oracle | grep tns | grep -v grep'
-bash: [: -ge: unary operator expected
-bash: [: -lt: unary operator expected

[oracle@cosarac1 ~]$ setsid
 1-      +ASM1
 2-    oracos1

Select the Oracle SID with given number [1]:
2
Your profile configured for oracos1 with information below:

The Oracle base for ORACLE_HOME=/u01/app/oracle/product/10.2.0/db_1 is /u01/app/oracle/product/10.2.0/db_1

[oracle@cosarac1 ~]$ showsid

ORACLE_SID=oracos1
ORACLE_BASE=/u01/app/oracle/product/10.2.0/db_1
ORACLE_HOME=/u01/app/oracle/product/10.2.0/db_1
alias oh=cd /u01/app/oracle/product/10.2.0/db_1
alias pmon='ps -fu oracle | grep pmon | grep -v grep'
alias tns='ps -fu oracle | grep tns | grep -v grep'
alias bdump=cd /u01/app/oracle/admin/oracos/bdump
alias talert=tail -f "/u01/app/oracle/admin/oracos/bdump/alert_oracos1.log"
alias valert="view /u01/app/oracle/admin/oracos/bdump/alert_oracos1.log"

[oracle@cosarac1 ~]$ bdump
[oracle@cosarac1 bdump]$ pwd
/u01/app/oracle/admin/oracos/bdump
[oracle@cosarac1 bdump]$ pmpn
-bash: pmpn: command not found
[oracle@cosarac1 bdump]$ pmon
oracle    2860     1  0 Sep10 ?        00:00:21 asm_pmon_+ASM1
oracle   19925     1  0 Sep12 ?        00:00:12 ora_pmon_oracos1
[oracle@cosarac1 bdump]$ oh
[oracle@cosarac1 db_1]$ pwd
/u01/app/oracle/product/10.2.0/db_1
[oracle@cosarac1 db_1]$ tns
oracle    3287     1  0 Sep10 ?        00:00:05 /u01/crs/oracle/product/11.2.0/grid/bin/tnslsnr LISTENER_SCAN1 -inherit
oracle   26861     1  0 Sep13 ?        00:00:06 /u01/crs/oracle/product/11.2.0/grid/bin/tnslsnr LISTENER -inherit
[oracle@cosarac1 db_1]$ talert
Tue Sep 14 18:25:07 2010
Thread 1 advanced to log sequence 70 (LGWR switch)
  Current log# 2 seq# 70 mem# 0: +DATA/oracos/onlinelog/group_2.257.729388121
  Current log# 2 seq# 70 mem# 1: +FRA/oracos/onlinelog/group_2.258.729388123

Believe or not at the end of a year this settings will save lots of your time when you start using them .

If you have problems with formatting please contact me so I can send you the txt file.

September 11, 2010

“DBCA could not startup the ASM instance configured on this node” error for lower versions with 11GR2 GI

Filed under: RAC — coskan @ 9:14 am

Last 3 days ,I have been trying to have the toy environment at home, for 11GR2 upgrade project at work.

The challenge was building exactly same environment on virtual machine. Problem is that I did not built the environment at work so I had no idea about tricks which are not clear in doc.

The environment is;

Oracle 2 node RAC with 11GR2 clusterware July PSU with ASM storage

Database with 10.2.0.4.2  with no local listener.

I installed the grid with some minor problems which are not todays topic. Problems solved and grid was completely healthy.

I then installed 10.2.0.4 binaries pinned the nodes for lower version installation as documented in official installation doc like below from GI home


[root@cosarac1 ~]$
crsctl pin css -n cosarac1,cosarac2
[oracle@cosarac1 ~]$ olsnodes -t -n
cosarac1        1       Pinned
cosarac2        2       Pinned

And I ran dbca from 10.2.0.4  and when I chose storage as ASM I started to get “DBCA could not startup the ASM instance configured on this node. To proceed with the database creation using ASM, ASM instance needs to be up and running. Do you want to recreate ASM instance on this node?”  warning.

Checked if ASM is up and running and it was and also being listened by my default listener. So what was the problem ?

Google+otn forums is again the answer

Basically during the installation you need to link the listener.ora in oracle home to listener.ora in grid home

cd <10G_DB_HOME>/network/admin

ln –s <11G_GRID_HOME>/network/admin/endpoints_listener.ora listener.ora

After you create the link it, please do not expect that  it will  just work , because it won’t:)

You also need to have TNS_ADMIN env setting to make dbca work with ASM. (You don’t need to set it on both nodes you only need to set it in the session of the node you run dbca.)

export TNS_ADMIN=<10G_DB_HOME>/network/admin

There is also a bug and one off patch available (8288940) but because our environment did not have 10.2.0.4 home patched with that one of patch  (At office DB was installed before GI upgrade) I did not bother to install the patch when there is a beautiful easy peasy solution.

What I learnt from this  creating the same toy environment at home practice is that,  building a VM RAC following a guide is just 3-4 hours work (for this particular one I followed Tim Halls 11GR2 RAC installation Guide for RAC on Virtualbox )but once you change some of the things in the tutorial  you follow,  then you invite the trouble which is very teaching practice. I learned hell a lot just with this 2 node RAC installation.  Once you learn how to install a rac I suggest you to try to learn how to break a RAC installation :)

Next challenge is building the DR of the Same environment (not with RAC due to resource problem). Maybe I can find something to write about.

August 18, 2010

Session Snapper on duty

Filed under: Performance — coskan @ 11:52 am
I have joined another company 2 weeks ago and I immediately started  to enjoy of the active Oracle Environment.
It looks like  I really missed the action too much in last 3 years (Last company was a bit quite).
Because I am going to upgrade major systems to 11GR2 from 10GR2 I will be very busy but I hope I can write somethin.
Trying to keep up with blogroll report but no chance :(
Anyways today’s story does not need long paragraphs. Everything is self explanatory. (Because I did not write the tools I used here,  all credit can go to Tanel Poder and his scripts)
Long story short I got a call that system is slow and waiting on library cache lock. Here is the action I took (the script output is also available as text at the bottom)
######################################################
#####SESSION STATE WHEN I CHECK COUPLE OF TIMES#######
######################################################

DBA@CLONE1> @swact

    SID STATE   EVENT                                          SEQ# SEC_IN_STATE         P1         P2         P3 P1TRANSL                                   SQL_ID          CHILD_NO
------- ------- ---------------------------------------- ---------- ------------ ---------- ---------- ---------- ------------------------------------------ ------------- ----------
    698 WAITING DIAG idle wait                                  696          662          7          8          0                                            4tq4zndbtty5g          0
    897 WAITING Streams AQ: waiting for messages in the       64312            0       8560 1.2335E+10          5
   1047 WAITING Streams AQ: waiting for messages in the       15818            0     539956 1.2251E+10         10                                            ady0t9s6h5x5n          0
    732 WAITING cursor: pin S wait on X                       37240            0 2272359238 2.5469E+12 2.1475E+10                                            fwxq99y3r2wu6
    680 WAITING cursor: pin S wait on X                       30734            0 2272359238 2.5469E+12 2.1475E+10                                            fwxq99y3r2wu6
    926 WAITING cursor: pin S wait on X                       48363            0 2272359238 2.5469E+12 2.1475E+10                                            fwxq99y3r2wu6
    682 WAITING cursor: pin S wait on X                       38796            0 3849361425 3.4145E+12 2.1476E+10                                            7v63nkmkr160j
    906 WAITING cursor: pin S wait on X                       31566            0 3849361425 3.4145E+12 2.1476E+10                                            7v63nkmkr160j
   1037 WAITING cursor: pin S wait on X                         854            0 3849361425 3.4145E+12 2.1476E+10                                            7v63nkmkr160j
    612 WAITING jobq slave wait                                   1          271          0          0          0                                                                   0
   1053 WAITING library cache lock                             1474         4650 1.2269E+10 1.1683E+10        501                                            7xvut41x0dxj2          0
    774 WAITING library cache lock                               41         2866 1.2269E+10 1.1663E+10        301                                            9r5pb2sbs10v4          0
    593 WAITING library cache lock                            15936          834 1.2269E+10 1.1775E+10        301                                            fwxq99y3r2wu6
    979 WAITING library cache lock                              553         2646 1.2288E+10 1.1516E+10        301                                            a610tnjgas2xg          2
    613 WAITING library cache lock                              750         1131 1.2288E+10 1.1511E+10        301                                            gyg59d0f8hk1t          0
    961 WAITING library cache lock                            34638         2752 1.2305E+10 1.1518E+10        501                                            0000000000000          0
    914 WAITING library cache pin                               543          111 1.2300E+10 1.1665E+10        202                                            a610tnjgas2xg          2
   1061 WAITING wait for unread message on broadcast cha      30681            4 1.2239E+10 1.2221E+10          0                                            2b064ybzkwf1y          0
    760 WORKING On CPU / runqueue                               369            0 1413697536          1          0                                            3y2zzajvss71p          0
    795 WORKING On CPU / runqueue                             42057           75 1.1969E+10        215          0                                            b221muwskhmq6          0

20 rows selected.

#########################################################################
#### ONLY ONE SESSION IS RUNNING OTHER THAN MINE LETS SEE WHAT IS THE SQL PLAN for 795  ####
#########################################################################

DBA@CLONE1> @e3
Enter value for sql_id:  b221muwskhmq6
Enter value for child_number: 0

PLAN_TABLE_OUTPUT
-----------------------------------------------------------
SQL_ID:  b221muwskhmq6, child number: 0 cannot be found

######################################
######NO PLAN BUT WHAT IS THE SQL#####
######################################

DBA@CLONE1> @sqltext  b221muwskhmq6

no rows selected

######################################
###NO SQL IN CACHE MAYBE IN HISTORY###
######################################

DBA@CLONE1>  @h_sqltext b221muwskhmq6

no rows selected

DBA@CLONE1> l
  1* select sql_text from dba_hist_sqltext where sql_id='&1'

######################################
#######NO CHANCE- TIME TO SNAP########
######################################

DBA@CLONE1> @snapper ash,stats 50 1 795
Sampling...

-- Session Snapper v3.10 by Tanel Poder @ E2SN ( http://tech.e2sn.com )

----------------------------------------------------------------------------------------------------------------------
    SID, USERNAME  , TYPE, STATISTIC                               ,         DELTA, HDELTA/SEC,    %TIME, GRAPH
----------------------------------------------------------------------------------------------------------------------
    795, VALDATACAP, STAT, opened cursors cumulative               ,           210,       4.12,
    795, VALDATACAP, STAT, recursive calls                         ,          2856,         56,
    795, VALDATACAP, STAT, session logical reads                   ,          1344,      26.35,
    795, VALDATACAP, STAT, CPU used by this session                ,          4648,      91.14,
    795, VALDATACAP, STAT, concurrency wait time                   ,           337,       6.61,
    795, VALDATACAP, STAT, session pga memory                      ,       5111808,    100.23k,
    795, VALDATACAP, STAT, session pga memory max                  ,       5111808,    100.23k,
    795, VALDATACAP, STAT, global enqueue gets sync                ,            42,        .82,
    795, VALDATACAP, STAT, global enqueue releases                 ,            42,        .82,
    795, VALDATACAP, STAT, consistent gets                         ,          1344,      26.35,
    795, VALDATACAP, STAT, consistent gets from cache              ,          1344,      26.35,
    795, VALDATACAP, STAT, consistent gets - examination           ,           672,      13.18,
    795, VALDATACAP, STAT, calls to get snapshot scn: kcmgss       ,           378,       7.41,
    795, VALDATACAP, STAT, no work - consistent read gets          ,           672,      13.18,
    795, VALDATACAP, STAT, table fetch by rowid                    ,           546,      10.71,
    795, VALDATACAP, STAT, cluster key scans                       ,            84,       1.65,
    795, VALDATACAP, STAT, cluster key scan block gets             ,           210,       4.12,
    795, VALDATACAP, STAT, rows fetched via callback               ,           126,       2.47,
    795, VALDATACAP, STAT, index fetch by key                      ,           252,       4.94,
    795, VALDATACAP, STAT, index scans kdiixs1                     ,            42,        .82,
    795, VALDATACAP, STAT, sql area purged                         ,            42,        .82,
    795, VALDATACAP, STAT, session cursor cache hits               ,           378,       7.41,
    795, VALDATACAP, STAT, buffer is not pinned count              ,          1306,      25.61,
    795, VALDATACAP, STAT, parse time cpu                          ,             1,        .02,
    795, VALDATACAP, STAT, parse count (total)                     ,           379,       7.43,
    795, VALDATACAP, STAT, parse count (hard)                      ,            42,        .82,
    795, VALDATACAP, STAT, execute count                           ,           379,       7.43,
    795, VALDATACAP, STAT, sorts (memory)                          ,            42,        .82,
    795, VALDATACAP, STAT, sorts (rows)                            ,           126,       2.47,
    795, VALDATACAP, TIME, hard parse elapsed time                 ,      47918246,   939.57ms,    94.0%, |@@@@@@@@@@|
    795, VALDATACAP, TIME, parse time elapsed                      ,      47918246,   939.57ms,    94.0%, |@@@@@@@@@@|
    795, VALDATACAP, TIME, DB CPU                                  ,      44676472,   876.01ms,    87.6%, |@@@@@@@@@ |
    795, VALDATACAP, TIME, sql execute elapsed time                ,      47918246,   939.57ms,    94.0%, |@@@@@@@@@@|
    795, VALDATACAP, TIME, DB time                                 ,      47918246,   939.57ms,    94.0%, |@@@@@@@@@@|
    795, VALDATACAP, WAIT, latch: library cache                    ,       3370707,    66.09ms,     6.6%, |@         |
--  End of Stats snap 1, end=2010-08-18 11:28:06, seconds=51

-----------------------------------------------------------------------
Active% | SQL_ID          | EVENT                     | WAIT_CLASS
-----------------------------------------------------------------------
    94% | b221muwskhmq6   | ON CPU                    | ON CPU
     6% | b221muwskhmq6   | latch: library cache      | Concurrency

--  End of ASH snap 1, end=2010-08-18 11:28:06, seconds=50, samples_taken=100

##############################################################
#######HARD PARSE SOFT PARSE AND ON CPU ALL THE TIME ?########
##############################################################

######################################
#####SESSIONS ARE STILL WAITING#######
######################################

DBA@CLONE1> @swact

    SID STATE   EVENT                                          SEQ# SEC_IN_STATE         P1         P2         P3 P1TRANSL                                   SQLID             CHILD_NO
------- ------- ---------------------------------------- ---------- ------------ ---------- ---------- ---------- ------------------------------------------ --------------- ----------
    698 WAITING DIAG idle wait                                  731          151          7          8          0                                            4tq4zndbtty5g            0
    897 WAITING Streams AQ: waiting for messages in the       64728            2       8560 1.2335E+10          5
   1047 WAITING Streams AQ: waiting for messages in the       16512            3     539956 1.2251E+10         10                                            ady0t9s6h5x5n            0
    732 WAITING cursor: pin S wait on X                         692            0 2272359238 3.9771E+12 2.1475E+10                                            fwxq99y3r2wu6
    682 WAITING cursor: pin S wait on X                       34091            0 3849361425 3.4145E+12 2.1476E+10                                            7v63nkmkr160j
    906 WAITING cursor: pin S wait on X                       26951            0 3849361425 3.4145E+12 2.1476E+10                                            7v63nkmkr160j
   1037 WAITING cursor: pin S wait on X                       61795            0 3849361425 3.4145E+12 2.1476E+10                                            7v63nkmkr160j
    612 WAITING jobq slave wait                                   1          946          0          0          0                                                                     0
   1053 WAITING library cache lock                             1474         5325 1.2269E+10 1.1683E+10        501                                            7xvut41x0dxj2            0
    774 WAITING library cache lock                               41         3541 1.2269E+10 1.1663E+10        301                                            9r5pb2sbs10v4            0
    926 WAITING library cache lock                            42987            9 1.2269E+10 1.1689E+10        301                                            fwxq99y3r2wu6
    979 WAITING library cache lock                              553         3321 1.2288E+10 1.1516E+10        301                                            a610tnjgas2xg            2
    961 WAITING library cache lock                            34638         3427 1.2305E+10 1.1518E+10        501                                            0000000000000            0
   1061 WAITING wait for unread message on broadcast cha      30791            9 1.2239E+10 1.2221E+10          0                                            2b064ybzkwf1y            0
    760 WORKING On CPU / runqueue                               750            0 1413697536          1          0                                            3y2zzajvss71p            0
    795 WORKING On CPU / runqueue                             42061           67 1.1969E+10        215          0                                            b221muwskhmq6            0

######################################################################
#######GOT PERMISSION TO KILL THE SESSION AND I KILLED FROM OS########
######################################################################

-----KILL THE SESSION AND CHECK AGAIN

######################################
#####NO MORE LIBRARY CACHE LOCK#######
######################################

COSKANDBA@CLONE1> @swact

    SID STATE   EVENT                                          SEQ# SEC_IN_STATE         P1         P2         P3 P1TRANSL                                   SQLID             CHILD_NO
------- ------- ---------------------------------------- ---------- ------------ ---------- ---------- ---------- ------------------------------------------ --------------- ----------
    698 WAITING DIAG idle wait                                  733          122          7          8          0                                            4tq4zndbtty5g            0
   1053 WAITING PX Deq: Execute Reply                          1541            0        200          2          0                                            62gz6xzzrb8r3            0
    732 WAITING PX Deq: Execution Msg                             8            1  268566527          4          0                                                                     0
    774 WAITING PX Deq: Execution Msg                             8            1  268566527          4          0                                                                     0
    897 WAITING Streams AQ: waiting for messages in the       64880            1       8560 1.2335E+10          5
   1047 WAITING Streams AQ: waiting for messages in the       16720            5     539956 1.2251E+10         10                                            ady0t9s6h5x5n            0
    977 WAITING db file scattered read                          738            0        217    1214913         32                                                                     0
    926 WAITING db file scattered read                         1076            0        243    4114803         32                                                                     0
    612 WAITING jobq slave wait                                   1         1149          0          0          0                                                                     0
   1061 WAITING wait for unread message on broadcast cha      30826            1 1.2239E+10 1.2221E+10          0                                            2b064ybzkwf1y            0
    961 WORKING On CPU / runqueue                             45580            0 1230372869 2507953651  559265612                                            0000000000000            0
    760 WORKING On CPU / runqueue                               799            0 1413697536          1          0                                            3y2zzajvss71p            0

Cause of the problem :

It is caused because of a session whose application server was shut down but somehow it stuck on DB at parsing and continuously spinning on CPU and blocking others.

I wish I could see which sql it was running but no chance. App owner was not sure what it could be doing :(

Moral of the story :

Snapper is just so cool :)

Thanks again Tanel, you are a superstar.

For the ones who is loving OEM, The Performance  Graph is just like this but no chance to find what the session is doing from OEM (or I don’t know how to look)

Because of the formatting I think it is better to put a text output


The scripts used here are

Tanel Poders sw.sql for session waits   (swact.sql  is just to call it like @sw ‘select sid from v$session where status=”ACTIVE” and type<>”BACKGROUND”’)

Tanel Poders snapper.sql for snapping

e3.sql  is for gathering plan (SELECT * FROM table(DBMS_XPLAN.DISPLAY_CURSOR((‘&sql_id’),&child_number,’ALLSTATS LAST’));)

sqltext.sql  is for getting the sqltext (select sql_text from dba_hist_sqltext where sql_id=’&1′)

instead of e3 and sqltext.sql you can use Tanel Poders usql.sql :)

July 23, 2010

Blogroll Report 16/07/2010 – 23/07/2010

Filed under: Blogroll Report — coskan @ 3:17 pm

<—- Blogroll Report 09/07 /2010 – 16/07/2010

1-What is tablespace and disk level fragmentation?
Jonathan Lewis-Fragmentation-2

2-What is table level fragmentation?
Jonathan Lewis-Fragmentation-3

3-What is index level fragmentation?
Jonathan Lewis-Fragmentation-4

4-How to delete database file system when you hit “ORA-64007: invalid store specified” error.
Frits Hoogland-DBFS and ORA-64007: invalid store specified

5-Automated SQL*Loader control file generator
Charles Kim-Generate SQL*Loader Control File Script

6-How to unbind NICS on Unix to remove them from ifconfig -a output?
Dan Norris-unplumb (or unbinding) NICs on Linux

7-ASMCMD privileges with 11GR2
Neil Johnson-ASMCMD privileges in Grid Infrastructure

8-How does OEM Performance Tab uses ASH data to generate reports ?
Marcin Przepiorowski-OEM performance tab and Active Session History data.

9-I/O throughput vs IOPS
Martin Widlake-More Memory Meanderings – IOPS and Form Factors

10-How to read block header part of index block dump?
Richard Foote-Index Block Dump: Block Header Part I (Editions Of You)

11-Why does Oracle / CBO ignores your Hint?
Charles Hooper-Demonstration of Oracle “Ignoring” an Index Hint

12-How do you calculate the chance of loosing data with ASM mirroring? ASM disk partnership
Alex Fatkulin-ASM Mirroring and Disk Partnership

13-How to sort ora-0094 when using tablespaces tab with select catalog role?
Hector R Madrid-ORA-00942 Querying Tablespaces from Enterprise Manager

14-How does exadata storage indexes work?
Marc Fielding-Exadata’s Best Kept Secret: Storage Indexes

15-Operating system Tuning recommendations for using Oracle on Linux
Ronny Egner-Tuning Linux for Oracle

16-What is the meaning of V$DATABASE.CREATED column ? Is it DB creation or controlfile creation date ?
Hemant K Chitale-V$DATABASE.CREATED — is this the Database Creation timestamp ?

17-Oracle Data Dictionary and ASYNCH I/O
Frits Hoogland-Doing synchronous IO on ASM

18-Unexpected growth in size and not using of free space with ASSM
Nigel Noble-10gR2 – 11gR2, ASSM Space Management “Bug”

« Newer PostsOlder Posts »

The Silver is the New Black Theme Blog at WordPress.com.

Follow

Get every new post delivered to your Inbox.

Join 193 other followers