存储控制器故障导致RAC数据库ORA-600[kclchkblk_4]错误故障修复

大家好，我是黄伟老师。前几天，一位网友的数据库因为双存储控制器故障，导致一套跑在该存储上的Oracle11gR2 RAC数据库异常，出现ORA-600的错误，数据库无法正常启动，影响业务系统的正常使用和生产，于是找我帮忙处理。处理完这个case之后，现在我把当时的情景尽可能的还原出来，录制成这个视频，希望各位观看学习之后，将来如果在你的工作中，也出现类似的数据库故障，可以起到一个参考指导的作用，提供一个分析的思路，帮各位快速定位和恢复启动数据库。当然，这里面会涉及到一些Oracle数据库的运行原理和一些专业术语，比如SCN、Checkpoint，不过我会尽可能尝试着把它们讲清楚。

一首先，接到帮助请求

二分析错误和定位问题

对于不熟悉Oracle错误的同学，可以参考metalink(Oracle官方技术支持网站)官方文档(What is an ORA-600 Internal Error? (Doc ID 146580.1))的解释：

什么是ORA-600？

*ORA-600 errors are raised from the kernel code of the Oracle RDBMS software when an internal inconsistency is detected or an unexpected condition is met. This situation is not necessarily a bug as it might be caused by problems with the Operating System, lack of resources, hardware failures, etc.

With the ORA-600 error comes a list of arguments in square brackets. The first of these arguments tells us from where in the code the error was caught and thus is the key information in identifying the problem. This argument is either a number or a character string. The remaining arguments are used to supply further information (e.g. values of internal variables etc).

Whenever an ORA-600 error is raised a trace file is generated and an entry written to the alert.log with details of the trace file location. Starting with Oracle Database 11g Release 1, the diagnosability infrastructure was introduced which places the trace and core files into a location controlled by the DIAGNOSTIC_DEST initialization parameter when an incident, such as an ORA-600 is created. For earlier versions, the trace file will be written to either USER_DUMP_DEST (if the error was caught in a user process) or BACKGROUND_DUMP_DEST (if the error was caught in a background process like PMON or SMON). The trace file contains vital information about what led to the error condition.*

所以，我们从错误信息参数中，可以猜测出，ORA-00600: internal error code, arguments: [kclchkblk_4]应该是跟数据块错误有关的可能性很大。再结合这个案例，网友提供的信息说存储控制器故障，猜测多半情况下，数据库在运行（数据库进程通过内存空间，频繁和存储设备读写数据）的过程中，存储控制器一旦故障，多数情况下会导致内存中的脏数据（被修改过的数据）无法写入数据库，或者数据库检查点信息无法同步到控制文件、日志文件、数据文件中。那么数据库必死无疑，无法再继续工作下去了，当我们下次手工启库、或者数据库自动重启的过程中，数据库在open阶段，如果数据库无法完成一致性校验或者Instance Recovery实例恢复，那么数据库就无法Open，不能对业务系统提供服务了。

那么，本案例中，这个ORA-00600: internal error code, arguments: [kclchkblk_4]究竟表示什么意思呢？后面的几个参数又表示什么呢？我想，如果我们能把这几个参数搞清楚的话，那么这个问题也许就有眉目了。

于是，从metalink上找到跟该错误有关的几篇文章：

1 ORA-600 [kclchkblk_4] (Doc ID 1522401.1)

从ORA-600 [kclchkblk_4] (Doc ID 1522401.1)这篇文档中，获取的信息有限，只是说：目前该错误并没有完全公开发布出来，因为它通常伴随ORA-600错误出现，而且被认为是已知确认的bug。

2 Bug 14351566 – ORA-600 [kclchkblk_4] ORA-600 [2662] when doing flash back (Doc ID 14351566.8)

该文档描述的是数据库多次执行flashback之后，导致的bug。我们该故障场景中，数据库并没有执行flashback的操作，排除。

3 ORA-600 [2662] “Block SCN is ahead of Current SCN” (Doc ID 28929.1)

不过，从该指导文档中可以获取到对此案例有用的指导信息。

① 该错误比较常见，通常由于存储故障、或者服务器异常掉电，数据库abort关闭等，导致的数据块里记录的SCN与数据库当前SCN不一致导致的。解决问题的常规办法就是通过redo log恢复数据，如果依然不奏效的话，可能需要通过非常规手段来修改数据库的SCN，使之一致，进而避免该错误发生。

这里，我在一套测试环境上模拟了该错误，并且手工修复了该错误：

