My Oracle Support Banner

RAC Database Instance Crashed And Post Restart Instance Recovery Hang At "PARALLEL RECOVERY COORD WAIT FOR REPLY" Which Was Blocked By "RDBMS IPC MESSAGE" (Doc ID 2682836.1)

Last updated on JULY 06, 2020

Applies to:

Oracle Database - Enterprise Edition - Version 12.2.0.1 and later
Information in this document applies to any platform.

Symptoms

<ORACLE_BASE>/diag/rdbms/<DB>/<SID>/trace/Alert_<SID>.log

=================

2020-06-08T00:45:28.117095+00:00
ERROR: failed to establish dependency between database <DBNAME> and diskgroup resource ora.DATA.dg
2020-06-08T00:45:34.688947+00:00
ALTER SYSTEM SET remote_listener='qdbrac-scan:1521' SCOPE=MEMORY SID='<DBNAME>';
2020-06-08T00:45:34.690907+00:00
ALTER SYSTEM SET listener_networks='' SCOPE=MEMORY SID='<DBNAME>';
ALTER DATABASE MOUNT /* db agent *//* {3:4086:48574} */
2020-06-08T00:45:38.766476+00:00
Network throttle feature is disabled as mount time

2020-06-08T00:45:47.349184+00:00

* instance 1 validates domain 0
2020-06-08T00:45:58.531087+00:00
Successful mount of redo thread 2, with mount id 2698364515
2020-06-08T00:45:58.537576+00:00
Database mounted in Shared Mode (CLUSTER_DATABASE=TRUE)
Lost write protection disabled
Using STANDBY_ARCHIVE_DEST parameter default value as USE_DB_RECOVERY_FILE_DEST
2020-06-08T00:45:58.978788+00:00
ARCH: STARTING ARCH PROCESSES
Starting background process ARC0
2020-06-08T00:45:59.041887+00:00
ARC0 started with pid=189, OS id=67513
Starting background process ARC1
2020-06-08T00:45:59.100722+00:00
ARC1 started with pid=190, OS id=67517
Starting background process ARC2
2020-06-08T00:45:59.148923+00:00
ARC2 started with pid=188, OS id=67519
Starting background process ARC3
2020-06-08T00:45:59.199845+00:00
ARC3 started with pid=191, OS id=67521
ARC0: Archival started
ARC1: Archival started
ARC2: Archival started
2020-06-08T00:45:59.200370+00:00
ARC1: Becoming a 'no FAL' ARCH
ARC1: Becoming the 'no SRL' ARCH
2020-06-08T00:45:59.210498+00:00
ARC3: Archival started
ARCH: STARTING ARCH PROCESSES COMPLETE
2020-06-08T00:45:59.272902+00:00
TT00: Gap Manager starting (PID:67527)
2020-06-08T00:46:02.157160+00:00
Completed: ALTER DATABASE MOUNT /* db agent *//* {3:4086:48574} */
ALTER DATABASE OPEN /* db agent *//* {3:4086:48574} */
2020-06-08T00:46:34.012282+00:00
Ping without log force is disabled:
  not an Exadata system.
Picked broadcast on commit scheme to generate SCNs
2020-06-08T00:46:37.645660+00:00
Endian type of dictionary set to little
2020-06-08T01:25:08.775140+00:00
NOTE: ASMB mounting group 1 (ARCH)
NOTE: ASM background process initiating disk discovery for grp 1 (reqid:0)
NOTE: Assigning number (1,3) to disk (<DISK_PATH>4)
NOTE: Assigning number (1,0) to disk (<DISK_PATH>3)
NOTE: Assigning number (1,1) to disk (<DISK_PATH>2)
NOTE: Assigning number (1,2) to disk (<DISK_PATH>1)
SUCCESS: mounted group 1 (ARCH)
NOTE: grp 1 disk 3: ARCH_0003 path:<DISK_PATH>4
NOTE: grp 1 disk 0: ARCH_0000 path:<DISK_PATH>3
NOTE: grp 1 disk 1: ARCH_0001 path:<DISK_PATH>2
NOTE: grp 1 disk 2: ARCH_0002 path:<DISK_PATH>1
2020-06-08T01:25:08.940034+00:00
ERROR: failed to establish dependency between database <DBNAME> and diskgroup resource ora.ARCH.dg

