DataBase can’t be open after shutdown immediate
本站文章除注明转载外,均为本站原创: 转载自love wife love life —Roger的Oracle/MySQL/PostgreSQL数据恢复博客
五一放假期间,某客户的数据库出现故障,据说对方找了一些工程师折腾了一天,都无法将数据库open,其中参考了网络上的很多文章,也使用了一系列隐含参数,均无法将数据库打开。这里我简单的与大家分享一下这个case。
首先我介绍一下整个case的背景,客户在4月30号凌晨通过shutdown immediate停库维护后,启动数据库无法报错,此时发现数据库无法open,期间尝试了各种数据库手段,均失败告终。我们先来看看相关日志,如下是数据库停库的日志:
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 38 39 40 41 42 43 44 45 46 47 48 49 |
Sun Apr 30 02:01:19 2017 Shutting down instance (immediate) Stopping background process SMCO Shutting down instance: further logons disabled Sun Apr 30 02:01:20 2017 Stopping background process CJQ0 Stopping background process QMNC Stopping background process MMNL Stopping background process MMON License high water mark = 262 All dispatchers and shared servers shutdown Sun Apr 30 02:01:30 2017 ALTER DATABASE CLOSE NORMAL Sun Apr 30 02:01:30 2017 SMON: disabling tx recovery SMON: disabling cache recovery Sun Apr 30 02:01:36 2017 Shutting down archive processes Archiving is disabled Sun Apr 30 02:01:36 2017 Sun Apr 30 02:01:36 2017 ARCH shutting downARCH shutting downSun Apr 30 02:01:36 2017 ARCH shutting down ARC3: Archival stopped ARC0: Archival stopped ARC1: Archival stopped Sun Apr 30 02:01:36 2017 ARCH shutting down ARC2: Archival stopped Thread 1 closed at log sequence 138760 Successful close of redo thread 1 Sun Apr 30 02:02:18 2017 Completed: ALTER DATABASE CLOSE NORMAL ALTER DATABASE DISMOUNT Shutting down archive processes Archiving is disabled Completed: ALTER DATABASE DISMOUNT ARCH: Archival disabled due to shutdown: 1089 Shutting down archive processes Archiving is disabled ARCH: Archival disabled due to shutdown: 1089 Shutting down archive processes Archiving is disabled Sun Apr 30 02:02:20 2017 Stopping background process VKTM Sun Apr 30 02:03:20 2017 Instance shutdown complete |
我们可以看出,这个数据库确实是以shutdown immediate的方式停止的。客户第一次尝试启动时,发现报错ORA-00600 [2663],如下:
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 |
Sun Apr 30 02:56:50 2017 ARC3 started with pid=40, OS id=73358 ARC1: Archival started ARC2: Archival started ARC1: Becoming the 'no FAL' ARCH ARC1: Becoming the 'no SRL' ARCH ARC2: Becoming the heartbeat ARCH Thread 1 opened at log sequence 138760 Current log# 5 seq# 138760 mem# 0: /opt/oracle/oradata/jddb/redo05.log Successful open of redo thread 1 MTTR advisory is disabled because FAST_START_MTTR_TARGET is not set SMON: enabling cache recovery Errors in file /opt/oracle/diag/rdbms/jddb/jddb/trace/jddb_ora_73336.trc (incident=384297): ORA-00600: internal error code, arguments: [2663], [0], [2081888970], [0], [2081892886], [], [], [], [], [], [], [] Incident details in: /opt/oracle/diag/rdbms/jddb/jddb/incident/incdir_384297/jddb_ora_73336_i384297.trc ARC3: Archival started ARC0: STARTING ARCH PROCESSES COMPLETE Use ADRCI or Support Workbench to package the incident. See Note 411.1 at My Oracle Support for error and packaging details. Undo initialization errored: err:600 serial:0 start:1909462874 end:1909464654 diff:1780 (17 seconds) Errors in file /opt/oracle/diag/rdbms/jddb/jddb/trace/jddb_ora_73336.trc: ORA-00600: internal error code, arguments: [2663], [0], [2081888970], [0], [2081892886], [], [], [], [], [], [], [] Errors in file /opt/oracle/diag/rdbms/jddb/jddb/trace/jddb_ora_73336.trc: ORA-00600: internal error code, arguments: [2663], [0], [2081888970], [0], [2081892886], [], [], [], [], [], [], [] Error 600 happened during db open, shutting down database USER (ospid: 73336): terminating the instance due to error 600 Instance terminated by USER, pid = 73336 ORA-1092 signalled during: ALTER DATABASE OPEN... opiodr aborting process unknown ospid (73336) as a result of ORA-1092 |
这是一个非常常见的错误,这个错误通常是是更数据块有关系。我们知道,根据经验,一般来讲,如果current scn (这里是scn base)与dependent scn(scn base)非常接近(且scn wrap都一致或者为0)的情况下,说明scn的差异非常小,通过多次重启数据库的手段,基本上可以绕过这个错误。果然,通过看客户提供的alert log发现多次重启后,alert log的报错日志变了ORA-00600 [4194]错误,如下:
1 2 3 4 5 6 7 8 9 10 11 12 |
Recovery of Online Redo Log: Thread 1 Group 1 Seq 138761 Reading mem 0 Mem# 0: /opt/oracle/oradata/jddb/redo01.log Block recovery completed at rba 138761.5.16, scn 0.2081908976 Errors in file /opt/oracle/diag/rdbms/jddb/jddb/trace/jddb_ora_73923.trc: ORA-00600: internal error code, arguments: [4194], [], [], [], [], [], [], [], [], [], [], [] Errors in file /opt/oracle/diag/rdbms/jddb/jddb/trace/jddb_ora_73923.trc: ORA-00600: internal error code, arguments: [4194], [], [], [], [], [], [], [], [], [], [], [] Error 600 happened during db open, shutting down database USER (ospid: 73923): terminating the instance due to error 600 Instance terminated by USER, pid = 73923 ORA-1092 signalled during: ALTER DATABASE OPEN... opiodr aborting process unknown ospid (73923) as a result of ORA-1092 |
这是一个看似非常简单的错误,大致意思是说Oracle 在进行事务恢复时发现redo和undo的信息有所出入,因此抛出这个错误。这里我仍然贴出Oracle MOS的标准解释供大家参考:Basic Steps to be Followed While Solving ORA-00600 [4194]/[4193] Errors Without Using Unsupported parameter (文档 ID 281429.1)
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 |
Format: ORA-600 [4194] [a] [b] VERSIONS: versions 6.0 to 12.1 DESCRIPTION: A mismatch has been detected between Redo records and rollback (Undo) records. We are validating the Undo record number relating to the change being applied against the maximum undo record number recorded in the undo block. This error is reported when the validation fails. ARGUMENTS: Arg [a] Maximum Undo record number in Undo block Arg [b] Undo record number from Redo block FUNCTIONALITY: Kernel Transaction Undo called from Cache layer IMPACT: PROCESS FAILURE POSSIBLE ROLLBACK SEGMENT CORRUPTION SUGGESTIONS: This error may indicate a rollback segment corruption. This may require a recovery from a database backup depending on the situation. If the Known Issues section below does not help in terms of identifying a solution, please submit the trace files and alert.log to Oracle Support Services for further analysis. |
上述文档中提到,这个错误其实就是指恢复时发现undo block对应的record 编号与redo block 对应的undo record 编号不一致。通常情况下来讲,都是由于回滚段损坏导致的问题。 这里我们先不去进行alert log的详细分析展开了,以自己的实际操作过程来进行展开分析说明。如下是我的简单恢复过程。
首先我尝试进行正常恢复,并打开数据库:
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 |
SQL> recover database using backup controlfile until cancel; ORA-00279: change 2082649195 generated at 04/30/2017 12:53:07 needed for thread 1 ORA-00289: suggestion : /opt/oraarch/1_138798_924909160.dbf ORA-00280: change 2082649195 for thread 1 is in sequence #138798 Specify log: {<RET>=suggested | filename | AUTO | CANCEL} /opt/oracle/oradata/jddb/redo03.log Log applied. Media recovery complete. SQL> SQL> alter database open resetlogs; alter database open resetlogs * ERROR at line 1: ORA-03113: end-of-file on communication channel Process ID: 44134 Session ID: 397 Serial number: 3 |
我们可以看到操作报错,并没有打开数据库。此时查看数据库alert 告警日志,发现正是前面提到的ORA-00600 [4194]错误:
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 |
Sun Apr 30 21:01:05 2017 SMON: enabling cache recovery Errors in file /opt/oracle/diag/rdbms/jddb/jddb/trace/jddb_ora_44134.trc (incident=840297): ORA-00600: internal error code, arguments: [4194], [rch/1_138795_924909160.dbft/oraarch/1_138798_924909160.dbf Incident details in: /opt/oracle/diag/rdbms/jddb/jddb/incident/incdir_840297/jddb_ora_44134_i840297.trc Use ADRCI or Support Workbench to package the incident. See Note 411.1 at My Oracle Support for error and packaging details. ARC3: Archival started ARC0: STARTING ARCH PROCESSES COMPLETE Block recovery from logseq 1, block 3 to scn 2082649208 Recovery of Online Redo Log: Thread 1 Group 1 Seq 1 Reading mem 0 Mem# 0: /opt/oracle/oradata/jddb/redo01.log Block recovery stopped at EOT rba 1.5.16 Block recovery completed at rba 1.5.16, scn 0.2082649206 Block recovery from logseq 1, block 3 to scn 2082649205 Recovery of Online Redo Log: Thread 1 Group 1 Seq 1 Reading mem 0 Mem# 0: /opt/oracle/oradata/jddb/redo01.log Block recovery completed at rba 1.5.16, scn 0.2082649206 Errors in file /opt/oracle/diag/rdbms/jddb/jddb/trace/jddb_ora_44134.trc: ORA-00600: internal error code, arguments: [4194], [rch/1_138795_924909160.dbft/oraarch/1_138798_924909160.dbf ], [], [], [], [], [], [], [], [], [], [] Errors in file /opt/oracle/diag/rdbms/jddb/jddb/trace/jddb_ora_44134.trc: ORA-00600: internal error code, arguments: [4194], [rch/1_138795_924909160.dbft/oraarch/1_138798_924909160.dbf ], [], [], [], [], [], [], [], [], [], [] Error 600 happened during db open, shutting down database USER (ospid: 44134): terminating the instance due to error 600 Instance terminated by USER, pid = 44134 |
这个ora-00600 错误与前面提到的完全一致。根据我们常规处理这个错误的套路,基本上就是使用undo_management=’manual’ 来尝试绕过,经过测试发现不好使。进一步查看对应的trace 文件,发现oracle提示说某个块存在异常:
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 38 39 |
Error 600 in redo application callback Dump of change vector: TYP:0 CLS:16 AFN:1 DBA:0x00400083 OBJ:4294967295 SCN:0x0000.7c172a16 SEQ:11 OP:5.1 ENC:0 RBL:0 ktudb redo: siz: 268 spc: 7602 flg: 0x0012 seq: 0x0024 rec: 0x03 xid: 0x0000.03f.00000023 ktubl redo: slt: 63 rci: 0 opc: 11.1 [objn: 15 objd: 15 tsn: 0] Undo type: Regular undo Begin trans Last buffer split: No Temp Object: No Tablespace Undo: No 0x00000000 prev ctl uba: 0x00400084.0024.20 prev ctl max cmt scn: 0x0000.70105e77 prev tx cmt scn: 0x0000.70105e79 txn start scn: 0xffff.ffffffff logon user: 0 prev brb: 4194863 prev bcl: 0 BuExt idx: 0 flg2: 0 KDO undo record: KTB Redo op: 0x04 ver: 0x01 compat bit: 4 (post-11) padding: 1 op: L itl: xid: 0x0000.03d.00000023 uba: 0x00400084.0024.1e flg: C--- lkc: 0 scn: 0x0000.7c171ac6 KDO Op code: URP row dependencies Disabled xtype: XA flags: 0x00000000 bdba: 0x004000e1 hdba: 0x004000e0 itli: 1 ispac: 0 maxfr: 4863 tabn: 0 slot: 1(0x1) flag: 0x2c lock: 0 ckix: 0 ncol: 17 nnew: 12 size: 0 col 1: [20] <span style="color: #ff0000;">5f 53 59 53 53 4d 55 31</span> 5f 33 37 32 34 30 30 34 36 30 36 24 col 2: [ 2] c1 02 col 3: [ 2] c1 04 col 4: [ 3] c2 02 1d col 5: [ 6] c5 15 52 59 59 51 col 6: [ 1] 80 col 7: [ 4] c3 11 5b 25 col 8: [ 3] c3 03 08 col 9: [ 1] 80 col 10: [ 2] <span style="color: #ff0000;">c1 04</span> col 11: [ 2] c1 03 col 16: [ 2] c1 03 Block after image is corrupt: buffer tsn: 0 rdba: 0x00400083 (1/131) scn: 0x0000.7c172a16 seq: 0x0b flg: 0x04 tail: 0x2a16020b frmt: 0x02 chkval: 0x205f type: 0x02=KTU UNDO BLOCK |
上述的错误其实也很容易解释,简单的讲就是redo应用时出现了异常,而且oracle 明确提升file 1 block 131 这个undo block有问题. 上述的内容是redo block的dump;那么我们来看看对应的undo block 中的前镜像是什么:
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 |
*----------------------------- * Rec #0x3 slt: 0x3f objn: 15(0x0000000f) objd: 15 tblspc: 0(0x00000000) * Layer: 11 (Row) opc: 1 rci 0x00 Undo type: Regular undo Begin trans Last buffer split: No Temp Object: No Tablespace Undo: No rdba: 0x00000000Ext idx: 0 flg2: 0 *----------------------------- uba: 0x00400084.0024.20 ctl max scn: 0x0000.70105e77 prv tx scn: 0x0000.70105e79 txn start scn: scn: 0x0000.7c171acb logon user: 0 prev brb: 4194863 prev bcl: 0 KDO undo record: KTB Redo op: 0x04 ver: 0x01 compat bit: 4 (post-11) padding: 1 op: L itl: xid: 0x0000.03d.00000023 uba: 0x00400084.0024.1e flg: C--- lkc: 0 scn: 0x0000.7c171ac6 KDO Op code: URP row dependencies Disabled xtype: XA flags: 0x00000000 bdba: 0x004000e1 hdba: 0x004000e0 itli: 1 ispac: 0 maxfr: 4863 tabn: 0 slot: 10(0xa) flag: 0x2c lock: 0 ckix: 0 ncol: 17 nnew: 12 size: 0 col 1: [21] <span style="color: #ff0000;">5f 53 59 53 53 4d 55 31</span> 30 5f 31 31 39 37 37 33 34 39 38 39 24 col 2: [ 2] c1 02 col 3: [ 2] c1 04 col 4: [ 3] c2 03 49 col 5: [ 6] c5 15 52 59 5a 0a col 6: [ 1] 80 col 7: [ 4] c3 21 40 24 col 8: [ 4] c3 04 06 33 col 9: [ 1] 80 col 10: [ 2] <span style="color: #ff0000;">c1 03</span> col 11: [ 2] c1 03 col 16: [ 2] c1 03 |
我们可以看到完全不匹配,同时我们通过脚本将上述内容进行转换,可以发现是其实是回滚段名称:
1 2 3 4 5 6 7 8 9 10 11 12 13 |
www.killdb.com@ SELECT F_GET_FROM_DUMP('5f,53,59,53,53,4d,55,32,5f,32,39,39,36,33,39,31,33,33,32,24','VARCHAR2') GET_DUMP 2 from dual; GET_DUMP -------------------------------------------------------------------------------------------------------------------------- _SYSSMU2_2996391332$ www.killdb.com@ SELECT F_GET_FROM_DUMP('5f,53,59,53,53,4d,55,31,30,5f,31,31,39,37,37,33,34,39,38,39,24','VARCHAR2') GET_DUMP 2 from dual; GET_DUMP -------------------------------------------------------------------------------------------------------------------------- _SYSSMU10_1197734989$ |
其次结合我们前面解释ora-00600 [4194]错误来看,这里undo block 对应的record number是0x20,而redo block中记录的record number是0x2. 这确实是不匹配的。
那么怎么解决这个问题呢? 能不能通过屏蔽回滚段的方式来解决呢?我尝试在open之前设置10046 trace,来观察了一下得到了如下结果:
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 |
update /*+ rule */ undo$ set name=:2,file#=:3,block#=:4,status$=:5,user#=:6,undosqn=:7,xactsqn=:8,scnbas=:9,scnwrp=:10,inst#=:11,ts#=:12,spare1=:13 where us#=:1 END OF STMT PARSE #140333533666600:c=4999,e=4974,p=8,cr=62,cu=0,mis=1,r=0,dep=1,og=3,plh=0,tim=1493558803488842 BINDS #140333533666600: Bind#0 oacdty=01 mxl=32(20) mxlc=00 mal=00 scl=00 pre=00 oacflg=18 fl2=0001 frm=01 csi=871 siz=32 off=0 kxsbbbfp=281ff02342 bln=32 avl=20 flg=09 value="_SYSSMU1_3724004606$" Bind#1 oacdty=02 mxl=22(22) mxlc=00 mal=00 scl=00 pre=00 oacflg=08 fl2=0001 frm=00 csi=00 siz=24 off=0 kxsbbbfp=7fa1f26dc788 bln=24 avl=02 flg=05 value=3 ...... WAIT #140333533666600: nam='db file sequential read' ela= 12 file#=1 block#=131 blocks=1 obj#=0 tim=1493558803489767 ...... Incident 864297 created, dump file: /opt/oracle/diag/rdbms/jddb/jddb/incident/incdir_864297/jddb_ora_49305_i864297.trc ORA-00600: internal error code, arguments: [4194], [rch/1_1_942699661.dbfcceeded but OPEN RESETLOGS would get error below ORA-01194: file 1 needs more recovery to be consistent ORA-01110: data file 1: '/opt/oracle/oradata/jddb/system01.dbf |
1 |
可以看到oracle在执行update undo$时报错,其中更新的是_SYSSMU1_3724004606$ 这个回滚段。而且我们也可以看到,wait# 中记录的正好是前面 |
1 |
报错的file# 1 block 131. 那么通过_corrupted_rollback_segments=(_SYSSMU1_3724004606$)这种方式是否可以解决这个问题呢? |
1 |
很遗憾,这里我测试也不行。甚至通过bbed 修改undo$的kdbr记录,将_SYSSMU1 的状态修改为offline,也无法绕过这个ora-00600 4194错误。 |
1 |
简直堪称最顽固的ORA-00600 [4194]。 |
1 |
我又检查了一下前面的trace文件,发现所针对这个回滚段头的dump记录,可以确认其中并没有什么活动事务。 |
1 |
然后再仔细看我们所遇到的这个ora-00600 [4194]错误,我感觉有点怪异。为什么说怪异呢? |
1 |
如果说根据Oracle mos的解释文档来看,这里是是没有[a],[b] 值的,因为均为0. |
1 |
最后我们想到通过修改system 回滚段头来绕过这个错误,如下是操作过程: |
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 |
<pre class="brush:plain">BBED> p ktuxc struct ktuxc, 104 bytes @4148 struct ktuxcscn, 8 bytes @4148 ub4 kscnbas @4148 0x70105e77 ub2 kscnwrp @4152 0x0000 struct ktuxcuba, 8 bytes @4156 ub4 kubadba @4156 0x00400084 ub2 kubaseq @4160 0x0024 ub1 kubarec @4162 0x20 sb2 ktuxcflg @4164 1 (KTUXCFSK) ub2 ktuxcseq @4166 0x0024 sb2 ktuxcnfb @4168 1 ub4 ktuxcinc @4172 0x00000000 sb2 ktuxcchd @4176 63 sb2 ktuxcctl @4178 56 ub2 ktuxcmgc @4180 0x8002 ub4 ktuxcopt @4188 0x7ffffffe struct ktuxcfbp[0], 12 bytes @4192 struct ktufbuba, 8 bytes @4192 ub4 kubadba @4192 0x00000000 ub2 kubaseq @4196 0x0024 ub1 kubarec @4198 0x1f sb2 ktufbext @4200 0 sb2 ktufbspc @4202 656 struct ktuxcfbp[1], 12 bytes @4204 struct ktufbuba, 8 bytes @4204 ub4 kubadba @4204 0x00400083 ub2 kubaseq @4208 0x0024 ub1 kubarec @4210 0x02 sb2 ktufbext @4212 0 sb2 ktufbspc @4214 7602 |
1 |
注意,这里我们仅仅需要修改ktuxcnfb和ktuxcfbp[1] 即可。其中将ktuxcnfb修改为0,ktuxcfbp[1]中的uba修改为0. |
1 |
然后再尝试打开数据库,发现顺利打开了数据库,如下: |
1 2 3 4 5 6 7 8 9 10 11 12 |
<pre class="brush:plain">SQL> alter database open resetlogs; Database altered. SQL> show parameter job NAME TYPE VALUE ------------------------------------ ----------- ------------------------------ job_queue_processes integer 1000 SQL> alter system set job_queue_processes=0; System altered. |
1 |
接着检查了数据库alert log,也没有发现任何的ora-错误。 |
1 |
看到最后,或许大家会觉得很奇怪,为什么会出现这样的故障呢 ? 这里我也跟大家一样困惑。为什么说困惑呢? |
1 |
因为这库是通过shutdown immediate方式正常停止的。我们都知道,这种方式停库之后,整个Oracle数据库的 |
1 |
文件都是处于一致的状态,重新启动数据库实例后按理说是不需要再进行实例恢复的。 |
1 |
那么为什么这里又出现了这种情况呢? |
1 |
针对这个问题,我认为有2种可能性: |
1 |
1、shutdown immediate之后,数据库写入到操作系统cache,还未完全写入到disk上时,此时数据库主机被强行重启; |
1 |
由于操作系统cache丢失,导致数据库出现了不一致的情况(本文环境是Linux文件系统)。 |
1 |
2、其他程序或软件破坏了Oracle数据库文件的一致性(实际上,经过了解该环境部署了Rose HA软件;而且 |
1 |
客户在操作时,据说并没有停止rose ha软件)。 |
1 |
由于客户操作的时间点是凌晨2点,几乎是0业务场景,因此我认为第一种可能性几乎为0;第2种可能性更大。 |
1 |
当然由于我们不了解Rose HA软件的工作机制,这里不便评论。只能说这是一个非常奇怪的case了。 |
1 |
值得欣慰的是,通过我们的努力,很快就帮助客户恢复了系统访问,并且无数据丢失。 |
Leave a Reply
You must be logged in to post a comment.