Sat Dec 19 08:55:28 2020
SMON: enabling cache recovery
Errors in file /u01/app/oracle/diag/rdbms/orcl/orcl/trace/orcl_ora_8251.trc  (incident=28953):
ORA-00600: internal error code, arguments: [2662], [0], [112587826], [0], [112587881], [4194432], [], [], [], [], [], []
Incident details in: /u01/app/oracle/diag/rdbms/orcl/orcl/incident/incdir_28953/orcl_ora_8251_i28953.trc
Errors in file /u01/app/oracle/diag/rdbms/orcl/orcl/trace/orcl_ora_8251.trc:
ORA-00600: internal error code, arguments: [2662], [0], [112587826], [0], [112587881], [4194432], [], [], [], [], [], []
Errors in file /u01/app/oracle/diag/rdbms/orcl/orcl/trace/orcl_ora_8251.trc:
ORA-00600: internal error code, arguments: [2662], [0], [112587826], [0], [112587881], [4194432], [], [], [], [], [], []
Error 600 happened during db open, shutting down database
USER (ospid: 8251): terminating the instance due to error 600
Instance terminated by USER, pid = 8251
ORA-1092 signalled during: alter database open resetlogs...
opiodr aborting process unknown ospid (8251) as a result of ORA-1092
Sat Dec 19 08:55:33 2020

当然，这是另外一个case，我们暂且不去聚焦这个ORA-600 26662的错误如果解决。如果大家感兴趣且有需求的话，我可以另外录制一个视频去讲解它。

②从该文档中，倒是给出了有意义的错误参数：

ARGUMENTS:
Arg [a] Current SCN WRAP
Arg [b] Current SCN BASE
Arg [c] dependent SCN WRAP
Arg [d] dependent SCN BASE
Arg [e] Where present this is the DBA where the dependent SCN came from.

可以看出，这些错误参数，跟前面提到的错误参数格式非常一致：

RROR:

Format: ORA-600 [kclchkblk_4] [a] [b] [c] [d] [e]

但是，Oracle官方并没有给出这里的几个参数表示的具体意义。

那么，进一步猜测，我们这个故障的错误是不是也可以借鉴于该文档中给出的suggestion来尝试恢复呢？

③ 官方给出的几个suggestion


SUGGESTIONS:        
     
  There are different situations where ORA-600 [2662] can be raised.

  It can be raised on startup or during database operation.

  If not using Parallel Server, check that 2 instances have not mounted
  the same database.

  Check for SMON traces and have the alert.log and trace files ready
  to send to support.

  Check the SCN difference [argument d]-[argument b].

  If the SCNs in the error are very close, then try to shutdown and startup
  the instance several times. 

  In some situations, the SCN increment during startup may permit the 
  database to open. Keep track of the number of times you attempted a 
  startup.

到这里，有了一个可以尝试的解决问题的思路了，如果ORA-600 [kclchkblk_4] [a] [b] [c] [d] [e]这里的几个参数也表示某种与SCN有关的信息的话，那么，是不是可以根据该建议尝试恢复呢？

三解决问题

1 start instance，确认错误参数是否推进

Tue Dec 08 15:04:02 2020
Thread 1 advanced to log sequence 9 (thread open)
Thread 1 opened at log sequence 9
  Current log# 1 seq# 9 mem# 0: +DATA/jhzmpr/onlinelog/group_1.262.1045198071
  Current log# 1 seq# 9 mem# 1: +DATA/jhzmpr/onlinelog/group_1.263.1045198071
