SYSTEMSTATE DUMP: Shooting DB Hang, sqlplus Hang, self deadlock latch, PMON deadlock latch

One DB is hang. Try to login with "sqlplus / as sysdba" also fail, just hang there.

I use "-prelim" option to login and make a systemstate dump.

Below is the ass.awk output for systemstate dump:

System State 1
~~~~~~~~~~~~~~~~
1:
2:  0: waiting for 'pmon timer'    <---- PMON is fine at this moment
3:  0: waiting for 'rdbms ipc message'
4:  0: waiting for 'VKTM Logical Idle Wait'
5:  0: waiting for 'rdbms ipc message'
6:  0: waiting for 'DIAG idle wait'
7:  0: waiting for 'rdbms ipc message'
8:  0: waiting for 'DIAG idle wait'
9:  0: waiting for 'rdbms ipc message'
10: 0: waiting for 'rdbms ipc message'
11: 0: waiting for 'rdbms ipc message'
12: 0: waiting for 'rdbms ipc message'
13: 0: waiting for 'rdbms ipc message'
14: 0: waiting for 'rdbms ipc message'
15: 0: waiting for 'rdbms ipc message'
16: 0: waiting for 'rdbms ipc message'
17: 0: waiting for 'rdbms ipc message'
18: 0: waiting for 'rdbms ipc message'
19: 0: waiting for 'rdbms ipc message'
20: 0: waiting for 'rdbms ipc message'
21: 0: waiting for 'rdbms ipc message'
22: 0: waiting for 'rdbms ipc message'
23: 0: waiting for 'rdbms ipc message'
24: 0: waiting for 'rdbms ipc message'
25: 0: waiting for 'rdbms ipc message'
26: 0: waiting for 'rdbms ipc message'
27: 0: waiting for 'rdbms ipc message'
28: 0: waiting for 'rdbms ipc message'
29: 0: waiting for 'rdbms ipc message'
30: 0: waiting for 'rdbms ipc message'
31: 0: waiting for 'rdbms ipc message'
32: 0: waiting for 'smon timer'
33: 0: waiting for 'rdbms ipc message'
34: 0: waiting for 'latch free'        [Latch 60009fc8]
35: 0: waiting for 'rdbms ipc message'
36:                                    [Latch 60009fc8]
37: 0: waiting for 'enq: PV - syncstart'[Enqueue PV-00000000-00000000]
38:                                    [Latch 60009fc8]
39: 0: waiting for 'SQL*Net message from client'
40: 0: waiting for 'VKRM Idle'
41: 0: waiting for 'rdbms ipc message'
42: 0: waiting for 'rdbms ipc message'
43: 0: waiting for 'rdbms ipc message'
44: 0: waiting for 'Streams AQ: qmn coordinator idle wait'
45: 0: waiting for 'enq: PR - contention'[Enqueue PR-00000000-00000000]
46:                                    [Latch 60009fc8]
47: 0: waiting for 'Streams AQ: qmn slave idle wait'
48:                                    [Latch 60009fc8]
49: 0: waiting for 'SQL*Net message from client'
50:                                    [Latch 60009fc8]
51: 9: waited for 'Streams AQ: waiting for time management or cleanup tasks'
52: 0: waiting for 'SQL*Net message from client'
Blockers
~~~~~~~~

        Above is a list of all the processes. If they are waiting for a resource
        then it will be given in square brackets. Below is a summary of the
        waited upon resources, together with the holder of that resource.
        Notes:
        ~~~~~
         o A process id of '???' implies that the holder was not found in the
           systemstate.

                    Resource Holder State
              Latch 60009fc8    ??? Blocker
Enqueue PV-00000000-00000000    34: 34: is waiting for Latch 60009fc8
Enqueue PR-00000000-00000000    34: 34: is waiting for Latch 60009fc8

Object Names
~~~~~~~~~~~~
Latch 60009fc8   process allocation
Enqueue PV-00000000-00000000
Enqueue PR-00000000-00000000

Obviously the root blocker is latch: 60009fc8. But unluckily the systemstate dump don't have the infor that which session is holding the latch：

alpcispdb552[oracle]_pgbs> cat pgbs_diag_2254.trc|grep 60009fc8
      waiting for 60009fc8  process allocation level=7
        address=0x60009fc8, number=0x9, tries=0x0
          p1: 'address'=0x60009fc8
      waiting for 60009fc8  process allocation level=7
      waiting for 60009fc8  process allocation level=7
      waiting for 60009fc8  process allocation level=7
      waiting for 60009fc8  process allocation level=7
      waiting for 60009fc8  process allocation level=7

Then let's choose any one blocked process to check:

PROCESS 34: MMON
  ----------------------------------------
  SO: 0x1972e95a8, type: 2, owner: (nil), flag: INIT/-/-/0x00 if: 0x3 c: 0x3
   proc=0x1972e95a8, name=process, file=ksu.h LINE:12451, pg=0
  (process) Oracle pid:34, ser:1, calls cur/top: 0x189db28e8/0x19f52b748
            flags : (0x2) SYSTEM
            flags2: (0x20),  flags3: (0x0)
            intr error: 0, call error: 0, sess error: 0, txn error 0
            intr queue: empty
    ksudlp FALSE at location: 0
  (post info) last post received: 0 0 68
              last post received-location: kso2.h LINE:467 ID:ksoreq_reply
              last process to post me: 19f2ef058 165 0
              last post sent: 0 0 26
              last post sent-location: ksa2.h LINE:282 ID:ksasnd
              last process posted by me: 1982dec38 1 6
    (latch info) wait_event=0 bits=0
        Location from where call was made: ksu.h LINE:13713 ID:ksu_unreserve:
      waiting for 60009fc8  process allocation level=7
        Location from where latch is held: ksu.h LINE:13677 ID:ksuapc: proc addr
        Context saved from call: 6965578584
        state=busy [holder orapid=0] wlstate=free [value=0]
          gotten 57043 times wait, failed first 54 sleeps 0
          gotten 26253 times nowait, failed: 1
        possible holder pid = 0 ospid=26755
    Process Group: DEFAULT, pseudo proc: 0x19734a4b8
    O/S info: user: oracle, term: UNKNOWN, ospid: 2339
    OSD pid info: Unix process pid: 2339, image: oracle@server552(MMON)

Above blocked process is MMON, pay attention to red part, it is waiting for 60009fc8, and latch's possible holder ospid: 26755.

Let’s check ospid 26755:

PROCESS 50:
  ----------------------------------------
  SO: 0x19f2ef058, type: 2, owner: (nil), flag: INIT/-/-/0x00 if: 0x3 c: 0x3
   proc=0x19f2ef058, name=process, file=ksu.h LINE:12451, pg=0
  (process) Oracle pid:50, ser:165, calls cur/top: (nil)/(nil)
            flags : (0x0) -
            flags2: (0x8000),  flags3: (0x0)
            intr error: 0, call error: 0, sess error: 0, txn error 0
            intr queue: empty
    ksudlp FALSE at location: 0
  (post info) last post received: 0 0 0
              last post received-location: No post
              last process to post me: none
              last post sent: 0 0 0
              last post sent-location: No post
              last process posted by me: none
    (latch info) wait_event=0 bits=0
        Location from where call was made: ksu.h LINE:13721 ID:ksudlp:
        Context saved from call: 6965620824
      waiting for 60009fc8  process allocation level=7
        Location from where latch is held: ksu.h LINE:13677 ID:ksuapc: proc addr
        Context saved from call: 6965578584
        state=busy [holder orapid=0] wlstate=free [value=0]
          gotten 57043 times wait, failed first 54 sleeps 0
          gotten 26253 times nowait, failed: 1
        possible holder pid = 0 ospid=26755
    O/S info: user: oracle, term: UNKNOWN, ospid: 26755
    OSD pid info: Unix process pid: 26755, image: oracle@alpcispdb552)

We can see the Process 26755 is blocked by itself. A self deadlock latch issue.

Then i kill the Process 26755 from OS level with "kill -9" to get the latch released. But unluckly the DB is still hang.

I make a latest systemstate and check:

System State 1
~~~~~~~~~~~~~~~~
1:
2:  0: waiting for 'latch free'        [Latch 60009fc8]  ---- PMON is blocked
3:  0: waiting for 'rdbms ipc message'
4:  0: waiting for 'VKTM Logical Idle Wait'
5:  0: waiting for 'rdbms ipc message'
6:
7:  0: waiting for 'rdbms ipc message'
8:  0: waiting for 'DIAG idle wait'
9:  0: waiting for 'rdbms ipc message'
10: 0: waiting for 'rdbms ipc message'
11: 0: waiting for 'rdbms ipc message'
12: 0: waiting for 'rdbms ipc message'
13: 0: waiting for 'rdbms ipc message'
14: 0: waiting for 'rdbms ipc message'
15: 0: waiting for 'rdbms ipc message'
16: 0: waiting for 'rdbms ipc message'
17: 0: waiting for 'rdbms ipc message'
18: 0: waiting for 'rdbms ipc message'
19: 0: waiting for 'rdbms ipc message'
20: 0: waiting for 'rdbms ipc message'
21: 0: waiting for 'rdbms ipc message'
22: 0: waiting for 'rdbms ipc message'
23: 0: waiting for 'rdbms ipc message'
24: 0: waiting for 'rdbms ipc message'
25: 0: waiting for 'rdbms ipc message'
26: 0: waiting for 'rdbms ipc message'
27: 0: waiting for 'rdbms ipc message'
28: 0: waiting for 'rdbms ipc message'
29: 0: waiting for 'rdbms ipc message'
30: 0: waiting for 'rdbms ipc message'
31: 0: waiting for 'rdbms ipc message'
32: 0: waiting for 'smon timer'
33: 0: waiting for 'rdbms ipc message'
34: 0: waiting for 'latch free'        [Latch 60009fc8]
35: 0: waiting for 'rdbms ipc message'
36:                                    [Latch 60009fc8]
37: 0: waiting for 'enq: PV - syncstart'[Enqueue PV-00000000-00000000]
38:                                    [Latch 60009fc8]
39: 0: waiting for 'SQL*Net message from client'
40: 0: waiting for 'VKRM Idle'
41: 0: waiting for 'rdbms ipc message'
42: 0: waiting for 'rdbms ipc message'
43: 0: waiting for 'rdbms ipc message'
44: 0: waiting for 'Streams AQ: qmn coordinator idle wait'
45: 0: waiting for 'enq: PR - contention'[Enqueue PR-00000000-00000000]
46:                                    [Latch 60009fc8]
47: 0: waiting for 'Streams AQ: qmn slave idle wait'
48:                                    [Latch 60009fc8]
49: 0: waiting for 'SQL*Net message from client'
50:                                    [Latch 60009fc8]
51: 9: waited for 'Streams AQ: waiting for time management or cleanup tasks'
52: 0: waiting for 'SQL*Net message from client'
Blockers
~~~~~~~~

        Above is a list of all the processes. If they are waiting for a resource
        then it will be given in square brackets. Below is a summary of the
        waited upon resources, together with the holder of that resource.
        Notes:
        ~~~~~
         o A process id of '???' implies that the holder was not found in the
           systemstate.

                    Resource Holder State
              Latch 60009fc8    ??? Blocker
