0

mapid溢出导致Oracle RAC 节点重启

Roger 2019-06-17
36
摘要:从节点1数据库db alert log日志来看,在11:38:10出现ASM故障,最后在11:38:26时间,节点1的ASM实例被Oracle ASM实例的ASMB进程强行终止,因此导致数据库实例也crash掉。

问题描述

某客户的CRM数据库在2015年9月17号11:38分左出现其中一个节点宕机的情况。其中节点1报错信息如下:

Thu Sep 17 11:38:10 2015
Use ADRCI or Support Workbench to package the incident.
See Note 411.1 at My Oracle Support for error and packaging details.
NOTE: ASMB terminating
Errors in file /oracle/app/oracle/diag/rdbms/crm2db/crm2db1/trace/crm2db1_asmb_11141424.trc:
ORA-15064: communication failure with ASM instance
ORA-00600: internal error code, arguments: [ORA_NPI_ERROR], [600], [ORA-00600: internal error code, arguments: [kffilCreate01], [crm2db1:crm2db], [], [], [], [], [], [], [], [], [], []
], [], [], [], [], [], [], [], [], []
Errors in file /oracle/app/oracle/diag/rdbms/crm2db/crm2db1/trace/crm2db1_asmb_11141424.trc:
ORA-15064: communication failure with ASM instance
ORA-00600: internal error code, arguments: [ORA_NPI_ERROR], [600], [ORA-00600: internal error code, arguments: [kffilCreate01], [crm2db1:crm2db], [], [], [], [], [], [], [], [], [], []
], [], [], [], [], [], [], [], [], []
ASMB (ospid: 11141424): terminating the instance due to error 15064
Thu Sep 17 11:38:10 2015
System state dump requested by (instance=1, osid=11141424 (ASMB)), summary=[abnormal instance termination].
System State dumped to trace file /oracle/app/oracle/diag/rdbms/crm2db/crm2db1/trace/crm2db1_diag_12714592.trc
Thu Sep 17 11:38:10 2015
opiodr aborting process unknown ospid (22414298) as a result of ORA-1092
Termination issued to instance processes. Waiting for the processes to exit
Thu Sep 17 11:38:25 2015
ORA-1092 : opitsk aborting process
Thu Sep 17 11:38:26 2015
Instance termination failed to kill one or more processes
Instance terminated by ASMB, pid = 11141424
Thu Sep 17 11:39:43 2015
Starting ORACLE instance (normal)


专家解答

从节点1数据库db alert log日志来看,在11:38:10出现ASM故障,最后在11:38:26时间,节点1的ASM实例被Oracle ASM实例的ASMB进程强行终止,因此导致数据库实例也crash掉。如下是相关日志信息:

Thu Sep 17 11:38:25 2015 ORA-1092 : opitsk aborting process 
Thu Sep 17 11:38:26 2015 
Instance termination failed to kill one or more processes 
Instance terminated by ASMB, pid = 11141424

而此时在节点2的数据库alert log日志中,没有发现其他信息,仅仅只有节点1实例被重启的信息。因此,不难看出,节点ASM实例被强行终止,是此次问题的关键所在。我们进一步分析节点1 ASM实例的日志,发现如下信息:

Tue Sep 15 21:51:52 2015
Time drift detected. Please check VKTM trace file for more details.
Thu Sep 17 11:38:06 2015
Errors in file /oracle/app/grid/diag/asm/+asm/+ASM1/trace/+ASM1_ora_8716976.trc  (incident=179751):
ORA-00600: internal error code, arguments: [kffilCreate01], [crm2db1:crm2db], [], [], [], [], [], [], [], [], [], []
Incident details in: /oracle/app/grid/diag/asm/+asm/+ASM1/incident/incdir_179751/+ASM1_ora_8716976_i179751.trc
Use ADRCI or Support Workbench to package the incident.
See Note 411.1 at My Oracle Support for error and packaging details.
Thu Sep 17 11:38:10 2015
Dumping diagnostic data in directory=[cdmp_20150917113809], requested by (instance=1, osid=8716976), summary=[incident=179751].
Thu Sep 17 11:38:24 2015
Sweep [inc][179751]: completed
Sweep [inc2][179751]: completed
Thu Sep 17 11:39:29 2015
NOTE: ASM client crm2db1:crm2db disconnected unexpectedly.
NOTE: check client alert log.
NOTE: Trace records dumped in trace file /oracle/app/grid/diag/asm/+asm/+ASM1/trace/+ASM1_ora_8716976.trc
Thu Sep 17 11:39:29 2015
System State dumped to trace file /oracle/app/grid/diag/asm/+asm/+ASM1/trace/+ASM1_ora_42729726.trc
Thu Sep 17 11:40:10 2015
NOTE: client crm2db1:crm2db registered, osid 50266474, mbr 0x1