<ORACLE_BASE>/diag/rdbms/<DB>/<SID>/trace/<SID>_diag_206311.trc
Chains most likely to have caused the hang:
 [a] Chain 1 Signature: 'rdbms ipc message'<='checkpoint completed'<='parallel recovery coord wait for reply'<='gc domain validation'<='library cache lock'
     Chain 1 Signature Hash: 0x13a57715
 [b] Chain 2 Signature: 'gc current request'<='gc buffer busy acquire'
     Chain 2 Signature Hash: 0x8823aa2a
 [c] Chain 3 Signature: 'gc current request'<='enq: TX - row lock contention'
     Chain 3 Signature Hash: 0x670f45d4


-------------------------------------------------------------------------------
Chain 1:
-------------------------------------------------------------------------------
    Oracle session identified by:
    {
                instance: 1 (<DBNAME>)
                   os id: 223050
              process id: 3456, oracle@<HOSTNAME>
              session id: 19
        session serial #: 44659
    }
    is waiting for 'library cache lock' with wait info:
    {
                      p1: 'handle address'=0xfc89f470
                      p2: 'lock address'=0x3fc7fde988
                      p3: '100*mode+namespace'=0x7f0002
            time in wait: 1 min 11 sec (last interval)
            time in wait: 6 min 45 sec (total)
           timeout after: 8 min 14 sec
                 wait id: 8
                blocking: 0 sessions
             current sql: <none>
             short stack: ksedsts()+346<-ksdxfstk()+71<-ksdxcb()+912<-sspuser()+217<-__sighandler()<-semtimedop()+10<-skgpwwait()+200<-ksliwat()+2304<-kslwaitctx()+212<-kjusuc()+9058<-ksipgetctxia()+5359<-ksixpgetia()+167<-kqlmLock()+3201<-kqlmClusterLock()+209<-kgllkal()+3417<-kglLock()+1361<-kglget()+290<-kziaRetrieveLSLT()+333<-kpolnb()+2735<-kpoauth()+1766<-opiodr()+1229<-ttcpip()+1263<-opitsk()+1940<-opiino()+941<-opiodr()+1229<-opidrv()+1021<-sou2o()+145<-opimai_real()+455<-ssthrdmain()+417<-main()+262<-__libc_start_main()+245
            wait history:
              * time between current wait and wait #1: 0.000000 sec
              1.       event: 'latch: ges resource hash list'
                 time waited: 0.000807 sec
                     wait id: 13               p1: 'address'=0x270a6e4928
                                               p2: 'number'=0xb3
                                               p3: 'why'=0x0
              * time between wait #1 and #2: 0.000000 sec
              2.       event: 'library cache lock'
                 time waited: 17.501467 sec (last interval)
                 time waited: 5 min 33 sec (total)
                     wait id: 8                p1: 'handle address'=0xfc89f470
                                               p2: 'lock address'=0x3fc7fde988
                                               p3: '100*mode+namespace'=0x7f0002
              * time between wait #2 and #3: 0.000000 sec
              3.       event: 'latch: ges resource hash list'
                 time waited: 0.000552 sec
                     wait id: 12               p1: 'address'=0x270a6e4928
                                               p2: 'number'=0xb3
                                               p3: 'why'=0x0
    }
    and is blocked by
 => Oracle session identified by:
    {
                instance: 1 (<DBNAME>)
                   os id: 218254
              process id: 1435, oracle@<HOSTNAME>
              session id: 7229
        session serial #: 48995
    }
    which is waiting for 'gc domain validation' with wait info:
    {
                      p1: 'file#'=0x1d81
                      p2: 'block#'=0x19f9
                      p3: 'class#'=0x1
            time in wait: 0.960235 sec
      heur. time in wait: 14.961266 sec
           timeout after: 1.039765 sec
                 wait id: 257
                blocking: 2152 sessions
             current sql: update user$ set spare6=DECODE(to_char(:2, 'YYYY-MM-DD'), '0000-00-00', to_date(NULL), :2) where user#=:1
             short stack: ksedsts()+346<-ksdxfstk()+71<-ksdxcb()+912<-sspuser()+217<-__sighandler()<-semtimedop()+10<-skgpwwait()+200<-ksliwat()+2304<-kslwaitctx()+212<-kclwrcv()+387<-kcbgcur()+36724<-ktbgcur()+126<-kdddgb()+868<-kdusru()+551<-kauupd()+419<-updrow()+1826<-qerupFetch()+2352<-updaul()+1399<-updThreePhaseExe()+325<-updexe()+435<-opiexe()+11054<-kpoal8()+2678<-opiodr()+1229<-kpoodrc()+42<-rpiswu2()+627<-kpoodr()+656<-upirtrc()+2390<-kpurcsc()+102<-kpuexec()+10518<-OCIStmtExecute()+41<-kzulsltUpdate()+848<-kglHandleFlush()+264<
            wait history:
              * time between current wait and wait #1: 0.000313 sec
              1.       event: 'gc domain validation'
                 time waited: 1.999727 sec
                     wait id: 256              p1: 'file#'=0x1d81
                                               p2: 'block#'=0x19f9
                                               p3: 'class#'=0x1
              * time between wait #1 and #2: 0.000270 sec
              2.       event: 'gc domain validation'
                 time waited: 1.999775 sec
                     wait id: 255              p1: 'file#'=0x1d81
                                               p2: 'block#'=0x19f9
                                               p3: 'class#'=0x1
              * time between wait #2 and #3: 0.000219 sec
              3.       event: 'gc domain validation'
                 time waited: 1.999738 sec
                     wait id: 254              p1: 'file#'=0x1d81
                                               p2: 'block#'=0x19f9
                                               p3: 'class#'=0x1
    }
    and is blocked by
 => Oracle session identified by:
    {
                instance: 1 (<DBNAME>)
                   os id: 207440
              process id: 91, oracle@<HOSTNAME> (SMON)
              session id: 7190
        session serial #: 43083
    }
    which is waiting for 'parallel recovery coord wait for reply' with wait info:
    {
                      p1: ''=0x1001001d
                      p2: ''=0x4bf9
                      p3: ''=0x3db07d630
            time in wait: 171 min 24 sec
      heur. time in wait: 171 min 24 sec
           timeout after: never
                 wait id: 211036434
                blocking: 2994 sessions
             current sql: <none>
             short stack: ksedsts()+346<-ksdxfstk()+71<-ksdxcb()+912<-sspuser()+217<-__sighandler()<-__poll()+16<-ipcgxp_selectex()+409<-ipclw_wait()+1045<-ksxpwait_ipclw()+3844<-ksxpwait_int()+22103<-ksxpwait()+845<-ksliwat()+11015<-kslwaitctx()+212<-kxfpqidqr()+2513<-kxfpqdqr()+371<-kcrprd()+123<-kcrpcf()+285<-kcratr_apply()+29020<-kcratr()+4552<-kctrec()+12434<-kcvirv_internal()+14940<-kcvirv()+216<-ktmmon()+3494<-ktmSmonMain()+218<-ksbrdp()+1079<-opirip()+609<-opidrv()+602<-sou2o()+145<-opimai_real()+202<-ssthrdmain()+417<-main()+262<-
            wait history:
              * time between current wait and wait #1: 0.000001 sec
              1.       event: 'parallel recovery coord wait for reply'
                 time waited: 0.000001 sec
                     wait id: 211036433       
              * time between wait #1 and #2: 0.000001 sec
              2.       event: 'parallel recovery coord wait for reply'
                 time waited: 0.000001 sec
                     wait id: 211036432       
              * time between wait #2 and #3: 0.000001 sec
              3.       event: 'parallel recovery coord wait for reply'
                 time waited: 0.000001 sec
                     wait id: 211036431       
    }
    and is blocked by
 => Oracle session identified by:
    {
                instance: 1 (<DBNAME>)
                   os id: 13260
              process id: 260, oracle@<HOSTNAME> (P00T)
              session id: 5430
        session serial #: 55825
    }
    which is waiting for 'checkpoint completed' with wait info:
    {
            time in wait: 4.789986 sec
      heur. time in wait: 171 min 24 sec
           timeout after: 0.210014 sec
                 wait id: 7276
                blocking: 2995 sessions
             current sql: <none>
             short stack: ksedsts()+346<-ksdxfstk()+71<-ksdxcb()+912<-sspuser()+217<-__sighandler()<-__poll()+16<-ipcgxp_selectex()+409<-ipclw_wait()+1045<-ksxpwait_ipclw()+3844<-ksxpwait_int()+22103<-ksxpwait()+845<-ksliwat()+11015<-kslwaitctx()+212<-kslwait()+150<-kcbzck1()+718<-kcbrcp()+390<-kcrpcf()+204<-kcrpdv()+2578<-kxfprdp_int()+1696<-opirip()+750<-opidrv()+602<-sou2o()+145<-opimai_real()+202<-ssthrdmain()+417<-main()+262<-__libc_start_main()+245
            wait history:
              * time between current wait and wait #1: 0.000505 sec
              1.       event: 'checkpoint completed'
                 time waited: 5.004831 sec
                     wait id: 7275            
              * time between wait #1 and #2: 0.000265 sec
              2.       event: 'checkpoint completed'
                 time waited: 5.004798 sec
                     wait id: 7274            
              * time between wait #2 and #3: 0.000164 sec
              3.       event: 'checkpoint completed'
                 time waited: 5.004888 sec
                     wait id: 7273            
    }
    and is blocked by
 => Oracle session identified by:
    {
                instance: 1 (<DBNAME>)
                   os id: 207436
              process id: 89, oracle@<HOSTNAME> (CKPT)
              session id: 7032
        session serial #: 31290
    }
    which is waiting for 'rdbms ipc message' with wait info:
    {
                      p1: 'timeout'=0xf5
            time in wait: 0.010978 sec
      heur. time in wait: 0.010994 sec
           timeout after: 2.439022 sec
                 wait id: 53427936
                blocking: 2996 sessions
             current sql: <none>
             short stack: ksedsts()+346<-ksdxfstk()+71<-ksdxcb()+912<-sspuser()+217<-__sighandler()<-__poll()+16<-ipcgxp_selectex()+409<-ipclw_wait()+1045<-ksxpwait_ipclw()+3844<-ksxpwait_int()+22103<-ksxpwait()+845<-ksliwat()+11015<-kslwaitctx()+212<-ksarcv()+355<-ksbabs()+517<-ksbrdp()+1079<-opirip()+609<-opidrv()+602<-sou2o()+145<-opimai_real()+202<-ssthrdmain()+417<-main()+262<-__libc_start_main()+245
            wait history:
              * time between current wait and wait #1: 0.000008 sec
              1.       event: 'rdbms ipc message'
                 time waited: 0.000008 sec
                     wait id: 53427935         p1: 'timeout'=0xf5
              * time between wait #1 and #2: 0.000094 sec
              2.       event: 'rdbms ipc message'
                 time waited: 0.551719 sec
                     wait id: 53427934         p1: 'timeout'=0x12c
              * time between wait #2 and #3: 0.000030 sec
              3.       event: 'rdbms ipc message'
                 time waited: 0.000002 sec
                     wait id: 53427933         p1: 'timeout'=0x12c
    }
 