Enqueue PV-00000000-00000000    34: 34: is waiting for Latch 60009fc8
Enqueue PR-00000000-00000000    34: 34: is waiting for Latch 60009fc8

Object Names
~~~~~~~~~~~~
Latch 60009fc8   process allocation
Enqueue PV-00000000-00000000
Enqueue PR-00000000-00000000

We can see pmon is also blocked on latch 60009fc8.

And below is the process dump for PMON:

PROCESS 2: PMON
  ----------------------------------------
  SO: 0x19935b370, type: 2, owner: (nil), flag: INIT/-/-/0x00 if: 0x3 c: 0x3
   proc=0x19935b370, name=process, file=ksu.h LINE:12451, pg=0
  (process) Oracle pid:2, ser:1, calls cur/top: 0x19f525a88/0x19f525a88
            flags : (0xe) SYSTEM
            flags2: (0x0),  flags3: (0x0)
            intr error: 0, call error: 0, sess error: 0, txn error 0
            intr queue: empty
    ksudlp FALSE at location: 0
  (post info) last post received: 0 0 68
              last post received-location: kso2.h LINE:467 ID:ksoreq_reply
              last process to post me: 19f2edfd8 2 2
              last post sent: 0 0 26
              last post sent-location: ksa2.h LINE:282 ID:ksasnd
              last process posted by me: 1982dec38 1 6
    (latch info) wait_event=0 bits=0
        Location from where call was made: ksu.h LINE:13721 ID:ksudlp:
        Context saved from call: 6814711808
      waiting for 60009fc8  process allocation level=7
        Location from where latch is held: ksu.h LINE:13677 ID:ksuapc: proc addr
        Context saved from call: 6965578584
        state=busy [holder orapid=0] wlstate=free [value=0]
          gotten 57043 times wait, failed first 54 sleeps 0
          gotten 26253 times nowait, failed: 1
        possible holder pid = 0 ospid=26755
    Process Group: DEFAULT, pseudo proc: 0x19734a4b8
    O/S info: user: oracle, term: UNKNOWN, ospid: 1311
    OSD pid info: Unix process pid: 1311, image: oracle@server552(PMON)

We can see PMON is waiting on latch 60009fc8, blocked by the process that we just killed.

It is clear to us now:
process 26755 was in self deadlock state on latch 60009fc8 and blocked other processes. Later i killed process 26755 to release the latch, then pmon should go to clean the process and release the resource.
But before pmon start to work, pmon itself also require the same latch: 60009fc8 and hence blocked and can't progress.
So it is a typiclly pmon deadlock.

We had to bounce the DB at last.
More......

RMAN senior: duplicate database from tape without target DB, "RMAN-05548: The set of duplicated tablespaces is not self-contained"

Today, user require to restore a table from old backup.
The table is small, a few thousands rows. But the DB is big, 200gb. We don't have sufficient space to support restoring the whole DB.

We decide to resotre the table and its tablespace only, we will use "duplicate database skip tablespace" clause to skip irrelative tablespaces:

server001[oracle]_ORCLPROD> rman target / auxiliary  sys/oracle@temp2 catalog rmanadmin/rman_psswd@rmancatalog

Recovery Manager: Release 11.2.0.2.0 - Production on Sun Jul 29 04:23:34 2012

Copyright (c) 1982, 2009, Oracle and/or its affiliates.  All rights reserved.

connected to target database: ORCLPROD (DBID=1650044020)
connected to recovery catalog database
connected to auxiliary database: TEMP2 (not mounted)

RMAN> run
{
set until time "to_date('03-JUL-201212:00:00','dd-mm-yyyyhh24:mi:ss')";
allocate auxiliary  channel ch1 type 'sbt_tape' parms 'ENV=(NB_ORA_SERVER=netbacksev1_b,NB_ORA_CLIENT=server001_b)';
allocate auxiliary  channel ch2 type 'sbt_tape' parms 'ENV=(NB_ORA_SERVER=netbacksev1_b,NB_ORA_CLIENT=server001_b)';
duplicate target database to temp2 nofilenamecheck skip tablespace USERS,TBS1,TBS2,TBS3,TBS4,TBS5,TBS6,TBS7;
}

executing command: SET until clause
..........
..........
Violation: ORA-39906: Constraint SYS_C0050693 between table GETS_SO.GETS_SO_ATS_PROJECT in tablespace OTD and table GETS_SO.GETS_SO_SWPT_SSO_SHOP_ORD in tablespace SWPT_TABLES.
Violation: ORA-39908: Index GETS_SO.GETS_SO_NRE_BUSINESS_MST_PK in tablespace OTX_INDEXES enforces primary constraints  of table GETS_SO.GETS_SO_NRE_BUSINESS_MST in tablespace OTD.
Violation: ORA-39908: Index GETS_SO.GETS_SO_NRE_CUSTOMER_MST_PK in tablespace OTX_INDEXES enforces primary constraints  of table GETS_SO.GETS_SO_NRE_CUSTOMER_MST in tablespace OTD.
Violation: ORA-39908: Index GETS_SO.GETS_SO_NRE_ESR_DETAIL_PK in tablespace OTX_INDEXES enforces primary constraints  of table GETS_SO.GETS_SO_NRE_ESR_DETAIL in tablespace OTD.
Violation: ORA-39907: Index GETS_SO.GETS_SO_NRE_ESR_DSGN_TSK_IE2 in tablespace OTX_INDEXES points to table GETS_SO.GETS_SO_NRE_ESR_DSGN_TSK in tablespace OTD.
Violation: ORA-39907: Index GETS_SO.GETS_SO_NRE_ESR_RPT_TSK_IE1 in tablespace OTX_INDEXES points to table GETS_SO.GETS_SO_NRE_ESR_RPT_TSK in tablespace OTD.
..........
..........

released channel: ch1
released channel: ch2
released channel: ch3
released channel: ch4
RMAN-00571: ===========================================================
RMAN-00569: =============== ERROR MESSAGE STACK FOLLOWS ===============
RMAN-00571: ===========================================================
RMAN-03002: failure of Duplicate Db command at 07/29/2012 05:13:00
RMAN-05501: aborting duplication of target database
RMAN-05548: The set of duplicated tablespaces is not self-contained

The red part is an enhancement in 11g. When we skipped some tablespaces, oracle will check dependency on remaining tablespace through TTS transport check procedure. If the check failed, then rman will refuse to restore.

How to skip that? The only method is to use no-target duplicate.
Since the tablespace checking relies on target database, so with this method, oracle can't check the dependency from target DB:

no target duplicate:
rman auxiliary / catalog catalog rmanadmin/rman_psswd@rmancatalog
set dbid 21111;
run
{
set until time "to_date('03-JUL-201212:00:00','dd-mm-yyyyhh24:mi:ss')";
allocate auxiliary  channel ch1 type 'sbt_tape' parms 'ENV=(NB_ORA_SERVER=netbacksev1_b,NB_ORA_CLIENT=server001_b)';
allocate auxiliary  channel ch2 type 'sbt_tape' parms 'ENV=(NB_ORA_SERVER=netbacksev1_b,NB_ORA_CLIENT=server001_b)';
duplicate database to temp backup location  'sbt_tape' nofilenamecheck skip tablespace USERS,TBS1,TBS2,TBS3,TBS4,TBS5,TBS6,TBS7;
}

More......

From 11.2.0.2.5, oracle don't support ADJUST SCN any more

Today, after incomplete recovery and opened a DB, i decided to increasing SCN for the DB.
I set "_allow_error_simulation=true", and use:

alter session set events 'IMMEDIATE trace name adjust_scn level 4490';
ALTER SESSION SET EVENTS '10015 TRACE NAME ADJUST_SCN LEVEL 4490';

at open/mount state for serveral times, but the SCN didn't get changed!

The alert.log shew that oracle even didn't try to turn the SCN.
Very wiered.

Then i decide to try "_minimum_giga_scn" once, i added "_minimum_giga_scn=7000" into init.ora and then startup the DB:

SYS @ apci > startup
ORA-01078: failure in processing system parameters
LRM-00101: unknown parameter name '_minimum_giga_scn'

Kidding? I removed the parameter and again i can startup DB normal.
Let's query the hidden parameter:

SYS @ apci > select ksppinm from x$ksppi where ksppinm like '%giga%';
no rows selected

Let's check different version databases:

10.2.0.4, no problem as we expected：
SYS @ 10gDB> select ksppinm from x$ksppi where ksppinm like '%giga%';
KSPPINM
--------------------------------------------------------------------------------
_minimum_giga_scn

11.2.0.2.4, parameter still there：
SYS @ XXDB >select ksppinm from x$ksppi where ksppinm like '%giga%';
KSPPINM
--------------------------------------------------------------------------------
_minimum_giga_scn

11.2.0.2.5, from this version the parameter disapper:
SQL>  select ksppinm from x$ksppi where ksppinm like '%giga%';
no rows selected

11.2.0.2.6：
SYS @ DB1 > select ksppinm from x$ksppi where ksppinm like '%giga%';
no rows selected

11.2.0.3：
SYS @ DB2 > select ksppinm from x$ksppi where ksppinm like '%giga%';
no rows selected

We can see oracle remove the ADJUST SCN function since 11.2.0.2.5, so we can't use oracle's function to adjust SCN in future.
In there any alternative way?

Yes, we can do first increasing the checkpoint_change# value in datafile header block to a appopraite value, and then re-create controlfile.
So the new controlfile will read our new value as current SCN.

Below is the step:

SYS @ test8 > select current_scn from v$database;
CURRENT_SCN
-----------
    4324729

BBED> set offset 484
        OFFSET          484

BBED> dump
 File: /d735/data02/oracle/test8/data/system01.dbf (1)
 Block: 1                Offsets:  484 to  995           Dba:0x00400001
------------------------------------------------------------------------
 3ffe4100 00000000 59d60a2f 01000000 01000000 62010000 1000db8a 02000000
 00000000 00000000 00000000 00000000 00000000 00000000 00000000 00000000
 00000000 00000000 00000000 00000000 00000000 00000000 00000000 00000000
 00000000 00000000 00000000 00000000 00000000 00000000 00000000 00000000

BBED> modify /x dddddddd
Warning: contents of previous BIFILE will be lost. Proceed? (Y/N) Y
 File: /d735/data02/oracle/test8/data/system01.dbf (1)
 Block: 1                Offsets:  484 to  995           Dba:0x00400001
------------------------------------------------------------------------
 dddddddd 00000000 59d60a2f 01000000 01000000 62010000 1000db8a 02000000
 00000000 00000000 00000000 00000000 00000000 00000000 00000000 00000000
 00000000 00000000 00000000 00000000 00000000 00000000 00000000 00000000
 00000000 00000000 00000000 00000000 00000000 00000000 00000000 00000000

BBED> sum apply;
Check value for File 1, Block 1:
current = 0x5036, required = 0x5036

SYS @ test8 > startup nomount;
ORACLE instance started.

Total System Global Area  730714112 bytes
Fixed Size                  2230080 bytes
Variable Size             318769344 bytes
Database Buffers          322961408 bytes
Redo Buffers               86753280 bytes
SYS @ test8 > CREATE CONTROLFILE REUSE DATABASE "TEST8" RESETLOGS  NOARCHIVELOG
  2      MAXLOGFILES 200
  3      MAXLOGMEMBERS 4
 ...........
 ...........
 29    '/d735/data02/oracle/test8/data/user03_new.dbf'
 30  CHARACTER SET UTF8
 31  ;