Successful open of redo thread 1
MTTR advisory is disabled because FAST_START_MTTR_TARGET is not set
Tue Dec 08 15:04:02 2020
SMON: enabling cache recovery
SUCCESS: diskgroup ARCH was mounted
Archived Log entry 1831 added for thread 1 sequence 8 ID 0xddd7c8e4 dest 1:
Errors in file /u01/app/oracle/diag/rdbms/jhzmpr/jhzmpr1/trace/jhzmpr1_ora_17070.trc  (incident=800345):
ORA-00600: internal error code, arguments: [kclchkblk_4], [0], [171642483], [0], [171385871], [], [], [], [], [], [], []
Incident details in: /u01/app/oracle/diag/rdbms/jhzmpr/jhzmpr1/incident/incdir_800345/jhzmpr1_ora_17070_i800345.trc
Use ADRCI or Support Workbench to package the incident.
See Note 411.1 at My Oracle Support for error and packaging details.
NOTE: dependency between database jhzmpr and diskgroup resource ora.ARCH.dg is established
Errors in file /u01/app/oracle/diag/rdbms/jhzmpr/jhzmpr1/trace/jhzmpr1_ora_17070.trc:
ORA-00704: bootstrap process failure
ORA-00704: bootstrap process failure
ORA-00600: internal error code, arguments: [kclchkblk_4], [0], [171642483], [0], [171385871], [], [], [], [], [], [], []
Errors in file /u01/app/oracle/diag/rdbms/jhzmpr/jhzmpr1/trace/jhzmpr1_ora_17070.trc:
ORA-00704: bootstrap process failure
ORA-00704: bootstrap process failure
ORA-00600: internal error code, arguments: [kclchkblk_4], [0], [171642483], [0], [171385871], [], [], [], [], [], [], []
Error 704 happened during db open, shutting down database
USER (ospid: 17070): terminating the instance due to error 704
Instance terminated by USER, pid = 17070
ORA-1092 signalled during: alter database open...
opiodr aborting process unknown ospid (17070) as a result of ORA-1092
Tue Dec 08 15:04:05 2020
ORA-1092 : opitsk aborting process

果不其然，argument d比上次推进了：从之前的171365869推进到171385871。同时，argument b保持不变，其它错误信息也保持一致。

2 继续上述操作

[root@jhzmpr01 ~]# srvctl start db -d jhzmpr
PRCR-1079 : Failed to start resource ora.jhzmpr.db
CRS-5017: The resource action "ora.jhzmpr.db start" encountered the following error:
ORA-01092: ORACLE instance terminated. Disconnection forced
ORA-00704: bootstrap process failure
ORA-00704: bootstrap process failure
ORA-00600: internal error code, arguments: [kclchkblk_4], [0], [171642483], [0], [171405876], [], [], [], [], [], [], []
Process ID: 21207
Session ID: 3175 Serial number: 3
. For details refer to "(:CLSN00107:)" in "/u01/app/11.2.0/grid/log/jhzmpr01/agent/crsd/oraagent_oracle//oraagent_oracle.log".

CRS-5017: The resource action "ora.jhzmpr.db start" encountered the following error:
ORA-01092: ORACLE instance terminated. Disconnection forced
ORA-00704: bootstrap process failure
ORA-00704: bootstrap process failure
ORA-00600: internal error code, arguments: [kclchkblk_4], [0], [171642483], [0], [171405882], [], [], [], [], [], [], []
Process ID: 43944
Session ID: 3175 Serial number: 3
. For details refer to "(:CLSN00107:)" in "/u01/app/11.2.0/grid/log/jhzmpr02/agent/crsd/oraagent_oracle//oraagent_oracle.log".

CRS-2674: Start of 'ora.jhzmpr.db' on 'jhzmpr01' failed
CRS-2674: Start of 'ora.jhzmpr.db' on 'jhzmpr02' failed
CRS-2632: There are no more servers to try to place resource 'ora.jhzmpr.db' on that would satisfy its placement policy
[root@jhzmpr01 ~]#

3 直至错误参数一致

Tue Dec 08 15:44:31 2020
SMON: enabling cache recovery
SUCCESS: diskgroup ARCH was mounted
Archived Log entry 1846 added for thread 1 sequence 22 ID 0xddd7c8e4 dest 1:
NOTE: dependency between database jhzmpr and diskgroup resource ora.ARCH.dg is established
Errors in file /u01/app/oracle/diag/rdbms/jhzmpr/jhzmpr1/trace/jhzmpr1_ora_54315.trc  (incident=1248369):
ORA-00600: internal error code, arguments: [kclchkblk_4], [0], [171679465], [0], [171665974], [], [], [], [], [], [], []
Incident details in: /u01/app/oracle/diag/rdbms/jhzmpr/jhzmpr1/incident/incdir_1248369/jhzmpr1_ora_54315_i1248369.trc
Use ADRCI or Support Workbench to package the incident.
See Note 411.1 at My Oracle Support for error and packaging details.
Errors in file /u01/app/oracle/diag/rdbms/jhzmpr/jhzmpr1/trace/jhzmpr1_ora_54315.trc:
ORA-00600: internal error code, arguments: [kclchkblk_4], [0], [171679465], [0], [171665974], [], [], [], [], [], [], []
Errors in file /u01/app/oracle/diag/rdbms/jhzmpr/jhzmpr1/trace/jhzmpr1_ora_54315.trc:
ORA-00600: internal error code, arguments: [kclchkblk_4], [0], [171679465], [0], [171665974], [], [], [], [], [], [], []
Error 600 happened during db open, shutting down database
USER (ospid: 54315): terminating the instance due to error 600
Instance terminated by USER, pid = 54315
ORA-1092 signalled during: ALTER DATABASE OPEN /* db agent *//* {1:11782:10822} */...
opiodr aborting process unknown ospid (54315) as a result of ORA-1092
Tue Dec 08 15:44:34 2020
ORA-1092 : opitsk aborting process

