Terminating Instance Because ASMB is Stuck for x Seconds
(Doc ID 2278744.1)
Last updated on DECEMBER 20, 2022
Applies to:
Oracle Database - Enterprise Edition - Version 12.1.0.2 and laterOracle Database Cloud Schema Service - Version N/A and later
Oracle Database Exadata Express Cloud Service - Version N/A and later
Oracle Database Exadata Cloud Machine - Version N/A and later
Oracle Cloud Infrastructure - Database Service - Version N/A 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/<DATABASE>/ONLINELOG/redo2_01.log
Current log# 2 seq# 14568 mem# 1: +REDO1/<DATABASE>/ONLINELOG/redo2_02.log
Current log# 2 seq# 14568 mem# 2: +REDO2/<DATABASE>/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 $TRACE/<DATABASE>_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 $TRACE/<DATABASE>_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)
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/<DATABASE>/ONLINELOG/redo2_01.log
Current log# 2 seq# 14568 mem# 1: +REDO1/<DATABASE>/ONLINELOG/redo2_02.log
Current log# 2 seq# 14568 mem# 2: +REDO2/<DATABASE>/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 $TRACE/<DATABASE>_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 $TRACE/<DATABASE>_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 <node1> snmpd[46941]: Connection from UDP: [127.0.0.1]:56279->[127.0.0.1]
Jun 15 01:07:04 <node1> 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 <node1> snmpd[46941]: Connection from UDP: [127.0.0.1]:56279->[127.0.0.1]
Jun 15 01:07:06 <node1> snmpd[46941]: Connection from UDP: [127.0.0.1]:56279->[127.0.0.1] <<<<<<<<<<<<<<<<<
Jun 15 01:13:36 <node1> 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 <node1> snmpd[46941]: Connection from UDP: [127.0.0.1]:56279->[127.0.0.1]
Jun 15 01:13:38 <node1> snmpd[46941]: Connection from UDP: [127.0.0.1]:56279->[127.0.0.1]
Jun 15 01:13:39 <node1> snmpd[46941]: Connection from UDP: [127.0.0.1]:56279->[127.0.0.1]
Jun 15 01:07:04 <node1> 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 <node1> snmpd[46941]: Connection from UDP: [127.0.0.1]:56279->[127.0.0.1]
Jun 15 01:07:06 <node1> snmpd[46941]: Connection from UDP: [127.0.0.1]:56279->[127.0.0.1] <<<<<<<<<<<<<<<<<
Jun 15 01:13:36 <node1> 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 <node1> snmpd[46941]: Connection from UDP: [127.0.0.1]:56279->[127.0.0.1]
Jun 15 01:13:38 <node1> snmpd[46941]: Connection from UDP: [127.0.0.1]:56279->[127.0.0.1]
Jun 15 01:13:39 <node1> 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
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
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 |
| Cause |
| Solution |
| References |