Control file created.

SYS @ test8 > alter database open resetlogs;
Database altered.

SYS @ test8 > select current_scn from v$database;
CURRENT_SCN
-----------
 3722305178

Done.
More......

Instance evicted due to HAIP failure

Rac cluster, one server's instances abruptly evicted and re-joined the cluster after 10 minutes. Below is from DB's alert log:

Wed Jun 27 00:34:55 2012
Errors in file /q001/product/ora_base/diag/rdbms/ttpoltq/ttpoltq1/trace/ttpoltq1_ora_21759.trc  (incident=139278):
ORA-00603: ORACLE server session terminated by fatal error
ORA-27504: IPC error creating OSD context
ORA-27300: OS system dependent operation:if_not_found failed with status: 0
ORA-27301: OS failure message: Error 0
ORA-27302: failure occurred at: skgxpvaddr9
ORA-27303: additional information: requested interface 169.254.25.210 not found. Check output from ifconfig command
.............
ORA-29740: evicted by instance number 3, group incarnation 60
LMON (ospid: 20361): terminating the instance due to error 29740
Instance terminated by LMON, pid = 20361

From red part we know there must be something wrong with interconnect.

After checking found interfaces on 10.0.0.* network were working fine.
Also GPNP logfile shew no abnormal information.

Then the issue must be caused by HAIP.
Let's check CSSD's logfile:

oracle $ cat ocssd.log|egrep -i 'haip|disk'
2012-06-27 00:31:44.417: [    CSSD][1117505856]clssscMonitorThreads clssnmvDiskPingThread not scheduled for 7910 msecs
2012-06-27 00:31:52.433: [    CSSD][1117505856]clssscMonitorThreads clssnmvDiskPingThread not scheduled for 15920 msecs
2012-06-27 00:32:00.449: [    CSSD][1117505856]clssscMonitorThreads clssnmvDiskPingThread not scheduled for 23940 msecs
2012-06-27 00:32:08.170: [    CSSD][1105717568]clssscMonitorThreads clssnmvDiskPingThread not scheduled for 31660 msecs
2012-06-27 00:32:16.481: [    CSSD][1117505856]clssscMonitorThreads clssnmvDiskPingThread not scheduled for 39970 msecs
2012-06-27 00:32:24.497: [    CSSD][1117505856]clssscMonitorThreads clssnmvDiskPingThread not scheduled for 47980 msecs
2012-06-27 00:32:32.513: [    CSSD][1117505856]clssscMonitorThreads clssnmvDiskPingThread not scheduled for 56000 msecs
2012-06-27 00:32:40.945: [    CSSD][1117505856]clssscMonitorThreads clssnmvDiskPingThread not scheduled for 64430 msecs
2012-06-27 00:32:49.236: [    CSSD][1105717568]clssscMonitorThreads clssnmvDiskPingThread not scheduled for 72720 msecs
2012-06-27 00:32:58.565: [    CSSD][1117505856]clssscMonitorThreads clssnmvDiskPingThread not scheduled for 82040 msecs
2012-06-27 00:33:06.581: [    CSSD][1117505856]clssscMonitorThreads clssnmvDiskPingThread not scheduled for 90060 msecs
2012-06-27 00:33:14.597: [    CSSD][1117505856]clssscMonitorThreads clssnmvDiskPingThread not scheduled for 98070 msecs
2012-06-27 00:33:15.539: [    CSSD][1109621056]clssnmvDiskCheck: (ORCL:ASM_DISK01) No I/O completed after 50% maximum time, 200000 ms, will be considered unusable in 99990 ms
2012-06-27 00:33:22.614: [    CSSD][1117505856]clssscMonitorThreads clssnmvDiskPingThread not scheduled for 106090 msecs
2012-06-27 00:33:30.629: [    CSSD][1117505856]clssscMonitorThreads clssnmvDiskPingThread not scheduled for 114100 msecs
2012-06-27 00:33:34.069: [    CSSD][1105717568]clssgmFenceClient: fencing client (0x19278b0), member 1 in group haip.cluster_interconnect, no share, death fence 1, SAGE fence 0
2012-06-27 00:33:34.069: [    CSSD][1105717568]clssgmUnreferenceMember: global grock haip.cluster_interconnect member 1 refcount is 1
2012-06-27 00:33:34.069: [    CSSD][1093089600]clssgmTermMember: Terminating member 1 (0x18afc30) in grock haip.cluster_interconnect
2012-06-27 00:33:34.069: [    CSSD][1093089600]clssgmUnreferenceMember: global grock haip.cluster_interconnect member 1 refcount is 0
2012-06-27 00:33:34.070: [    CSSD][1111198016]clssgmRemoveMember: grock haip.cluster_interconnect, member number 1 (0x18afc30) node number 1 state 0x0 grock type 2
2012-06-27 00:33:34.070: [    CSSD][1111198016]clssgmGrantLocks: 1-> new master (3/3) group haip.cluster_interconnect
2012-06-27 00:33:34.072: [    CSSD][1111198016]clssgmBroadcastGrockRcfgCmpl: RPC(0x6c30034) of grock(haip.cluster_interconnect) is waiting for at least another ack from node(2)
2012-06-27 00:33:34.072: [    CSSD][1111198016]clssgmBroadcastGrockRcfgCmpl: RPC(0x6c30034) of grock(haip.cluster_interconnect) received all acks, grock update sequence(109)
2012-06-27 00:33:34.242: [    CSSD][1105717568]clssgmJoinGrock: global grock haip.cluster_interconnect new client 0x2aaab0611a70 with con 0x12622491, requested num 1, flags 0x4000100
2012-06-27 00:33:34.242: [    CSSD][1105717568]clssgmAddGrockMember: adding member to grock haip.cluster_interconnect
2012-06-27 00:33:34.242: [    CSSD][1111198016]clssgmAddMember: Adding fencing for member 1, group haip.cluster_interconnect, death 1, SAGE 0
2012-06-27 00:33:34.242: [    CSSD][1111198016]clssgmAddMember: member (1/0x2aaab051c000) added. pbsz(0) prsz(0) flags 0x0 to grock (0x2aaab00e3190/haip.cluster_interconnect)
2012-06-27 00:33:34.242: [    CSSD][1111198016]clssgmCommonAddMember: global group grock haip.cluster_interconnect member(1/Local) node(1) flags 0x0 0x423b6300
2012-06-27 00:33:34.245: [    CSSD][1111198016]clssgmBroadcastGrockRcfgCmpl: RPC(0x6c70034) of grock(haip.cluster_interconnect) is waiting for at least another ack from node(2)
2012-06-27 00:33:34.245: [    CSSD][1111198016]clssgmBroadcastGrockRcfgCmpl: RPC(0x6c70034) of grock(haip.cluster_interconnect) received all acks, grock update sequence(110)
2012-06-27 00:33:34.562: [    CSSD][1105717568]clssgmExitGrock: client 1 (0x2aaab0611a70), grock haip.cluster_interconnect, member 1
2012-06-27 00:33:34.562: [    CSSD][1105717568]clssgmUnregisterPrimary: Unregistering member 1 (0x2aaab051c000) in global grock haip.cluster_interconnect
2012-06-27 00:33:34.562: [    CSSD][1105717568]clssgmUnreferenceMember: global grock haip.cluster_interconnect member 1 refcount is 0
2012-06-27 00:33:34.562: [    CSSD][1111198016]clssgmRemoveMember: grock haip.cluster_interconnect, member number 1 (0x2aaab051c000) node number 1 state 0x4 grock type 2
2012-06-27 00:33:34.564: [    CSSD][1111198016]clssgmBroadcastGrockRcfgCmpl: RPC(0x6c80034) of grock(haip.cluster_interconnect) is waiting for at least another ack from node(2)
2012-06-27 00:33:34.565: [    CSSD][1111198016]clssgmBroadcastGrockRcfgCmpl: RPC(0x6c80034) of grock(haip.cluster_interconnect) received all acks, grock update sequence(111)
2012-06-27 00:33:34.627: [    CSSD][1105717568]clssgmJoinGrock: global grock haip.cluster_interconnect new client 0x2aaab04022b0 with con 0x1262256c, requested num 1, flags 0x4000100
2012-06-27 00:33:34.627: [    CSSD][1105717568]clssgmAddGrockMember: adding member to grock haip.cluster_interconnect
2012-06-27 00:33:34.627: [    CSSD][1111198016]clssgmAddMember: Adding fencing for member 1, group haip.cluster_interconnect, death 1, SAGE 0
2012-06-27 00:33:34.627: [    CSSD][1111198016]clssgmAddMember: member (1/0x2aaab04c0f80) added. pbsz(0) prsz(0) flags 0x0 to grock (0x2aaab00e3190/haip.cluster_interconnect)
2012-06-27 00:33:34.627: [    CSSD][1111198016]clssgmCommonAddMember: global group grock haip.cluster_interconnect member(1/Local) node(1) flags 0x0 0x423b6300
2012-06-27 00:33:34.629: [    CSSD][1111198016]clssgmBroadcastGrockRcfgCmpl: RPC(0x6cb0034) of grock(haip.cluster_interconnect) is waiting for at least another ack from node(2)
2012-06-27 00:33:34.630: [    CSSD][1111198016]clssgmBroadcastGrockRcfgCmpl: RPC(0x6cb0034) of grock(haip.cluster_interconnect) received all acks, grock update sequence(112)
2012-06-27 00:33:39.647: [    CSSD][1117505856]clssscMonitorThreads clssnmvDiskPingThread not scheduled for 123120 msecs
2012-06-27 00:33:47.663: [    CSSD][1117505856]clssscMonitorThreads clssnmvDiskPingThread not scheduled for 131130 msecs
2012-06-27 00:33:55.680: [    CSSD][1117505856]clssscMonitorThreads clssnmvDiskPingThread not scheduled for 139150 msecs
2012-06-27 00:34:04.115: [    CSSD][1117505856]clssscMonitorThreads clssnmvDiskPingThread not scheduled for 147580 msecs
2012-06-27 00:34:05.658: [    CSSD][1109621056]clssnmvDiskCheck: (ORCL:ASM_DISK01) No I/O completed after 75% maximum time, 200000 ms, will be considered unusable in 49880 ms
2012-06-27 00:34:11.712: [    CSSD][1117505856]clssscMonitorThreads clssnmvDiskPingThread not scheduled for 155180 msecs
2012-06-27 00:34:19.728: [    CSSD][1117505856]clssscMonitorThreads clssnmvDiskPingThread not scheduled for 163190 msecs
2012-06-27 00:34:28.314: [    CSSD][1105717568]clssscMonitorThreads clssnmvDiskPingThread not scheduled for 171770 msecs
2012-06-27 00:34:35.732: [    CSSD][1109621056]clssnmvDiskCheck: (ORCL:ASM_DISK01) No I/O completed after 90% maximum time, 200000 ms, will be considered unusable in 19810 ms
2012-06-27 00:34:36.762: [    CSSD][1117505856]clssscMonitorThreads clssnmvDiskPingThread not scheduled for 180220 msecs
2012-06-27 00:34:43.044: [    CSSD][1111198016]clssgmRemoveMember: grock haip.cluster_interconnect, member number 3 (0x2aaaac27b800) node number 3 state 0x0 grock type 2
2012-06-27 00:34:43.044: [    CSSD][1111198016]clssgmGrantLocks: 3-> new master (2/2) group haip.cluster_interconnect
2012-06-27 00:34:43.046: [    CSSD][1111198016]clssgmBroadcastGrockRcfgCmpl: RPC(0x7200034) of grock(haip.cluster_interconnect) is waiting for at least another ack from node(2)
2012-06-27 00:34:43.047: [    CSSD][1111198016]clssgmBroadcastGrockRcfgCmpl: RPC(0x7200034) of grock(haip.cluster_interconnect) received all acks, grock update sequence(113)
2012-06-27 00:34:43.291: [    CSSD][1111198016]clssgmAddMember: member (3/0x2aaaac5844a0) added. pbsz(0) prsz(0) flags 0x0 to grock (0x2aaab00e3190/haip.cluster_interconnect)
2012-06-27 00:34:43.291: [    CSSD][1111198016]clssgmCommonAddMember: global group grock haip.cluster_interconnect member(3/Remote) node(3) flags 0x0 0xac5844a0
2012-06-27 00:34:43.293: [    CSSD][1111198016]clssgmBroadcastGrockRcfgCmpl: RPC(0x7400034) of grock(haip.cluster_interconnect) is waiting for at least another ack from node(2)
2012-06-27 00:34:43.293: [    CSSD][1111198016]clssgmBroadcastGrockRcfgCmpl: RPC(0x7400034) of grock(haip.cluster_interconnect) received all acks, grock update sequence(114)
2012-06-27 00:34:43.636: [    CSSD][1111198016]clssgmRemoveMember: grock haip.cluster_interconnect, member number 3 (0x2aaaac5844a0) node number 3 state 0x0 grock type 2
2012-06-27 00:34:43.638: [    CSSD][1111198016]clssgmBroadcastGrockRcfgCmpl: RPC(0x74f0034) of grock(haip.cluster_interconnect) is waiting for at least another ack from node(3)
2012-06-27 00:34:43.639: [    CSSD][1111198016]clssgmBroadcastGrockRcfgCmpl: RPC(0x74f0034) of grock(haip.cluster_interconnect) received all acks, grock update sequence(115)
2012-06-27 00:34:43.730: [    CSSD][1111198016]clssgmAddMember: member (3/0x1dba9d0) added. pbsz(0) prsz(0) flags 0x0 to grock (0x2aaab00e3190/haip.cluster_interconnect)
2012-06-27 00:34:43.731: [    CSSD][1111198016]clssgmCommonAddMember: global group grock haip.cluster_interconnect member(3/Remote) node(3) flags 0x0 0x1dba9d0
2012-06-27 00:34:43.733: [    CSSD][1111198016]clssgmBroadcastGrockRcfgCmpl: RPC(0x74a0034) of grock(haip.cluster_interconnect) is waiting for at least another ack from node(2)
2012-06-27 00:34:43.733: [    CSSD][1111198016]clssgmBroadcastGrockRcfgCmpl: RPC(0x74a0034) of grock(haip.cluster_interconnect) received all acks, grock update sequence(116)
2012-06-27 00:34:45.457: [    CSSD][1105717568]clssgmExitGrock: client 1 (0x2aaab04022b0), grock haip.cluster_interconnect, member 1
2012-06-27 00:34:45.457: [    CSSD][1105717568]clssgmUnregisterPrimary: Unregistering member 1 (0x2aaab04c0f80) in global grock haip.cluster_interconnect
2012-06-27 00:34:45.457: [    CSSD][1105717568]clssgmUnreferenceMember: global grock haip.cluster_interconnect member 1 refcount is 0
2012-06-27 00:34:45.457: [    CSSD][1111198016]clssgmRemoveMember: grock haip.cluster_interconnect, member number 1 (0x2aaab04c0f80) node number 1 state 0x4 grock type 2
2012-06-27 00:34:45.459: [    CSSD][1111198016]clssgmBroadcastGrockRcfgCmpl: RPC(0x7640034) of grock(haip.cluster_interconnect) is waiting for at least another ack from node(2)
2012-06-27 00:34:45.459: [    CSSD][1111198016]clssgmBroadcastGrockRcfgCmpl: RPC(0x7640034) of grock(haip.cluster_interconnect) received all acks, grock update sequence(117)
2012-06-27 00:43:28.566: [    CSSD][1105717568]clssgmJoinGrock: global grock haip.cluster_interconnect new client 0x2aaab43103e0 with con 0x126435d1, requested num 1, flags 0x4000100
2012-06-27 00:43:28.566: [    CSSD][1105717568]clssgmAddGrockMember: adding member to grock haip.cluster_interconnect
2012-06-27 00:43:28.566: [    CSSD][1111198016]clssgmAddMember: Adding fencing for member 1, group haip.cluster_interconnect, death 1, SAGE 0
2012-06-27 00:43:28.566: [    CSSD][1111198016]clssgmAddMember: member (1/0x2aaab46fbd20) added. pbsz(0) prsz(0) flags 0x0 to grock (0x2aaab00e3190/haip.cluster_interconnect)
2012-06-27 00:43:28.566: [    CSSD][1111198016]clssgmCommonAddMember: global group grock haip.cluster_interconnect member(1/Local) node(1) flags 0x0 0x423b6300
2012-06-27 00:43:28.568: [    CSSD][1111198016]clssgmBroadcastGrockRcfgCmpl: RPC(0x2aa0035) of grock(haip.cluster_interconnect) is waiting for at least another ack from node(2)
2012-06-27 00:43:28.569: [    CSSD][1111198016]clssgmBroadcastGrockRcfgCmpl: RPC(0x2aa0035) of grock(haip.cluster_interconnect) received all acks, grock update sequence(118)
2012-06-27 00:43:44.470: [    CSSD][1105717568]clssgmExecuteClientRequest: VOTEDISKQUERY recvd from proc 32 (0x2aaab4269a70)
2012-06-27 00:43:45.958: [    CSSD][1105717568]clssgmExecuteClientRequest: VOTEDISKQUERY recvd from proc 32 (0x2aaab4269a70)
2012-06-27 00:43:48.770: [    CSSD][1105717568]clssgmExecuteClientRequest: VOTEDISKQUERY recvd from proc 34 (0x2aaab05c4340)
2012-06-27 00:43:48.771: [    CSSD][1105717568]clssgmExecuteClientRequest: VOTEDISKQUERY recvd from proc 34 (0x2aaab05c4340)

