Coskan's Approach to Oracle

January 17, 2011

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';

Comments (1)

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

Comments (10)

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

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.

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

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

ORA-01031: insufficient privileges April 2007
16 comments

Setting , Resetting/Unsetting Database Parameters March 2007
3 comments

Changing the Current Schema March 2007
1 comment

Comments (1)

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.

Comments (2)

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

Comments (16)

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.

Comments (15)

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.

Comments (3)

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

Comments (11)

July 23, 2010

July 19, 2010

« Newer Posts — Older Posts »

	Elva on Reduce Transportable Tablespac…
	waveless waterbed ma… on Connect Role without Alter Ses…
	Lodge Lower price (H… on About Me
	Kathleen on About Me
	career objective exa… on About Me

Coskan’s Approach to Oracle

January 17, 2011

Beware of Deferred Segment during 11.2.0.2 upgrade from 11.2.0.1

January 5, 2011

What was wrong?

January 2, 2011

2010 in review from wordpress

Crunchy numbers

Where did they come from?

Attractions in 2010

December 29, 2010

How to monitor services on 11GR2 ?

December 6, 2010

Alert Log Monitoring script via ADRCI

September 14, 2010

Easy/Fast Navigation with aliases in profiles

September 11, 2010

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

August 18, 2010

Session Snapper on duty

July 23, 2010

July 19, 2010

Highlights

My Other Web Pages

Categories

Recent Comments

Archives

Recent Posts

Top Posts

Top Clicks

Top Rated

Blog Stats

Twitter Updates

Visitor Location

Email Subscription

Follow “Coskan's Approach to Oracle”

May 2013
M	T	W	T	F	S	S
« Apr
		1	2	3	4	5
6	7	8	9	10	11	12
13	14	15	16	17	18	19
20	21	22	23	24	25	26
27	28	29	30	31