我们可以看到,在11:38:06时间点,ASM实例抛出ORA-00600 [kffilCreate01] 错误后,接着将实例终止,同时将日志信息写入到+ASM1_ora_8716976_i179751.trc文件中,该trace 文件的内容如下:

Address: 0xfffffffffff3cc8
Incident ID: 179751
Problem Key: ORA 600 [kffilCreate01]
Error: ORA-600 [kffilCreate01] [crm2db1:crm2db] [] [] [] [] [] [] [] [] [] []
[00]: dbgexProcessError [diag_dde]
[01]: dbgeExecuteForError [diag_dde]
[02]: dbgePostErrorKGE [diag_dde]
[03]: dbkePostKGE_kgsf [rdbms_dde]
[04]: kgeadse []
[05]: kgerinv_internal []
[06]: kgerinv []
[07]: kgeasnmierr []
[08]: kffilCreate [ASM]<-- Signaling
[09]: kfnsUFG [KFNU]
[10]: kfnsBackground [KFNU]
[11]: kfnDispatch [KFN]
[12]: opiodr []
[13]: ttcpip []
[14]: opitsk []
[15]: opiino []
[16]: opiodr []
[17]: opidrv []
[18]: sou2o []
[19]: opimai_real []
[20]: ssthrdmain []
[21]: main []

我们可以看出,Oracle 在调用kffcicreate函数时出现了异常,进而导致asm实例被强行终止。经过分析我们发现该问题跟Oracle Bug 16357438  (ORA-600 [KFFILCREATE01] IN ASM TRIGGERS DB CRASH WHEN MAPID REACHES MAX VALUE )比较符合。如下是Oracle metalink文档针对该bug的call stack函数描述:

[00]: dbgexProcessError [diag_dde]
[01]: dbgeExecuteForError [diag_dde]
[02]: dbgePostErrorKGE [diag_dde]
[03]: dbkePostKGE_kgsf [rdbms_dde]
[04]: kgeadse []
[05]: kgerinv_internal []
[06]: kgerinv []
[07]: kgeasnmierr []
[08]: kffilCreate [ASM]<-- Signaling
[09]: kfnsUFG [KFNU]
[10]: kfnsBackground [KFNU]
[11]: kfnDispatch [KFN]
[12]: opiodr []
[13]: ttcpip []
[14]: opitsk []
[15]: opiino []
[16]: opiodr []
[17]: opidrv []
[18]: sou2o []
[19]: opimai_real []
[20]: ssthrdmain []
[21]: main []
[22]: __start []

对于Oracle数据库bug的判断,通常的做法是比较报错日志文件中的call stack函数调用是否与Oracle bug的call stack函数描述一致,一般来讲,相似度超多90%,则意味是符合bug的可能性就极大。基于这样的分析,我对比发现call stack与Oracle bug 的call stack描述完全一致。

根据Oracle 文档关于该bug的描述,大致意思是指asm实例的mapid溢出,导出asm实例无法正常运作,进而被asmb进程强行终止;当然,强行终止的目的是为了保持集群节点数据的完整性,如下是从trace文件中提取的mapid信息:

Roger$ cat ASM1_ora_8716976_i179751.trc |grep 'mapid:'
            (kffil) netnm: crm2db1:crm2db, mapid: 4293682398
            (kffil) netnm: crm2db1:crm2db, mapid: 4249534089
            (kffil) netnm: crm2db1:crm2db, mapid: 4185128984
            (kffil) netnm: crm2db1:crm2db, mapid: 4185125967
            (kffil) netnm: crm2db1:crm2db, mapid: 4185121734
            (kffil) netnm: crm2db1:crm2db, mapid: 4152108652
            (kffil) netnm: crm2db1:crm2db, mapid: 4139887931
             .......
            (kffil) netnm: crm2db1:crm2db, mapid: 520724217
            (kffil) netnm: crm2db1:crm2db, mapid: 482740313
            (kffil) netnm: crm2db1:crm2db, mapid: 394435399
            (kffil) netnm: crm2db1:crm2db, mapid: 298438600
            (kffil) netnm: crm2db1:crm2db, mapid: 171948102
            (kffil) netnm: crm2db1:crm2db, mapid: 291
            (kffil) netnm: crm2db1:crm2db, mapid: 289
            (kffil) netnm: crm2db1:crm2db, mapid: 278
            (kffil) netnm: crm2db1:crm2db, mapid: 275
             .......
            (kffil) netnm: crm2db1:crm2db, mapid: 42
            (kffil) netnm: crm2db1:crm2db, mapid: 38
            (kffil) netnm: crm2db1:crm2db, mapid: 3
            (kffil) netnm: <null>, mapid: <null>
            (kffil) netnm: crm2db1:crm2db, mapid: 4294967295
            (kffil) netnm: crm2db1:crm2db, mapid: 4294967294
            (kffil) netnm: crm2db1:crm2db, mapid: 4294967293

