Terminating Instance Because ASMB is Stuck for x Seconds (Doc ID 2278744.1)

Last updated on JULY 26, 2017

Applies to:

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

Symptoms

Why did database instance terminate at  a specific time ?

Customer has NUMA enabled servers

NUMA system with 2 nodes detected
 Wed Jun 14 23:53:40 2017
 Archived Log entry 14584 added for thread 1 sequence 14566 ID 0xd0719ec9 dest 1:
 Thu Jun 15 00:37:31 2017
 TABLE SYS.WRP$_REPORTS_TIME_BANDS: ADDED INTERVAL PARTITION SYS_P12899 (2722) VALUES LESS THAN (TO_DATE(' 2017-06-15 01:00:00', 'SYYYY-MM-DD HH24:MI:SS', 'NLS_CALENDAR=GREGORIAN'))
 Thu Jun 15 00:54:28 2017
 Thread 1 advanced to log sequence 14568 (LGWR switch)
   Current log# 2 seq# 14568 mem# 0: +DATA/RCUPMO/ONLINELOG/redo2_01.log
   Current log# 2 seq# 14568 mem# 1: +REDO1/RCUPMO/ONLINELOG/redo2_02.log
   Current log# 2 seq# 14568 mem# 2: +REDO2/RCUPMO/ONLINELOG/redo2_03.log
 Thu Jun 15 00:54:30 2017
 Archived Log entry 14585 added for thread 1 sequence 14567 ID 0xd0719ec9 dest 1:
 Thu Jun 15 01:13:37 2017
 WARNING: ASMB has not responded for 394 seconds
 NOTE: ASM umbilicus running slower than expected, ASMB diagnostic requested after 394 seconds
 NOTE: ASMB process state dumped to trace file /u01/app/oracle/diag/rdbms/rcupmo/RCUPMO_1/trace/RCUPMO_1_gen0_54942.trc
 ERROR: terminating instance because ASMB is stuck for 394 seconds
 GEN0 (ospid: 54942): terminating the instance due to error 15082
 Thu Jun 15 01:13:38 2017
 System state dump requested by (instance=1, osid=54942 (GEN0)), summary=[abnormal instance termination].
 System State dumped to trace file /u01/app/oracle/diag/rdbms/rcupmo/RCUPMO_1/trace/RCUPMO_1_diag_54948_20170615011338.trc
 Thu Jun 15 01:13:38 2017
 ORA-1092 : opitsk aborting process  : opitsk aborting process
 Thu Jun 15 01:13:40 2017
 License high water mark = 105
 Thu Jun 15 01:13:40 2017
 ORA-1092 : opitsk aborting process  : opitsk aborting process
 Thu Jun 15 01:13:40 2017
 ORA-1092 : opitsk aborting process  : opitsk aborting process
 Thu Jun 15 01:13:43 2017

 Instance terminated by GEN0, pid = 54942
 Thu Jun 15 01:13:44 2017
 USER (ospid: 71641): terminating the instance
 Thu Jun 15 01:13:44 2017
 Instance terminated by USER, pid = 71641
 Thu Jun 15 01:13:47 2017
 Starting ORACLE instance (normal) (OS id: 72980)


Gap was observed in the system message log  from 1:07 to 1:13  which is inconsistent with the frequency of updates to the system message log before and after this time frame.

Jun 15 01:07:04 usplsrcu527 snmpd[46941]: Connection from UDP: [127.0.0.1]:56279->[127.0.0.1]
Jun 15 01:07:04 usplsrcu527 Oracle Audit[57203]: LENGTH : '201' ACTION :[53] 'BEGIN DBMS_SESSION.USE_DEFAULT_EDITION_DEFERRED; END;' DATABASE USER:[1] '/' PRIVILEGE :[6] 'SYSDBA' CLIENT USER:[6] 'oracle' CLIENT TERMINAL:[0] '' STATUS:[1] '0' DBID:[10] '2675330069'
Jun 15 01:07:05 usplsrcu527 snmpd[46941]: Connection from UDP: [127.0.0.1]:56279->[127.0.0.1]
Jun 15 01:07:06 usplsrcu527 snmpd[46941]: Connection from UDP: [127.0.0.1]:56279->[127.0.0.1] <<<<<<<<<<<<<<<<<
Jun 15 01:13:36 usplsrcu527 Oracle Audit[57203]: LENGTH : '201' ACTION :[53] 'BEGIN DBMS_SESSION.USE_DEFAULT_EDITION_DEFERRED; END;' DATABASE USER:[1] '/' PRIVILEGE :[6] 'SYSDBA' CLIENT USER:[6] 'oracle' CLIENT TERMINAL:[0] '' STATUS:[1] '0' DBID:[10] '2675330069'
Jun 15 01:13:37 usplsrcu527 snmpd[46941]: Connection from UDP: [127.0.0.1]:56279->[127.0.0.1]
Jun 15 01:13:38 usplsrcu527 snmpd[46941]: Connection from UDP: [127.0.0.1]:56279->[127.0.0.1]
Jun 15 01:13:39 usplsrcu527 snmpd[46941]: Connection from UDP: [127.0.0.1]:56279->[127.0.0.1]

This same gap can also be seen in the vmstat output from os watcher

zzz ***Thu Jun 15 01:06:46 CDT 2017
procs -----------memory---------- ---swap-- -----io---- --system-- -----cpu-----
 r b swpd free buff cache si so bi bo in cs us sy id wa st
 4 0 0 60982520 1441528 42901688 0 0 1652 69 14 4 4 1 94 1 0
 2 0 0 60977996 1441532 42901872 0 0 99 522 10038 16513 1 2 96 0 0
 2 0 0 60980680 1441532 42902012 0 0 154 54 8311 15389 1 1 98 0 0
zzz ***Thu Jun 15 01:13:45 CDT 2017
procs -----------memory---------- ---swap-- -----io---- --system-- -----cpu-----
 r b swpd free buff cache si so bi bo in cs us sy id wa st
12 0 0 79417576 1441560 28248076 0 0 1651 69 14 4 4 1 94 1 0
 5 0 0 79410136 1441564 28248728 0 0 5689 777 16598 24309 5 9 86 0 0
 6 0 0 79152304 1441564 28512700 0 0 4343 889 14386 17767 6 9 85 0 0
zzz ***Thu Jun 15 01:14:15 CDT 2017

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