From above we can see the cluster started to countdown votedisk timeout:
2012-06-27 00:31:44.417: [ CSSD][1117505856]clssscMonitorThreads clssnmvDiskPingThread not scheduled for 7910 msecs

The long disk timeout threshold is 200 seconds in 11gR2.
During the countdown process, the cluster had a check on HAIP and belive HAIP already died:
2012-06-27 00:33:34.069: [ CSSD][1105717568]clssgmFenceClient: fencing client (0x19278b0), member 1 in group haip.cluster_interconnect, no share, death fence 1, SAGE fence 0

Cluster start to cleanup HAIP, and tried mutiple times to restart HAIP.

And later, the votedisk is online again, so votedisk timeout countdown stopped, and HAIP also re-brought up on-line, and all instances also be brought up, and all things back to normal then.
More......

MMAN in idle state but blocking other sessions which waiting 'SGA: allocation forcing component growth'

Find many blocking in one instance of an three nodes Rac DB.
Most sessions are either hang or running slow, after tracing found the blocker is MMAN process.

Below is from the trace:

Chain 1:
-------------------------------------------------------------------------------
    Oracle session identified by:
    {
                instance: 1 (apccfp1.apccfp11)
                   os id: 15557
              process id: 64, oracle@alpcispdb604 (J001)
              session id: 2
        session serial #: 23481
    }
    is waiting for 'latch free' with wait info:
    {
                      p1: 'address'=0x6003f518
                      p2: 'number'=0x189
                      p3: 'tries'=0x0
            time in wait: 22.106728 sec
           timeout after: never
                 wait id: 3995
                blocking: 0 sessions
             current sql: UPDATE T_XXXX HSC SET (HSC.HOSTAPP_STATE_ID, HSC..................
            wait history:
              * time between current wait and wait #1: 0.023292 sec
              1.       event: 'gc current block 2-way'
                 time waited: 0.000410 sec
                     wait id: 3994            p1: ''=0x1
                                              p2: ''=0x1a32e
                                              p3: ''=0x1
              * time between wait #1 and #2: 0.000438 sec
              2.       event: 'library cache pin'
                 time waited: 0.000327 sec
                     wait id: 3993            p1: 'handle address'=0x1b7e8b1f0
                                              p2: 'pin address'=0x13b609ef0
                                              p3: '100*mode+namespace'=0xffffffff00160002
              * time between wait #2 and #3: 0.000158 sec
              3.       event: 'library cache lock'
                 time waited: 0.000374 sec
                     wait id: 3992            p1: 'handle address'=0x1b7e8b1f0
                                              p2: 'lock address'=0x172458968
                                              p3: '100*mode+namespace'=0xffffffff00160002
    }
    and is blocked by
 => Oracle session identified by:
    {
                instance: 1 (apccfp1.apccfp11)
                   os id: 15454
              process id: 65, oracle@alpcispdb604
              session id: 28
        session serial #: 33079
    }
    which is waiting for 'SGA: allocation forcing component growth' with wait info:
    {
            time in wait: 0.047688 sec (last interval)
            time in wait: 4.538964 sec (total)
      heur. time in wait: 4.539095 sec
           timeout after: never
                 wait id: 44447
                blocking: 17 sessions
             current sql: 
            wait history:
              * time between current wait and wait #1: 0.000000 sec
              1.       event: 'SGA: allocation forcing component growth'
                 time waited: 0.000053 sec
                     wait id: 44535
              * time between wait #1 and #2: 0.000000 sec
              2.       event: 'SGA: allocation forcing component growth'
                 time waited: 0.050851 sec (last interval)
                 time waited: 4.491223 sec (total)
                     wait id: 44447
              * time between wait #2 and #3: 0.000000 sec
              3.       event: 'SGA: allocation forcing component growth'
                 time waited: 0.000122 sec
                     wait id: 44534
    }
    and is blocked by
 => Oracle session identified by:
    {
                instance: 1 (apccfp1.apccfp11)
                   os id: 25858
              process id: 18, oracle@alpcispdb604 (MMAN)
              session id: 451
        session serial #: 1
    }
    which is waiting for 'rdbms ipc message' with wait info:
    {
                      p1: 'timeout'=0x1f
            time in wait: 0.047679 sec
           timeout after: 0.262321 sec
                 wait id: 3739777
                blocking: 18 sessions
             current sql: 
            wait history:
              * time between current wait and wait #1: 0.000060 sec
              1.       event: 'rdbms ipc message'
                 time waited: 0.050904 sec
                     wait id: 3739776         p1: 'timeout'=0x24
              * time between wait #1 and #2: 0.000067 sec
              2.       event: 'rdbms ipc message'
                 time waited: 0.050946 sec
                     wait id: 3739775         p1: 'timeout'=0x29
              * time between wait #2 and #3: 0.000055 sec
              3.       event: 'rdbms ipc message'
                 time waited: 0.050844 sec
                     wait id: 3739774         p1: 'timeout'=0x2e
    }

Chain 1 Signature: 'rdbms ipc message'<='SGA: allocation forcing component growth'<='latch free'
Chain 1 Signature Hash: 0xd39c75b6
-------------------------------------------------------------------------------

There are mutiple other chains, but all chains' root is MMAN.

From above we can see some sessions were facing suffcient memory issue, hence waiting MMAN to turn memory for them.

These blocked sessions were also hodling some resouces, as a result they were blocking more sessions.

And during the whole time, MMAN is idle and do nothing.
We tried to flush shared_pool but also hang, also blocked by MMAN. Since MMAN is critical background process, we can't kill it. Therefore we had to bounce the first instance at last.
More......

diagnose 04030: koh-kghu sessi and large of free space

Recently one of our prod DB repeatly got 04030 error:

ORA-04030: out of process memory when trying allocate 64024 bytes (qmxeventInitCt,qmxeventInitctx:buffer)
ORA-04030: out of process memory when trying allocate 824504 bytes (pga heap,kco buffer)
ORA-04030: out of process memory when trying allocate 16328 bytes (PLSQL Opt Pool,pdz7M04_Create)

ORA-04030: (pga heap,kco buffer) may indiate kco buffer in PGA heap consuming too much space and leading to 04030.

But in our case, each ORA-04030's parameters are different.
It means some other type allocated most of PGA, and left no space for other types PGA request.

Trace file shows the 04031 coming from an daily expdp job:
Below is current SQL:

*** 2012-06-30 22:25:39.959
dbkedDefDump(): Starting incident default dumps (flags=0x2, level=3, mask=0x0)
----- Current SQL Statement for this session (sql_id=b1n2qbfhwsyhb) -----
CREATE TABLE "ET$036AA8ED0002"
   (    "ABSTRACT_ID",
        "FEED_ID",
        "SEC_STATE",
        "IS_ACTIVE",
        "CREATED_BY",
        "CREATED_DATE",
        "UPDATED_BY",
        "UPDATED_DATE",
        "XML_RSS_ABSTRACT",
        "XML_ABSTRACT_SOURCE"
   ) ORGANIZATION EXTERNAL
    ( TYPE ORACLE_DATAPUMP DEFAULT DIRECTORY "DATA_RAD" ACCESS PARAMETERS ( DEBUG = (0 , 0) DATAPUMP INTERNAL TABLE "POCDBA02"."T_NR_ABSTRACT"  JOB ( "SYSTEM
","SYS_EXPORT_FULL_20",1) WORKERID 1 PARALLEL 1 VERSION '11.2.0.2' ENCRYPTPASSWORDISNULL  COMPRESSION DISABLED  ENCRYPTION DISABLED ) LOCATION ('bogus.dat')
)  PARALLEL 1 REJECT LIMIT UNLIMITED
    AS SELECT /*+ PARALLEL(KU$,1) */ "ABSTRACT_ID", "FEED_ID", "SEC_STATE", "IS_ACTIVE", "CREATED_BY", "CREATED_DATE", "UPDATED_BY", "UPDATED_DATE", SYS_XMLT
_2_SC("XML_RSS_ABSTRACT"), SYS_XMLT_2_SC("XML_ABSTRACT_SOURCE")
    FROM RELATIONAL("PXXX02"."T_NR_AXXXCT" NOT XMLTYPE) KU$

Below is the PGA map from trace file, notice red part:

-------------------------
Private memory usage per Oracle process
Top 10 processes:
-------------------------
(percentage is of 4529 MB total allocated memory)
91% pid 62: 4104 MB used of 4107 MB allocated  <= CURRENT PROC
 2% pid 86: 16 MB used of 83 MB allocated (64 MB freeable)
 1% pid 37: 38 MB used of 41 MB allocated (1088 KB freeable)
 1% pid 38: 28 MB used of 29 MB allocated
 0% pid 15: 13 MB used of 13 MB allocated (64 KB freeable)
 0% pid 13: 13 MB used of 13 MB allocated (64 KB freeable)
 0% pid 14: 13 MB used of 13 MB allocated (64 KB freeable)
 0% pid 59: 6482 KB used of 13 MB allocated (6272 KB freeable)
 0% pid 20: 12 MB used of 13 MB allocated
 0% pid 19: 8853 KB used of 13 MB allocated

From current proc we see the expdp consumed 4000+mb PGA and reached the max limit at OS level. By default in 64-bit linux, the max limit for single process PGA is 4GB, controled by below parameter in OS：
vm.max_map_count=65536
And below parameter in DB：
_realfree_heap_pagesize_hint 65536

The easist solution is increasing the limit to allow process to apply more memory, but the best way is to identify why this process consumed so much memory.
Let's check into the trace file:

=======================================
TOP 10 MEMORY USES FOR THIS PROCESS
---------------------------------------
*** 2012-06-30 22:25:39.707
74% 3041 MB, 66260 chunks: "free memory               "
         session heap    ds=0x2b4fb3e26d30  dsprt=0xb7eec80
25% 1010 MB, 64838 chunks: "qmxtgCreateTempLob        "
         koh-kghu sessi  ds=0x2b4fb6638bd0  dsprt=0x2b4fb3e26d30
 0% 8859 KB, 2185 chunks: "kxsFrame4kPage            "
         session heap    ds=0x2b4fb3e26d30  dsprt=0xb7eec80
 0% 6019 KB, 378 chunks: "pmuccst: adt/record       "  PL/SQL
         koh-kghu sessi  ds=0x2b4fb492b110  dsprt=0x2b4fb3e26d30
 0% 5562 KB,  46 chunks: "XVM Storage               "
         XVM subheap of  ds=0x2b4fb498b278  dsprt=0x2b4fb3d89b38
 0% 3300 KB, 207 chunks: "pmucalm coll              "  PL/SQL
         koh-kghu sessi  ds=0x2b4fb48facf8  dsprt=0x2b4fb3e26d30
 0% 2312 KB, 2627 chunks: "permanent memory          "  SQL
         kxs-heap-p      ds=0x2b4fb5d31898  dsprt=0x2b4fb3e26d30
 0% 2281 KB, 185 chunks: "pl/sql vc2                "  PL/SQL
         koh-kghu sessi  ds=0x2b4fb66a8e30  dsprt=0x2b4fb3e26d30
 0% 1319 KB,  85 chunks: "static frame of inst      "  PL/SQL
         koh-kghu sessi  ds=0x2b4fb5bbfa70  dsprt=0x2b4fb3e26d30
 0% 1288 KB, 160 chunks: "kxsFrame8kPage            "
         session heap    ds=0x2b4fb3e26d30  dsprt=0xb7eec80

We can see the first one is belong to session heap(UGA), and type is "free memory", this is very wierd.

I restart the expdp job, and during it is running, the PGA usage keep increasing, and when the PGA allocation size reached 2gb, i made an PGA dump:

news2 >oradebug setospid 11903 

Statement processed. 

news2 >oradebug dump heapdump 536870913 

Statement processed.

Let's check our trace file:

server803.corporate.ge.com[oracle]_news2> cat db2_dw00_11903.trc.2|grep -i "total heap size"
HEAP DUMP heap name="session heap"  desc=0x2b88a22b6d30
Total heap size    =1768309088
HEAP DUMP heap name="koh-kghu sessi"  desc=0x2b88a487cd60
Total heap size    =429703184
HEAP DUMP heap name="koh-kghu sessi"  desc=0x2b88a2db6110
Total heap size    = 10794656
HEAP DUMP heap name="koh-kghu sessi"  desc=0x2b88a239d2b8
Total heap size    =  4149616
HEAP DUMP heap name="koh-kghu sessi"  desc=0x2b88a22de820
Total heap size    =  1272824
HEAP DUMP heap name="koh-kghu sessi"  desc=0x2b88a2da2c48
Total heap size    =  1178344
HEAP DUMP heap name="pga heap"  desc=0xb7e9240
Total heap size    = 11246712
HEAP DUMP heap name="XVMsubheap"  desc=0x2b88a2214b38
Total heap size    =  5709704
HEAP DUMP heap name="XVM subheap of"  desc=0x2b88a2e67d00
Total heap size    =  5708240
HEAP DUMP heap name="qmxdContextEnc"  desc=0x2b88a2e67c00
Total heap size    =     4216
HEAP DUMP heap name="KSFQ heap"  desc=0x2b88a21d7f30
Total heap size    =  1074104
HEAP DUMP heap name="koh-kghu call "  desc=0x2b88a2740010
Total heap size    =   940200
HEAP DUMP heap name="KFK_IO_SUBHEAP"  desc=0x2b88a20684a8
Total heap size    =   476688
HEAP DUMP heap name="PLS PGA hp"  desc=0x2b88a2210bc0
Total heap size    =   135280
HEAP DUMP heap name="top call heap"  desc=0xb7eea60
Total heap size    =   720680
HEAP DUMP heap name="callheap"  desc=0x2b88a2311108
Total heap size    =   285856
HEAP DUMP heap name="qbcqtcHTHeap"  desc=0x2b88a2354b00
Total heap size    =     6400
HEAP DUMP heap name="qcpi4.c.kgght"  desc=0x2b88a2354738
Total heap size    =     3624
HEAP DUMP heap name="kggec.c.kggfa"  desc=0x2b88a2354478
Total heap size    =     1528
HEAP DUMP heap name="PLS CGA hp"  desc=0x2b88a2b83ee8
Total heap size    =     1992
HEAP DUMP heap name="callheap"  desc=0xb7edc18
Total heap size    =   131064
HEAP DUMP heap name="callheap"  desc=0xb7edb60
Total heap size    =    38000
HEAP DUMP heap name="kti call subhe"  desc=0x2b88a220d7e8
Total heap size    =    36968
HEAP DUMP heap name="top uga heap"  desc=0xb7eec80
Total heap size    =1769554808
HEAP DUMP heap name="session heap"  desc=0x2b88a22b6d30
Total heap size    =1768309088
HEAP DUMP heap name="koh-kghu sessi"  desc=0x2b88a487cd60
Total heap size    =429703184
HEAP DUMP heap name="koh-kghu sessi"  desc=0x2b88a2db6110
Total heap size    = 10794656
HEAP DUMP heap name="koh-kghu sessi"  desc=0x2b88a239d2b8
Total heap size    =  4149616
HEAP DUMP heap name="koh-kghu sessi"  desc=0x2b88a22de820
Total heap size    =  1272824
HEAP DUMP heap name="koh-kghu sessi"  desc=0x2b88a2da2c48
Total heap size    =  1178344

Notice outstanding large part, "top uga heap" is big, caused by "session heap". 
Then let's check session heap:

HEAP DUMP heap name="session heap"  desc=0x2b88a22b6d30
...........
Total heap size    =1768309088
Total free space   =1296798672
...........
FIVE LARGEST SUB HEAPS for heap name="session heap"   desc=0x2b88a22b6d30
  Subheap ds=0x2b88a487cd60  heap name=  koh-kghu sessi  size=       430756008
   owner=(nil)  latch=(nil)
  Subheap ds=0x2b88a2db6110  heap name=  koh-kghu sessi  size=        10821000
   owner=(nil)  latch=(nil)
  Subheap ds=0x2b88a239d2b8  heap name=  koh-kghu sessi  size=         4159400
   owner=(nil)  latch=(nil)
  Subheap ds=0x2b88a22de820  heap name=  koh-kghu sessi  size=         1276088
   owner=(nil)  latch=(nil)
  Subheap ds=0x2b88a2da2c48  heap name=  koh-kghu sessi  size=         1181128
   owner=(nil)  latch=(nil)

We can see session heap is 1.7gb big. 0.5gb consumend on "koh-kghu sessi", and all other 1.2gb are free!
Eventhough the space is free, but it only belong to session heap and can't be used by other types in different heaps.

Why “koh-kghu sessi” consumend so much space and why so many free space are allcoated in session heap while it shouldn't be?

After searched on metalink, we may hit two bugs here, one for free memory, one for "koh-kghu sessi":
1.ORA-04030 encountered by a process which allocate large free memory [ID 1439928.1]
2.Bug 10194031 - EXPDP of OR XML leaks memory / runs slow [ID 10194031.8]

More......

RMAN blocked by ARCH process, waiting “enq: WL - contention”

Today, we got a file system alert, one server's arch mount point is 90% full.

After checking found one DB's archivelog occupied 90% space.
And this DB's backup arch job was running since 10 days ago and still hang there, no progress.

After checking in the DB, found the rman job was blocked by below red part event:

      SSID    OSUSER     USERNAME          STATE      STATUS                    MODULE
---------- --------- ------------ -------------- ------------ -------------------------                                                  

BLOCKING_SESSION                   EVENT                          PROGRAM
---------------- ----------------------- --------------------------------
       244    oracle          SYS        WAITING       ACTIVE  rman@server621 (TNS V1-V3)
              58     enq: WL - contention       rman@server621 (TNS V1-V3)
SQL_TEXT
--------------------------------------
begin dbms_rcvman.setDatabase(upper(:dbname), :rlscn, :rltime, :fhdbi, :db_unique_name, TRUE); dbms_rcvman.setCanApplyAnyRedo(TRUE); dbms_rcvman.setCanConvertCf(TRUE); if (:canhandletts = 1) then   dbms_rcvman.setCanHandleTransportableTbs(TRUE); end if; end;

It is blocked by session 58, which is ARC0 process:

SID     SPID                        ROGRAM
------ -------- -------------------------- 
    58    10899    oracle@server621 (ARC1)

Killing ARC0 process, oracle will restart it automaticlly.
Then the rman backup job began to progress normally.
More......

hack the core:bootstrap$, replace bootstrap$ with user's table

bootstrap$ is the most core table for database. It contains defination for oracle most critical dictinary tables such as: obj$, tab$, ts$ etc.

During an startup, oracle will read bootstrap$ to build dictionary for whole DB.
Any modification on bootstrap$ may destroy your database, and oracle support won't help anything on that.

Below is  bootstrap$ structure and one row in it:

SYS @ geded > select count(*) from bootstrap$;
  COUNT(*)
----------
        60

SYS @ geded > select * from bootstrap$ where line#=18;

     LINE#       OBJ#
---------- ----------
SQL_TEXT
-------------------------------------------------------------------------------------
        18         18
CREATE TABLE OBJ$("OBJ#" NUMBER NOT NULL,"DATAOBJ#" NUMBER,"OWNER#" NUMBER NOT NULL,"NAME" VARCHAR2(30) NOT NULL,"NAMESPACE" NUMBER NOT NULL,"SUBNAME" VARCHAR2(30),"TYPE#" NUMBER NOT NULL,"C
TIME" DATE NOT NULL,"MTIME" DATE NOT NULL,"STIME" DATE NOT NULL,"STATUS" NUMBER NOT NULL,"REMOTEOWNER" VARCHAR2(30),"LINKNAME" VARCHAR2(128),"FLAGS" NUMBER,"OID$" RAW(16),"SPARE1" NUMBER,"SP
ARE2" NUMBER,"SPARE3" NUMBER,"SPARE4" VARCHAR2(1000),"SPARE5" VARCHAR2(1000),"SPARE6" DATE) PCTFREE 10 PCTUSED 40 INITRANS 1 MAXTRANS 255 STORAGE (  INITIAL 16K NEXT 104K MINEXTENTS 1 MAXEXT
ENTS 2147483645 PCTINCREASE 0 OBJNO 18 EXTENTS (FILE 1 BLOCK 240))

SYS @ geded > desc bootstrap$;
Name              Null?    Type
-------------- ---------- ---------------
LINE#          NOT NULL   NUMBER
OBJ#           NOT NULL   NUMBER
SQL_TEXT       NOT NULL   VARCHAR2(4000)

Below is one possible error for bootstrap$ failure during startup:

ORA-01092: ORACLE instance terminated. Disconnection forced
ORA-00704: bootstrap process failure.

Today, let's hack the bootstrap$, even replace it with our own table:

Kevin.Zhang >  select count(*) from bootstrap$;
  COUNT(*)
----------
        60

Kevin.Zhang > shutdown immediate;
Database closed.
Database dismounted.
ORACLE instance shut down.

Kevin.Zhang > startup upgrade;
ORACLE instance started.
Total System Global Area  730714112 bytes
Fixed Size                  2230080 bytes
Variable Size             318769344 bytes
Database Buffers          322961408 bytes
Redo Buffers               86753280 bytes
Database mounted.
Database opened.

Kevin.Zhang > create table KILLBOOT as select * from bootstrap$;
Table created.

Kevin.Zhang > delete from KILLBOOT where LINE#=59;
1 row deleted.

Kevin.Zhang > commit;
Commit complete.

Kevin.Zhang > delete from bootstrap$;
60 rows deleted.

Kevin.Zhang > commit;
Commit complete.

Here we use an internal package DBMS_DDL_INTERNAL.SWAP_BOOTSTRAP to swap bootstrap$ to our new table KILLBOOT.
Infact package DBMS_DDL_INTERNAL.SWAP_BOOTSTRAP only do one thing, to update kcvfhrdb in super block(file 1 block 1):

Kevin.Zhang > exec DBMS_DDL_INTERNAL.SWAP_BOOTSTRAP('KILLBOOT');
PL/SQL procedure successfully completed.

Kevin.Zhang > update obj$ set name='BOOTSTRAP_DEL' where name='BOOTSTRAP$';
1 row updated.

Kevin.Zhang > commit;
Commit complete.

Kevin.Zhang > shutdown immediate;
Database closed.
Database dismounted.
ORACLE instance shut down.

Kevin.Zhang > startup;
ORACLE instance started.
Total System Global Area  730714112 bytes
Fixed Size                  2230080 bytes
Variable Size             318769344 bytes
Database Buffers          322961408 bytes
Redo Buffers               86753280 bytes
Database mounted.
Database opened.

Kevin.Zhang > select count(*) from bootstrap$;
  COUNT(*)
----------
        59

Kevin.Zhang > select count(*) from bootstrap_del;
  COUNT(*)
----------
         0

Kevin.Zhang > select count(*) from KILLBOOT;
  COUNT(*)
----------
        59

We are done, let's prove that we have already succeeded in replacing bootstrap$ with our new table KILLBOOT:

Kevin.Zhang > select dbms_rowid.rowid_relative_fno(rowid) file_id,dbms_rowid.rowid_block_number(rowid) block_id from bootstrap$ where rownum<10;

   FILE_ID   BLOCK_ID
---------- ----------
         1      60817
         1      60817
         1      60817
         1      60817
         1      60817
         1      60817
         1      60817
         1      60817
         1      60817

9 rows selected.

From the block_id we can clearly identify since this block belong to KILLBOOT table.
More......

LMS terminating the instance due to error 4031

One of our two node Rac DB encounter 04031 due to inbalance in mini sub heap.

After turned parameter for shared_pool, i decided to bounce instance one by one.
But when i was bouncing the instance on first node, the second node instance also crashed.

Below is in the logfile for second instance:

Wed Jun 27 04:57:28 2012
Reconfiguration started (old inc 4, new inc 6)
List of instances:
 2 (myinst: 2)
 Global Resource Directory frozen
 * dead instance detected - domain 0 invalid = TRUE
 Communication channels reestablished
 Master broadcasted resource hash value bitmaps
 Non-local Process blocks cleaned out
Wed Jun 27 04:57:28 2012
 LMS 1: 0 GCS shadows cancelled, 0 closed, 0 Xw survived
Wed Jun 27 04:57:28 2012
 LMS 2: 0 GCS shadows cancelled, 0 closed, 0 Xw survived
Wed Jun 27 04:57:28 2012
 LMS 0: 0 GCS shadows cancelled, 0 closed, 0 Xw survived
 Set master node info
 Submitted all remote-enqueue requests
 Dwn-cvts replayed, VALBLKs dubious
 All grantable enqueues granted
 Post SMON to start 1st pass IR
Wed Jun 27 04:57:28 2012
Instance recovery: looking for dead threads
Beginning instance recovery of 1 threads
 parallel recovery started with 6 processes
Started redo scan
Completed redo scan
 read 202 KB redo, 74 data blocks need recovery
Wed Jun 27 04:57:32 2012
Use ADRCI or Support Workbench to package the incident.
See Note 411.1 at My Oracle Support for error and packaging details.
Use ADRCI or Support Workbench to package the incident.
See Note 411.1 at My Oracle Support for error and packaging details.
Use ADRCI or Support Workbench to package the incident.
See Note 411.1 at My Oracle Support for error and packaging details.
Use ADRCI or Support Workbench to package the incident.
See Note 411.1 at My Oracle Support for error and packaging details.
Errors in file /d001/product/ora_base/diag/rdbms/ttpoltd/ttpoltd2/trace/ttpoltd2_lms2_942.trc:
ORA-04031: unable to allocate 4136 bytes of shared memory ("shared pool","unknown object","sga heap(3,0)","gcs dynamic r")
LMS2 (ospid: 942): terminating the instance due to error 4031
Wed Jun 27 04:57:33 2012
System state dump requested by (instance=2, osid=942 (LMS2)), summary=[abnormal instance termination].
System State dumped to trace file /d001/product/ora_base/diag/rdbms/ttpoltd/ttpoltd2/trace/ttpoltd2_diag_920.trc
Wed Jun 27 04:57:34 2012
ORA-1092 : opitsk aborting process
Errors in file /d001/product/ora_base/diag/rdbms/ttpoltd/ttpoltd2/trace/ttpoltd2_diag_920.trc:
ORA-00601: cleanup lock conflict
Dumping diagnostic data in directory=[cdmp_20120627045733], requested by (instance=2, osid=942 (LMS2)), summary=[abnormal instance termination].
Wed Jun 27 04:57:35 2012
ORA-1092 : opitsk aborting process
Wed Jun 27 04:57:35 2012
License high water mark = 38
Instance terminated by LMS2, pid = 942
USER (ospid: 17522): terminating the instance
Instance terminated by USER, pid = 17522

From above log we can see during instance reconfigure progress, LMS hit 04031 and failed to progress with reconfigure operation, hence LMS terminated the instance.:
More......

04031 and large pool, parallel and PX msg pool

Parallelism require "PX msg pool". In past, "PX msg pool" are allocate from shared_pool:

SYS @ test > select * from v$sgastat where  upper(name) like '%PX%';
POOL         NAME                                                    BYTES
------------ -------------------------------------------------- ----------
shared pool  PX subheap desc                                           256
shared pool  PX msg pool struct                                         56
shared pool  PX QC deq stats                                          1696
shared pool  ksu: ksusg_emptypxsta                                    5200
shared pool  PX server deq stats                                      1696
shared pool  PX list of chunk lists                                   1088
shared pool  PX subheap                                              66792
shared pool  PX QC msg stats                                          2904
shared pool  PX server msg stats                                      2904
shared pool  PX msg pool                                           8192000

Since 10g, if Automatic Shared Memory Management(ASMM) is enabled, the "PX msg pool" will be allocated from large_pool:

SYS @ SYS @ test > select * from v$sgastat where name like '%PX%';
POOL         NAME                                                    BYTES
------------ -------------------------------------------------- ----------
shared pool  PX subheap desc                                           256
shared pool  PX msg pool struct                                         56
shared pool  PX QC deq stats                                          1696
shared pool  PX server deq stats                                      1696
shared pool  PX list of chunk lists                                   1088
shared pool  PX subheap                                             757656
shared pool  PX QC msg stats                                          2904
shared pool  PX server msg stats                                      2904
large pool   PX msg pool                                           8088608

Ignore those names starting with PX in shared_pool, most of they are only some kind of descriptions for "PX msg pool". For example, "PX msg pool struct" describle the structure of "PX msg pool". "PX server msg stats" records statistics afor "PX msg pool".

Recently We hit the error 04031 in large_pool:

ORA-04031: unable to allocate 2048024 bytes of shared memory ("large pool","unknown object","large pool","PX msg pool")

Obviously it is because insufficient space in large pool.
Current size for large pool is 16m.This size fit most cases, for example, parallel 10.
But in our case the issue SQL's parallel is 20:

*** 2012-06-20 22:11:37.731
dbkedDefDump(): Starting incident default dumps (flags=0x2, level=3, mask=0x0)
----- Current SQL Statement for this session (sql_id=5a10rbj2tx6j4) -----
select substrb(dump(val,16,0,32),1,120) ep, cnt from (select /*+ no_expand_table(t) index_rs(t) parallel(t,20) parallel_index(t,20) dbms_stats cursor_shari
ng_exact use_weak_name_resl dynamic_sampling(0) no_monitoring no_substrb_pad */max(substrb("BUSINXXXMENT",1,32)) val,count(*) cnt from "XXXAVETH"."XXX_EXT" t where substrb("BUSINXXXMENT",1,32) is not null group by nlssort(substrb("BUSINXXXMENT",1,32), 'NLS_SORT = binary')) order by nlssor
t(val,'NLS_SORT = binary')

If the SGA have enough free memory, this is not a issue, because large_pool=16m only define an lower bound of large_pool. When large_pool is lack of space, ASMM will try to allocate some space for it:

SYS @ test > select * from v$sgastat where POOL ='large pool';
POOL         NAME                                               BYTES
------------ -------------------------------------------------- ----------
large pool   PX msg pool                                        8088608
large pool   free memory                                        300000
<---- here from another session i run one SQL with parallel 20：--->

SYS @ test > /
POOL         NAME                                               BYTES
------------ -------------------------------------------------- ----------
large pool   PX msg pool                                        26287976
large pool   free memory                                        2883640
large pool   KGH: NO ACCESS                                     188512

We can see large pool extends automaticlly. Also notice: "KGH: NO ACCESS", it means ASMM retrive some space from large_pool and offer to db_cache.But in our case, the SGA already reached its sga_max_size, so there is no extra space to offer to large_pool.

The issue SQL is coming from a daily gather stats job:

exec DBMS_STATS.GATHER_SCHEMA_STATS(ownname=>'XXXVETH',estimate_percent=>20,block_sample=>false,method_opt=>'For all columns size 225',GRANULARITY=>'ALL',degree=>20,cascade=>true);

To fix the issue, we can either:
1. increase large pool size.
2. reduce degree in gather stats job.
More......

Real meaning and Simulate "ORA-01152: file was not restored from a sufficiently old backup"

I saw many times people asked the meaning of "ORA-01152: file n was not restored from a sufficiently old backup" and the difference between "ORA-01152" and "ORA-01113: file needs media recovery".

First of all,  "ORA-01152" is not related to controlfile. I say so because someone said  "ORA-01152: file was not restored from a sufficiently old backup" is caused by old controlile.
It is not true. A simple prove is: even you recreate controlfile with "create database", you can still get the error.

Then what is the real meaning for "ORA-01152: file was not restored from a sufficiently old backup"?

To figure it out, let's firstly learn below knowledge regarding how oracle know if a recovery is nessasary during startup.
Infact oracle make the judgement from below two flags in datafile header block:
1. OFFSET 0138-0139: DB_state.
00 means DB is down, 04 means DB is running.
When a DB is up and running, this flag is 04. During an normal shutdown, oracle will change this flag to 00.
So if oracle read 04 of the flag during startup, then oracle will be aware that latest shutdown was not commpleted succeesfully, so a recovery will be nessasary.

2. OFFSET 0484-0489: checkpoint_change#
During a DB clean shutdown, oracle will make a full checkpoint, so all datafiles' checkpoint_change# will be sync.
So if in a startup checking, oracle found checkpoint_change# are inconsistent among datafiles, then an recovery will be required.


OK. Now we know how oracle judge the recovery, from two flags DB_state and checkpoint_change#.
Then it is a simple math that there are four combinations:
Scenario 1.DB_state=00 and checkpoint_change# are consistent.
It means lastest shutdown is an succeed clean shutdown. Oracle won't try to perform any recovery.

Scenario 2.DB_state=04 and checkpoint_change# are inconsistent.
95% DB crashing is located in this senerio. When a DB crashed, oracle have no time to change DB_state to 00, and checkpoint_change# among datafiles are not consistent.
In this senerio, when DB startup, a recovery will be required to perform, if you try to open resetlogs without recover, you will get below error:
ORA-01113: file 5 needs media recovery
ORA-01110: data file 5: '/data/oracle/data/miao/miao/stream01.dbf'
This is an common error we often get. We know very well about it.

Scenario 3.DB_state=04 and checkpoint_change# are consistent.
How can this happen? For example, you execute command "alter system checkpoint;" after this command you immediately execute below command:
shutdown abort;
Then checkpoint_change# among datafiles are the same. But DB_state remians 04.

Next time when oracle startup, oracle will read DB_state=04, which means, as i already introduced, latest close for this datafile is not an normal close.
The error here you will get is the same in senerio 2:
ORA-01113: file 5 needs media recovery

Scenario 4.state_flag=00 and checkpoint_change# are inconsistent.
In this case, you will get error "ORA-01152: file n was not restored from a sufficiently old backup".

But how could this happen? How can it be possible when checkpoint_change# are inconsistent while state_flag=00 which means a clean shutdown?

For example:
At time point T1, you shutdown database and made a closed clean backup.
Then you startup DB and do some operations and swtich logfile for mutiple times. Then at time point T2, again you normally shutdown the DB.

Now you delete some T2 datafiles and replace it with datafiles that you backuped at timepoint T1.
So now all these datafiles state_flag=00 because all datafiles are from an clean closed shutdown, but checkpoint_change# among these datafiles are not consistent.
In this sernerio, when you try to open resetlogs DB without recovery, you will get below error:
ORA-01152: file 1 was not restored from a sufficiently old backup
ORA-01110: data file 1: '/data/oracle/data/miao/miao/system01.dbf'
More......

CSSD died with no error during GM grock activity

Recently i observed one node crashed and rebooted case: during the node's clusterware starting, its CSSD suddenly died during GM(Group Management) grock activity without any error. And server got a reboot because of that.

CSSD shows no errors:
2012-06-08 09:18:10.495: [ CSSD][1106151744]clssgmTestSetLastGrockUpdate: grock(CLSN.oratab), updateseq(0) msgseq(1), lastupdt<(nil)>, ignoreseq(0)
2012-06-08 09:18:10.495: [ CSSD][1106151744]clssgmAddMember: granted member(0) flags(0x2) node(3) grock (0x2aaab0063ac0/CLSN.oratab)
2012-06-08 09:18:10.495: [ CSSD][1106151744]clssgmCommonAddMember: global lock grock CLSN.oratab member(0/Remote) node(3) flags 0x2 0xb00c1df0
2012-06-08 09:18:10.495: [ CSSD][1106151744]clssgmHandleGrockRcfgUpdate: grock(CLSN.oratab), updateseq(1), status(0), sendresp(1)
2012-06-08 09:18:10.533: [ CSSD][1106151744]clssgmTestSetLastGrockUpdate: grock(CLSN.oratab), updateseq(1) msgseq(2), lastupdt<0x2aaab0054dc0>, ignoreseq(0)
2012-06-08 09:18:10.533: [ CSSD][1106151744]clssgmRemoveMember: grock CLSN.oratab, member number 0 (0x2aaab00c1df0) node number 3 state 0x0 grock type 3
2012-06-08 09:18:10.533: [ CSSD][1106151744]clssgmResetGrock: grock(CLSN.oratab) reset=1
2012-06-08 09:18:10.533: [ CSSD][1106151744]clssgmHandleGrockRcfgUpdate: grock(CLSN.oratab), updateseq(2), status(0), sendresp(1)
2012-06-08 09:18:10.535: [ CSSD][1106151744]clssgmTestSetLastGrockUpdate: grock(CLSN.oratab), updateseq(2) msgseq(3), lastupdt<0x2aaab0097f50>, ignoreseq(0)
2012-06-08 09:18:10.535: [ CSSD][1106151744]clssgmDeleteGrock: (0x2aaab0063ac0) grock(CLSN.oratab) deleted
<<----here CSSD died, it was doing some GM grock maintance and suddenly died and then server reboot, here we see no abnormal information---->>
2012-06-08 09:28:30.052: [ CSSD][684039456]clsu_load_ENV_levels: Module = CSSD, LogLevel = 2, TraceLevel = 0
2012-06-08 09:28:30.052: [ CSSD][684039456]clsu_load_ENV_levels: Module = GIPCNM, LogLevel = 2, TraceLevel = 0
2012-06-08 09:28:30.052: [ CSSD][684039456]clsu_load_ENV_levels: Module = GIPCGM, LogLevel = 2, TraceLevel = 0
2012-06-08 09:28:30.052: [ CSSD][684039456]clsu_load_ENV_levels: Module = GIPCCM, LogLevel = 2, TraceLevel = 0
2012-06-08 09:28:30.052: [ CSSD][684039456]clsu_load_ENV_levels: Module = CLSF, LogLevel = 0, TraceLevel = 0
2012-06-08 09:28:30.052: [ CSSD][684039456]clsu_load_ENV_levels: Module = SKGFD, LogLevel = 0, TraceLevel = 0
2012-06-08 09:28:30.052: [ CSSD][684039456]clsu_load_ENV_levels: Module = GPNP, LogLevel = 1, TraceLevel = 0
2012-06-08 09:28:30.052: [ CSSD][684039456]clsu_load_ENV_levels: Module = OLR, LogLevel = 0, TraceLevel = 0
[ CSSD][684039456]clsugetconf : Configuration type [4].
2012-06-08 09:28:30.052: [ CSSD][684039456]clssscmain: Starting CSS daemon, version 11.2.0.2.0, in (clustered) mode with uniqueness value 1339162110

Very soon CSSDMONITOR found the CSSD had died so it then sync (reboot) the node. Below is from CSSDMONITOR log:
2012-06-08 09:18:12.479: [ CSSCLNT][1116543296]clsssRecvMsg: got a disconnect from the server while waiting for message type 27
2012-06-08 09:18:12.479: [ CSSCLNT][1113389376]clsssRecvMsg: got a disconnect from the server while waiting for message type 22
2012-06-08 09:18:12.479: [ USRTHRD][1113389376] clsnwork_queue: posting worker thread
2012-06-08 09:18:12.479: [ USRTHRD][1113389376] clsnpollmsg_main: exiting check loop
2012-06-08 09:18:12.479: [GIPCXCPT][1116543296]gipcInternalSend: connection not valid for send operation endp 0x86da430 [0000000000000162] { gipcEndpoint : l
ocalAddr 'clsc://(ADDRESS=(PROTOCOL=ipc)(KEY=)(GIPCID=031d7676-63f8ad6d-9852))', remoteAddr 'clsc://(ADDRESS=(PROTOCOL=ipc)(KEY=OCSSD_LL_cihcissdb759_)(GIPCI
D=63f8ad6d-031d7676-9884))', numPend 0, numReady 0, numDone 0, numDead 0, numTransfer 0, objFlags 0x0, pidPeer 9884, flags 0x3861e, usrFlags 0x20010 }, ret g
ipcretConnectionLost (12)
2012-06-08 09:18:12.479: [GIPCXCPT][1116543296]gipcSendSyncF [clsssServerRPC : clsss.c : 6271]: EXCEPTION[ ret gipcretConnectionLost (12) ] failed to send o
n endp 0x86da430 [0000000000000162] { gipcEndpoint : localAddr 'clsc://(ADDRESS=(PROTOCOL=ipc)(KEY=)(GIPCID=031d7676-63f8ad6d-9852))', remoteAddr 'clsc://(AD
DRESS=(PROTOCOL=ipc)(KEY=OCSSD_LL_cihcissdb759_)(GIPCID=63f8ad6d-031d7676-9884))', numPend 0, numReady 0, numDone 0, numDead 0, numTransfer 0, objFlags 0x0,
pidPeer 9884, flags 0x3861e, usrFlags 0x20010 }, addr 0000000000000000, buf 0x428d0d80, len 80, flags 0x8000000
2012-06-08 09:18:12.479: [ CSSCLNT][1116543296]clsssServerRPC: send failed with err 12, msg type 7
2012-06-08 09:18:12.479: [ CSSCLNT][1116543296]clsssCommonClientExit: RPC failure, rc 3
2012-06-08 09:18:12.479: [ CSSCLNT][1094465856]clsssRecvMsg: got a disconnect from the server while waiting for message type 1
2012-06-08 09:18:12.479: [ CSSCLNT][1094465856]clssgsGroupGetStatus: communications failed (0/3/-1)
2012-06-08 09:18:12.479: [ CSSCLNT][1094465856]clssgsGroupGetStatus: returning 8
2012-06-08 09:18:12.479: [ USRTHRD][1114966336] clsnwork_process_work: calling sync
2012-06-08 09:18:12.479: [ USRTHRD][1094465856] clsnomon_status: Communications failure with CSS detected. Waiting for sync to complete...

Checked OS log and no errors gernerate during that period of time:
Jun 8 09:18:02 node759 snmpd[21008]: Connection from UDP: [127.0.0.1 ]:27643
Jun 8 09:18:02 node759 snmpd[21008]: Received SNMP packet(s) from UDP: [127.0.0.1]:27643
Jun 8 09:18:02 node759 snmpd[21008]: Connection from UDP: [127.0.0.1]:27643
Jun 8 09:18:02 node759 snmpd[21008]: Connection from UDP: [127.0.0.1]:26972
Jun 8 09:18:02 node759 snmpd[21008]: Received SNMP packet(s) from UDP: [127.0.0.1]:26972
Jun 8 09:18:02 node759 snmpd[21008]: Connection from UDP: [127.0.0.1]:17368
Jun 8 09:18:02 node759 snmpd[21008]: Received SNMP packet(s) from UDP: [127.0.0.1]:17368
<<<----here suddenly rebooted with no information----->>>
Jun 8 09:23:03 node759 syslogd 1.4.1: restart.
Jun 8 09:23:03 node759 kernel: klogd 1.4.1, log source = /proc/kmsg started.
Jun 8 09:23:03 node759 kernel: g enabled (TM1)
Jun 8 09:23:03 node759 kernel: Intel(R) Xeon(R) CPU X7550 @ 2.00GHz stepping 06
Jun 8 09:23:03 node759 kernel: CPU 3: Syncing TSC to CPU 0.
Jun 8 09:23:03 node759 kernel: CPU 3: synchronized TSC with CPU 0 (last diff -6 cycles, maxerr 477 cycles)
Jun 8 09:23:03 node759 kernel: SMP alternatives: switching to SMP code
Jun 8 09:23:03 node759 kernel: Booting processor 4/32 APIC 0x10
Jun 8 09:23:03 node759 kernel: Initializing CPU#4

Searched on network, only find one bug report describle an similiar issue:
Bug 13954099: CSSD DIES SUDDENLY WITHOUT ANY ERRORS

Just like our case, In the bug report, cluster version is also 11.2.0.2, and the CSSD died during a GM grock activity without any errors.
Then CSSD monitor rebooted the node after found that CSSD died.

This problem is not repeatable, the next time we re-bring up the cluster on the node, it succeed. The issue not happen again.

No Patch avialable as yet.
More......

identify root session among hundreds of locks using hanganalyze

Today, one of our most critical production DB reports lock issue.
When i login into the DB there are already more then 200+ locks, and most of them are TM lock.
Below is the list:
SESS                   ID1        ID2      LMODE    REQUEST TY      CTIME
--------------- ---------- ---------- ---------- ---------- -- ----------
Holder: 4738         16737          0          2          0 TM       4021
Holder: 2080         16737          0          2          0 TM       4021
............
............
Holder: 3480         17347          0          3          0 TM       5958
Waiter: 4975         17347          0          0          2 TM       5792
Waiter: 1015         17347          0          0          2 TM       4090
Waiter: 1058         17347          0          0          2 TM       5832
............
Holder: 4729        983064    3155735          6          0 TX       3229
Waiter: 2301        983064    3155735          0          6 TX       2327
Waiter: 1194       2752522    2373725          0          6 TX       2931
Waiter: 3359       2752522    2373725          0          6 TX       2397

286 rows selected.

There are see 286 locking sessions as well as so dozens blockers which of couse we can't kill them all.
Then here is the problem: how to identify the root session?

In 11g there is a powerful View "V$WAIT_CHAINS". But our DB is 10g.
BLOCKING_SESSION column in v$session is useful but not for so many locks and so many blockers.

systemstate dump is also not a choice since i lost most of my scripts including ass109.awk after computer re-installed.

Then the left choice is hanganalyze, let's do it:
==============
HANG ANALYSIS:
==============
Found 106 objects waiting for
<0/4634/18424/0x600086e0/28223/enq: TM - contention>
Found 105 objects waiting for
<0/3317/59720/0x20005f58/27464/enq: TM - contention>
...............
...............
Found 20 objects waiting for
<0/4974/30755/0x60041418/29550/enq: TM - contention>
Open chains found:
Chain 1 : :
<0/3480/26248/0x200229e8/190/db file sequential read>
-- <0/4634/18424/0x600086e0/28223/enq: TM - contention>
-- <0/679/55269/0xa004e990/13104/enq: TM - contention>
-- <0/793/864/0xa0054088/25644/enq: TM - contention>
Chain 2 : :
<0/3797/1/0x20001048/24805/log file parallel write>
-- <0/707/60023/0xa001bb38/27013/log file sync>
Other chains found:
Chain 3 : :
<0/689/49815/0xa0016c28/15330/enq: TM - contention>
-- <0/793/864/0xa0054088/25644/enq: TM - contention>
...............
...............
Chain 104 : :       ---------(oops.  104 chains!!)
<0/5041/14667/0x6000b650/6616/PX Deq: Table Q Normal>
State of nodes
([nodenum]/cnode/sid/sess_srno/session/ospid/state/start/finish/[adjlist]/predecessor):
[678]/0/679/55269/0xa05c3618/13104/NLEAF/1/8/[4633][3316]/792
[681]/0/682/5041/0xa05c7650/22742/IGN/9/10//none
[682]/0/683/33667/0xa05c8bb8/27585/IGN/11/12//none
[687]/0/688/35783/0xa05cf6c0/13708/IGN/13/14//none
...............
...............
[5063]/0/5064/1/0x608d2e40/24807/IGN/1657/1658//none
[5064]/0/5065/1/0x608d43a8/24799/IGN/1659/1660//none
====================
END OF HANG ANALYSIS
====================

From above hanganylyze session it is clear that root chain (Open chains part) is:
Open chains found:
Chain 1 : :
<0/3480/26248/0x200229e8/190/db file sequential read>
-- <0/4634/18424/0x600086e0/28223/enq: TM - contention>
-- <0/679/55269/0xa004e990/13104/enq: TM - contention>
-- <0/793/864/0xa0054088/25644/enq: TM - contention>
Chain 2 : :
<0/3797/1/0x20001048/24805/log file parallel write>
-- <0/707/60023/0xa001bb38/27013/log file sync>

And the LEAF is:
server444[oracle]_hrpp1> cat supp_ora_17698.trc|grep -i single|grep -v none
[level 5] : 83 node dumps -- [SINGLE_NODE] [SINGLE_NODE_NW] [IGN_DMP]
server444[oracle]_hrpp1> cat supp_ora_17698.trc|grep -i leaf|grep -v NLEAF
[level 4] : 2 node dumps -- [REMOTE_WT] [LEAF] [LEAF_NW]
[3479]/0/3480/26248/0x20729710/190/LEAF/3/4//4633
[3796]/0/3797/1/0x208d18d8/24805/LEAF/28/29//706


Now it is clear to us Session 3480 and 3797 have the most suspect.
After check these two sessions in DB, we identify the 3480 session as the root session since it is also an pldevelop session:
SSID SERIAL# SPID OSUSER USERNAME MACHINE LOGON_TIME STATE STATUS SQL_ID PREV_SQL_ID WAIT_TIME SECONDS_IN_WAIT EVENT BLOCKING_INSTANCE BLOCKING_SESSION
----- ---------- ------------ ---------- -------------------- ---
PROGRAM
------------------------------------------------
SQL_TEXT
-----------------------------------------------------------------
3480 26248 190 324979 SUPXXXHOC MYHOMEGDC\MYH136092 07-JUN-12 16:17 WAITED SHORT TIME ACTIVE 5xzua1wzkfwpy fvgnun67x1bcg -1 1 db file sequential read
plsqldev.exe
DELETE FROM T_HAD_XXXX_AUDIT WHERE FORM_ID = :B1

After killed the session all 280+ locks released immediate.
More......