五一放假期间，某客户的数据库出现故障，据说对方找了一些工程师折腾了一天，都无法将数据库open，其中参考了网络上的很多文章，也使用了一系列隐含参数，均无法将数据库打开。这里我简单的与大家分享一下这个case。
首先我介绍一下整个case的背景，客户在4月30号凌晨通过shutdown immediate停库维护后，启动数据库无法报错，此时发现数据库无法open，期间尝试了各种数据库手段，均失败告终。我们先来看看相关日志，如下是数据库停库的日志：
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],如下：
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]错误，如下：
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)
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的详细分析展开了，以自己的实际操作过程来进行展开分析说明。如下是我的简单恢复过程。
首先我尝试进行正常恢复，并打开数据库：
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]错误：
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提示说某个块存在异常：
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 中的前镜像是什么：
*-----------------------------
* 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
我们可以看到完全不匹配，同时我们通过脚本将上述内容进行转换，可以发现是其实是回滚段名称：
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是0×20，而redo block中记录的record number是0×2. 这确实是不匹配的。
那么怎么解决这个问题呢？ 能不能通过屏蔽回滚段的方式来解决呢？我尝试在open之前设置10046 trace，来观察了一下得到了如下结果：
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
可以看到oracle在执行update undo$时报错，其中更新的是_SYSSMU1_3724004606$ 这个回滚段。而且我们也可以看到，wait# 中记录的正好是前面
报错的file# 1 block 131. 那么通过_corrupted_rollback_segments=(_SYSSMU1_3724004606$)这种方式是否可以解决这个问题呢？
很遗憾，这里我测试也不行。甚至通过bbed 修改undo$的kdbr记录，将_SYSSMU1 的状态修改为offline，也无法绕过这个ora-00600 4194错误。
简直堪称最顽固的ORA-00600 [4194]。
我又检查了一下前面的trace文件，发现所针对这个回滚段头的dump记录，可以确认其中并没有什么活动事务。
然后再仔细看我们所遇到的这个ora-00600 [4194]错误，我感觉有点怪异。为什么说怪异呢？
如果说根据Oracle mos的解释文档来看，这里是是没有[a],[b] 值的，因为均为0.
最后我们想到通过修改system 回滚段头来绕过这个错误，如下是操作过程：
<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</pre>
注意，这里我们仅仅需要修改ktuxcnfb和ktuxcfbp[1] 即可。其中将ktuxcnfb修改为0，ktuxcfbp[1]中的uba修改为0.
然后再尝试打开数据库，发现顺利打开了数据库，如下：
<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.</pre>
接着检查了数据库alert log，也没有发现任何的ora-错误。
看到最后，或许大家会觉得很奇怪，为什么会出现这样的故障呢 ？ 这里我也跟大家一样困惑。为什么说困惑呢？
因为这库是通过shutdown immediate方式正常停止的。我们都知道，这种方式停库之后，整个Oracle数据库的
文件都是处于一致的状态，重新启动数据库实例后按理说是不需要再进行实例恢复的。
那么为什么这里又出现了这种情况呢？
针对这个问题，我认为有2种可能性：
1、shutdown immediate之后，数据库写入到操作系统cache，还未完全写入到disk上时，此时数据库主机被强行重启；
由于操作系统cache丢失，导致数据库出现了不一致的情况(本文环境是Linux文件系统)。
2、其他程序或软件破坏了Oracle数据库文件的一致性（实际上，经过了解该环境部署了Rose HA软件；而且
客户在操作时，据说并没有停止rose ha软件）。
由于客户操作的时间点是凌晨2点，几乎是0业务场景，因此我认为第一种可能性几乎为0；第2种可能性更大。
当然由于我们不了解Rose HA软件的工作机制，这里不便评论。只能说这是一个非常奇怪的case了。
值得欣慰的是，通过我们的努力，很快就帮助客户恢复了系统访问，并且无数据丢失。
