ASM Fails to start -- Waiting For WARNING:io_getevents Timed Out 600 Sec (Doc ID 2164809.1)

Last updated on SEPTEMBER 20, 2016

Applies to:

Oracle Database - Enterprise Edition - Version 11.1.0.7 and later
Information in this document applies to any platform.
EC2 instance in Amazon Web Services (AWS)

Symptoms

Several oracle and clusterware processes hang and are unable to be killed on the node (kill -9)

Clusterware fails to shutdown cleanly.

crsctl stop has
CRS-2791: Starting shutdown of Oracle High Availability Services-managed resources on 'ranode1'
CRS-2673: Attempting to stop 'ora.CONTROL01.dg' on 'racnode1'
CRS-2673: Attempting to stop 'ora.CONTROL02.dg' on 'racnode1'
CRS-2673: Attempting to stop 'ora.DATA.dg' on 'racnode1'
CRS-5017: The resource action "ora.CONTROL01.dg stop" encountered the following error:
ORA-01013: user requested cancel of current operation
. For details refer to "(:CLSN00108:)" in "$GRID_HOME/log/racnode1/agent/ohasd/oraagent_oracle/oraagent_oracle.log".

CRS-5017: The resource action "ora.CONTROL02.dg stop" encountered the following error:
ORA-01013: user requested cancel of current operation
. For details refer to "(:CLSN00108:)" in "$GRID_HOME/log/racnode1/agent/ohasd/oraagent_oracle/oraagent_oracle.log".

CRS-5017: The resource action "ora.DATA.dg stop" encountered the following error:
ORA-01013: user requested cancel of current operation
. For details refer to "(:CLSN00108:)" in "$GRID_HOME/log/racnode1/agent/ohasd/oraagent_oracle/oraagent_oracle.log".

CRS-2675: Stop of 'ora.CONTROL02.dg' on 'racnode1' failed
CRS-2679: Attempting to clean 'ora.CONTROL02.dg' on 'racnode1'
CRS-2675: Stop of 'ora.CONTROL01.dg' on 'racnode1' failed
CRS-2679: Attempting to clean 'ora.CONTROL01.dg' on 'racnode1'
CRS-2675: Stop of 'ora.DATA.dg' on 'racnode1' failed
CRS-2679: Attempting to clean 'ora.DATA.dg' on 'racnode1'
CRS-5017: The resource action "ora.CONTROL01.dg clean" encountered the following error:
ORA-01013: user requested cancel of current operation
. For details refer to "(:CLSN00106:)" in "$GRID_HOME/log/racnode1/agent/ohasd/oraagent_oracle/oraagent_oracle.log".

CRS-5017: The resource action "ora.CONTROL02.dg clean" encountered the following error:
ORA-01013: user requested cancel of current operation
. For details refer to "(:CLSN00106:)" in "$GRID_HOME/log/racnode1/agent/ohasd/oraagent_oracle/oraagent_oracle.log".

CRS-5017: The resource action "ora.DATA.dg clean" encountered the following error:
ORA-01013: user requested cancel of current operation
. For details refer to "(:CLSN00106:)" in "$GRID_HOME/log/racnode1/agent/ohasd/oraagent_oracle/oraagent_oracle.log".

CRS-2678: 'ora.CONTROL01.dg' on 'racnode1' has experienced an unrecoverable failure
CRS-0267: Human intervention required to resume its availability.
CRS-2678: 'ora.CONTROL02.dg' on 'racnode1' has experienced an unrecoverable failure
CRS-0267: Human intervention required to resume its availability.
CRS-2678: 'ora.DATA.dg' on 'racnode1' has experienced an unrecoverable failure
CRS-0267: Human intervention required to resume its availability.
CRS-2799: Failed to shut down resource 'ora.CONTROL01.dg' on 'racnode1'
CRS-2799: Failed to shut down resource 'ora.CONTROL02.dg' on 'racnode1'
CRS-2799: Failed to shut down resource 'ora.DATA.dg' on 'racnode1'
CRS-2799: Failed to shut down resource 'ora.asm' on 'racnode1'
CRS-2799: Failed to shut down resource 'ora.cssd' on 'racnode1'
CRS-2795: Shutdown of Oracle High Availability Services-managed resources on 'racnode1' has failed
CRS-4687: Shutdown command has completed with errors.
CRS-4000: Command Stop failed, or completed with errors.

After rebooting the node, ASM resource is unable to start properly.

ASM alert log will have entries similar to following:

NOTE: starting recovery of thread=1 ckpt=179.505 group=3 (DATA)

NOTE: cache opening disk 0 of grp 3: DATA_0000 path:/dev/oracleasm/disks/DATA01
NOTE: F1X0 found on disk 0 au 2 fcn 0.0
NOTE: cache opening disk 1 of grp 3: DATA_0001 path:/dev/oracleasm/disks/DATA02
NOTE: cache opening disk 2 of grp 3: DATA_0002 path:/dev/oracleasm/disks/DATA03
NOTE: cache opening disk 3 of grp 3: DATA_0003 path:/dev/oracleasm/disks/DATA04
NOTE: cache opening disk 4 of grp 3: DATA_0004 path:/dev/oracleasm/disks/DATA05
NOTE: cache opening disk 5 of grp 3: DATA_0005 path:/dev/oracleasm/disks/DATA06
NOTE: cache mounting (first) external redundancy group 3/0x93B348BD (DATA)
NOTE: starting recovery of thread=1 ckpt=179.505 group=3 (DATA)
Thu Jun 30 11:32:14 2016
WARNING:io_getevents timed out 600 sec
Thu Jun 30 11:42:16 2016
WARNING:io_getevents timed out 600 sec
Thu Jun 30 11:52:18 2016
WARNING:io_getevents timed out 600 sec
Thu Jun 30 12:02:21 2016
WARNING:io_getevents timed out 600 sec

 

Changes

 None

Cause

Sign In with your My Oracle Support account

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

My Oracle Support provides customers with access to over a
Million Knowledge Articles and hundreds of Community platforms