IT博客汇
  • 首页
  • 精华
  • 技术
  • 设计
  • 资讯
  • 扯淡
  • 权利声明
  • 登录 注册

    DataBase can’t be open after shutdown immediate

    admin发表于 2017-05-02 14:07:46
    love 0

    本站文章除注明转载外,均为本站原创: 转载自love wife & love life —Roger 的Oracle技术博客

    本文链接地址: DataBase can’t be open after shutdown immediate

    五一放假期间,某客户的数据库出现故障,据说对方找了一些工程师折腾了一天,都无法将数据库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]  5f 53 59 53 53 4d 55 31 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]  c1 04
    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有问题,而且是after image。结合我们前面解释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 回滚段头来绕过这个错误,如下是操作过程:
    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
    注意,这里我们仅仅需要修改ktuxcnfb和ktuxcfbp[1] 即可。其中将ktuxcnfb修改为0,ktuxcfbp[1]中的uba修改为0.
    然后再尝试打开数据库,发现顺利打开了数据库,如下:
    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.
    接着检查了数据库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了。
    值得欣慰的是,通过我们的努力,很快就帮助客户恢复了系统访问,并且无数据丢失。

    Related posts:

    1. database crash with ora-00494
    2. 数据库open报错ORA-01555: snapshot too old
    3. 非归档遭遇ora-00600 [kcratr_nab_less_than_odr]的恢复
    4. Instance immediate crash after open
    5. Oracle 11gR2 for Windows遭遇ora-600[4194]的恢复


沪ICP备19023445号-2号
友情链接