RAC database hung analysis

If rac database instance is slow due to deadlock or other blocking ,we can use oradebug hang analyzer to deep dive into the root of cause.

Lets troubleshoot with a simulation

I create a sample table for testing purpose

SQL> CREATE TABLE regions
   ( region_id NUMBER
   CONSTRAINT region_id_nn NOT NULL
   , region_name VARCHAR2(25)
   );
CREATE UNIQUE INDEX reg_id_pk
         ON regions (region_id);
ALTER TABLE regions
         ADD ( CONSTRAINT reg_id_pk
   PRIMARY KEY (region_id)
   ) ;  2    3    4    5


Table created.

SQL>   2
Index created.

SQL>   2    3    4


Table altered.

I insert rows on node 1 and donot commit the changes

SQL> SQL> SQL> SQL>
SQL>
SQL> INSERT INTO regions VALUES
   ( 1
   , 'Europe'
   );
INSERT INTO regions VALUES
   ( 2
   , 'Americas'
   );
INSERT INTO regions VALUES
   ( 3
   , 'Asia'
   );
INSERT INTO regions VALUES
   ( 4
   , 'Middle East and Africa'
   );  2    3    4

1 row created.

SQL>   2    3    4
1 row created.

SQL>   2    3    4
1 row created.

SQL>   2    3    4
1 row created.

At the same time i insert the same rows on the same table with different user but from node 2!

SQL> select name from v$database;

NAME
---------
RACDB

SQL> select instance_name from v$instance;

INSTANCE_NAME
----------------
RACDB2

SQL> show user
USER is "TEST"
SQL> INSERT INTO sys.regions VALUES
   ( 1
   , 'Europe'
   );
INSERT INTO sys.regions VALUES
   ( 2
   , 'Americas'
   );
INSERT INTO sys.regions VALUES
   ( 3
   , 'Asia'
   );
INSERT INTO sys.regions VALUES
   ( 4
   , 'Middle East and Africa'
   );  2    3    4

The database is hung as node 1 blocks node 2 to insert rows

Enable the hang analyzer on one of the RAC nodes to generate trace files for analyzing

SQL> oradebug setmypid
oStatement processed.
SQL> radebug unlimit
oradebugStatement processed.
SQL> oradebug setmypid
SP2-0734: unknown command beginning "oradebugor..." - rest of line ignored.
SQL> oradebug setmypid
Statement processed.
SQL> oradebug unlimit
Statement processed.
SQL> oradebug setinst all
Statement processed.
SQL> oradebug -g all hanganalyze 3
Hang Analysis in /grid/base/diag/rdbms/racdb/RACDB1/trace/RACDB1_diag_3917.trc
SQL> oradebug -g all hanganalyze 3
Hang Analysis in /grid/base/diag/rdbms/racdb/RACDB1/trace/RACDB1_diag_3917.trc
SQL> oradebug -g all hanganalyze 3
Hang Analysis in /grid/base/diag/rdbms/racdb/RACDB1/trace/RACDB1_diag_3917.trc

In the hang trace file ,we can find the diagnostic details of RAC1 blocking RAC2 with wait event ,blocking id,waiting time etc which is pretty much valuable information!!

Chains most likely to have caused the hang:
 [a] Chain 1 Signature: <not in a wait><='rdbms ipc reply'<='enq: TX - row lock contention'
     Chain 1 Signature Hash: 0x7ba3a1e1

===============================================================================
Non-intersecting chains:

-------------------------------------------------------------------------------
Chain 1:
-------------------------------------------------------------------------------
    Oracle session identified by:
    {
                instance: 2 (racdb.racdb2)
                   os id: 5922
              process id: 40, oracle@RAC2 (TNS V1-V3)
              session id: 60
        session serial #: 67
    }
    is waiting for 'enq: TX - row lock contention' with wait info:
    {
                      p1: 'name|mode'=0x54580004
                      p2: 'usn<<16 | slot'=0x6000e
                      p3: 'sequence'=0x32b
            time in wait: 5 min 50 sec
           timeout after: never
                 wait id: 97
               blocking: 0 sessions
             current sql: INSERT INTO sys.regions VALUES
   ( 1
   , 'Europe'
   )
             short stack: ksedsts()+265<-ksdxfstk()+19<-ksdxcb()+1646<-sspuser()+100<-semtimedop()+36<-sskgpwwait()+202<-skgpwwait()+138<-ksliwat()+1602<-kslwaitctx()+138<-kjusuc()+6900<-ksipgetctxi()+1641<-ksqcmi()+23174<-ksqgtlctx()+3204<-ksqgelctx()+469<-ktuGetTxForXid()+95<-ktcwit1()+272<-ktbgtl0()+958<-kdiins0()+46577<-kdiinsp()+61<-kauxsin()+1634<-qesltcLoadIndexList()+718<-qesltcLoadIndexes()+43<-qerltcSimpleSingleInsRowCBK()+65<-qerltcSingleRowLoad()+228<-qerltcFetch()+301<-insexe()+567<-opiexe()+4953<-kpoal8()+1811<-opiodr()+962<-
            wait history:
              * time between current wait and wait #1: 0.002054 sec
              1.       event: 'SQL*Net message from client'
                 time waited: 26.277790 sec
                     wait id: 96              p1: 'driver id'=0x62657100
                                              p2: '#bytes'=0x1
              * time between wait #1 and #2: 0.000002 sec
              2.       event: 'SQL*Net message to client'
                 time waited: 0.000001 sec
                     wait id: 95              p1: 'driver id'=0x62657100
                                              p2: '#bytes'=0x1
              * time between wait #2 and #3: 0.000031 sec
              3.       event: 'SQL*Net message from client'
                 time waited: 0.000146 sec
                     wait id: 94              p1: 'driver id'=0x62657100
                                              p2: '#bytes'=0x1
    }
    and is blocked by
 => Oracle session identified by:
    {
                instance: 1 (racdb.racdb1)
                   os id: 11456

oradebug is the advisable tool in times of performance issues!!

Until the session 1 in node 1 releases the lock from the rows in the table,the other session couldnot modify the rows in the same table.So if the user doesnot commit and flush the block changes to the disk ,other sessions have to sit idle and wait in the queue!!