4 启动数据库

Tue Dec 08 15:46:51 2020
Starting ORACLE instance (normal)
...
...
tarted redo scan
SUCCESS: diskgroup FLASH was mounted
Completed redo scan
 read 11 KB redo, 5 data blocks need recovery
Started redo application at
 Thread 1: logseq 23, block 3
Recovery of Online Redo Log: Thread 1 Group 5 Seq 23 Reading mem 0
  Mem# 0: +DATA/jhzmpr/onlinelog/group_5.273.1046776933
  Mem# 1: +FLASH/jhzmpr/onlinelog/group_5.256.1046776933
Completed redo application of 0.01MB
Completed crash recovery at
 Thread 1: logseq 23, block 25, scn 171685974
 5 data blocks read, 5 data blocks written, 11 redo k-bytes read
ARCH: STARTING ARCH PROCESSES
SMON: enabling tx recovery
*********************************************************************
WARNING: The following temporary tablespaces contain no files.
         This condition can occur when a backup controlfile has
         been restored.  It may be necessary to add files to these
         tablespaces.  That can be done using the SQL statement:

ALTER TABLESPACE <tablespace_name> ADD TEMPFILE

Alternatively, if these temporary tablespaces are no longer
needed, then they can be dropped.
Empty temporary tablespace: TEMP
*********************************************************************
Database Characterset is AL32UTF8
Errors in file /u01/app/oracle/diag/rdbms/jhzmpr/jhzmpr1/trace/jhzmpr1_smon_57089.trc (incident=1280273):
ORA-00600: internal error code, arguments: [4194], [], [], [], [], [], [], [], [], [], [], []
Incident details in: /u01/app/oracle/diag/rdbms/jhzmpr/jhzmpr1/incident/incdir_1280273/jhzmpr1_smon_57089_i1280273.trc
Use ADRCI or Support Workbench to package the incident.
See Note 411.1 at My Oracle Support for error and packaging details.

5 至此，该错误已经消失了，数据库可以正常访问了。

但是，alert日志里抛出一个报警，让我们给数据库添加临时文件。为什么呢？这是因为，这位网友之前根据网上的一些帖子尝试对数据库删除临时文件，但是没能恢复数据库。这里，我们可以先不去理会临时文件的文件，可以让数据库使用SYSAUX那个表空间充当临时表空间，如果需要的话。

四补充

1 SCN

①定义

System Change Number,数据库“内部时钟”，数据库中每时每刻都在发生改变，这些改变对应这一个具体的时间点儿，每个具体的时间点儿对应一个数字编号，这个编号就是SCN值。比如：2020年12月19日18时30分52秒，对应一个SCN号,35789713456。注意，不同时间点儿对应不同的SCN，数据库一旦启动运行，SCN就不停向前滚动。

② 作用

对于关系型数据库而言，用于事务的ACID控制和管理，以及数据库的备份和恢复的标准。

③位置

数据文件、控制文件、日志文件、数据文件头、数据块中都有记录。

④查看

SQL> select dbms_flashback.get_system_change_number scn from dual;

       SCN
----------
 112573590

SQL> select current_scn from v$database;

CURRENT_SCN
-----------
  112573593

SQL> select file#,CHECKPOINT_CHANGE#,CHECKPOINT_TIME from v$datafile;

     FILE# CHECKPOINT_CHANGE# CHECKPOINT_TIME
---------- ------------------ -------------------
         1          112563728 2020/12/19 15:38:19
         2          112563728 2020/12/19 15:38:19
         3          112563728 2020/12/19 15:38:19
         4          112563728 2020/12/19 15:38:19
         5          112563728 2020/12/19 15:38:19
         6          112563728 2020/12/19 15:38:19
         7          112563728 2020/12/19 15:38:19

7 rows selected.

SQL> select group#,FIRST_CHANGE#,FIRST_TIME from v$log;

    GROUP# FIRST_CHANGE# FIRST_TIME
---------- ------------- -------------------
         1     112563728 2020/12/19 15:38:19
         2     112544279 2020/12/19 11:35:21
         3     112551742 2020/12/19 12:37:46

SQL>