Chain 1 Signature: 'rdbms ipc message'<='checkpoint completed'<='parallel recovery coord wait for reply'<='gc domain validation'<='library cache lock'
Chain 1 Signature Hash: 0x13a57715



   177: RSMN ospid 63206 sid 13984 ser 61993, waiting for 'rdbms ipc message'
    178: TMON ospid 63209 sid 14063 ser 23468, waiting for 'rdbms ipc message'
    179: USER ospid 63211 sid 14142 ser 14435, waiting for 'enq: IR - contention'
         Cmd: ALTER DATABASE
         Blocked by inst: 1, sid: 7190, ser: 43083
         Final Blocker inst: 1, sid: 7032, ser: 31290
    182: PPA7 ospid 66831 sid 0 ser 0,
    188: ARC2 ospid 67519 sid 14853 ser 16434, waiting for 'rdbms ipc message


machine: <HOSTNAME> program: oraagent.bin@<HOSTNAME> (TNS
     application name: oraagent.bin@<HOSTNAME> (TNS , hash value=3786091275
   Current Wait Stack:
    0: waiting for 'enq: IR - contention'
       name|mode=0x49520006, 0=0x0, 0/1=0x0
       wait_id=1017 seq_num=1051 snap_id=1
       wait times: snap=113 min 23 sec, exc=113 min 23 sec, total=113 min 23 sec
       wait times: max=infinite, heur=113 min 23 sec
       wait counts: calls=13593 os=13593
       in_wait=1 iflags=0x15a0
   There is at least one session blocking this session.
     Dumping 1 direct blocker(s):
       inst: 1, sid: 7190, ser: 43083
     Dumping final blocker:
       inst: 1, sid: 7032, ser: 31290
   Wait State:
     fixed_waits=0 flags=0x22 boundary=(nil)/-1

Changes

 No changes done

Cause

To view full details, sign in with your My Oracle Support account.

Don't have a My Oracle Support account? Click to get started!


In this Document
Symptoms
Changes
Cause
Solution
References


My Oracle Support provides customers with access to over a million knowledge articles and a vibrant support community of peers and Oracle experts.