我们可以看到,mapid已经达到最大值4294967296,这是Oracle数据库中数据对象的上限,同时我们从trace文件中的KST trace信息中也能看mapid溢出的类似信息:

2015-09-17 11:38:06.075000 :C23CEF42:KFNS:kfn.c@708:kfnDispatch(): calling server stub for KFNOP=5
2015-09-17 11:38:06.075011 :C23CEF45:KFNU:kfns.c@1725:kfnsBackground(): kfnsBackground consuming in-progress message typ=13 unread=1 status=0xfffffff1
2015-09-17 11:38:06.075012 :C23CEF46:KFNU:kfns.c@1963:kfnsConsume(): kfnsConsume message 0x700000124bd6670 status=0xfffffff1 flags=0x0
2015-09-17 11:38:06.075023 :C23CEF4C:KFNU:kfn.c@5313:kfnmsg_Dump(): kfnsBg (kfnmsg) opcode=14 (KFNMS_MAPFREE) fd 0x700000124bea1e0 mid 4294967291, gn [7.3971105324], fn [267.811087543] exts 1025, start 60, cnt 965
2015-09-17 11:38:06.075025 :C23CEF4E:KFNU:kfns.c@1784:kfnsBackground(): kfnsBackground got targeted message
2015-09-17 11:38:06.075029 :C23CEF54:db_trace:kfns.c@5342:kfnsFillMapMsg(): [10491:27:865] MAP_FREE: gn=7 fn=267, mapid=-5
2015-09-17 11:38:06.075047 :C23CEF5C:KFNU:kfns.c@1940:kfnsBackground(): kfnsBackground completed in 0 seconds (KFNPM=2)
2015-09-17 11:38:06.075048 :C23CEF5D:KFNS:kfn.c@739:kfnDispatch(): completed KFNOP=5 callcnt=-1386638497
2015-09-17 11:38:06.075107 :C23CEF7A:KFNS:kfn.c@708:kfnDispatch(): calling server stub for KFNOP=5
2015-09-17 11:38:06.075109 :C23CEF7C:KFNU:kfns.c@1725:kfnsBackground(): kfnsBackground consuming in-progress message typ=14 unread=1 status=0xfffffff1
2015-09-17 11:38:06.075110 :C23CEF7E:KFNU:kfns.c@1963:kfnsConsume(): kfnsConsume message 0x700000126f38a58 status=0xfffffff1 flags=0x0
2015-09-17 11:38:06.075113 :C23CEF83:KFNU:kfn.c@5313:kfnmsg_Dump(): kfnsBg (kfnmsg) opcode=14 (KFNMS_MAPFREE) fd 0x700000124beffe0 mid 4294967292, gn [7.3971105324], fn [267.811087543] exts 1025, start 60, cnt 965
2015-09-17 11:38:06.075114 :C23CEF84:KFNU:kfns.c@1784:kfnsBackground(): kfnsBackground got targeted message
2015-09-17 11:38:06.075118 :C23CEF85:db_trace:kfns.c@5342:kfnsFillMapMsg(): [10491:27:865] MAP_FREE: gn=7 fn=267, mapid=-4

我们可以看出,mapid已经出现了负数,这边表明mapid出现了溢出。

基于前面的种种分析,我们认为此次故障完全符合Oracle bug 16357438的描述细节,因此建议客户在下次维护时间窗口中安装相关Patch。

「喜欢文章,快来给作者赞赏墨值吧」

评论

0
0
Oracle
订阅
欢迎订阅Oracle频道,订阅之后可以获取最新资讯和更新通知。
墨值排行
今日本周综合
近期活动
全部
相关课程
全部