DataBase can’t be open after shutdown immediate

五一放假期间，某客户的数据库出现故障，据说对方找了一些工程师折腾了一天，都无法将数据库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是0×20，而redo block中记录的record number是0×2. 这确实是不匹配的。

那么怎么解决这个问题呢？ 能不能通过屏蔽回滚段的方式来解决呢？我尝试在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</pre>

?

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.</pre>

?

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

值得欣慰的是，通过我们的努力，很快就帮助客户恢复了系统访问，并且无数据丢失。