分类目录归档：Oracle备份恢复

File #N is offline, but is part of an online tablespace

发表于 2016 年 11 月 1 日由惜分飞

在看一个客户的数据库恢复日志的时候发现类似警告(File #N is offline, but is part of an online tablespace.),以前没有注意,这次通过试验来重现该部分内容
创建表空间

SQL> create tablespace readonly datafile '/home/oracle/.oradata/test/readonly01.dbf' size 128M;

Tablespace created.

SQL> alter tablespace  readonly add datafile '/home/oracle/.oradata/test/readonly02.dbf' size 128M;

Tablespace altered.

写入数据

SQL> create table t_readonly tablespace readonly as select * from dba_objects;

Table created.

read only 表空间

SQL> select count(*) from t_readonly;

  COUNT(*)
----------
     72226

SQL> alter system switch logfile;

System altered.

SQL> /

System altered.

SQL> /

System altered.

SQL>  alter tablespace readonly  read only;

Tablespace altered.

SQL> alter system switch logfile;

System altered.

SQL> /

System altered.

SQL> /

System altered.

SQL> /

System altered.

备份数据库

[oracle@localhost ~]$ rman target /

Recovery Manager: Release 11.2.0.1.0 - Production on Tue Nov 1 21:15:51 2016

Copyright (c) 1982, 2009, Oracle and/or its affiliates.  All rights reserved.

connected to target database: TEST (DBID=2210907828)

RMAN> backup database format '/home/oracle/full_%U.rman';

Starting backup at 01-NOV-16
using target database control file instead of recovery catalog
allocated channel: ORA_DISK_1
channel ORA_DISK_1: SID=197 device type=DISK
channel ORA_DISK_1: starting full datafile backup set
channel ORA_DISK_1: specifying datafile(s) in backup set
input datafile file number=00001 name=/home/oracle/.oradata/test/system01.dbf
input datafile file number=00002 name=/home/oracle/.oradata/test/sysaux01.dbf
input datafile file number=00005 name=/home/oracle/.oradata/test/test01.dbf
input datafile file number=00006 name=/home/oracle/.oradata/test/test02.dbf
input datafile file number=00007 name=/home/oracle/.oradata/test/readonly01.dbf
input datafile file number=00008 name=/home/oracle/.oradata/test/readonly02.dbf
input datafile file number=00003 name=/home/oracle/.oradata/test/undotbs01.dbf
input datafile file number=00004 name=/home/oracle/.oradata/test/users01.dbf
channel ORA_DISK_1: starting piece 1 at 01-NOV-16


channel ORA_DISK_1: finished piece 1 at 01-NOV-16
piece handle=/home/oracle/full_03rjrp0t_1_1.rman tag=TAG20161101T211613 comment=NONE
channel ORA_DISK_1: backup set complete, elapsed time: 00:00:25
channel ORA_DISK_1: starting full datafile backup set
channel ORA_DISK_1: specifying datafile(s) in backup set
including current control file in backup set
including current SPFILE in backup set
channel ORA_DISK_1: starting piece 1 at 01-NOV-16
channel ORA_DISK_1: finished piece 1 at 01-NOV-16
piece handle=/home/oracle/full_04rjrp1m_1_1.rman tag=TAG20161101T211613 comment=NONE
channel ORA_DISK_1: backup set complete, elapsed time: 00:00:01
Finished backup at 01-NOV-16

RMAN> sql 'alter system archive log current';
backup  as compressed backupset archivelog  all format '/home/oracle/arch_%T_%U.rman'  delete input;

sql statement: alter system archive log current

RMAN> 
Starting backup at 01-NOV-16
current log archived
using channel ORA_DISK_1
channel ORA_DISK_1: starting compressed archived log backup set
channel ORA_DISK_1: specifying archived log(s) in backup set
input archived log thread=1 sequence=494 RECID=1 STAMP=926802386
input archived log thread=1 sequence=495 RECID=2 STAMP=926802386
input archived log thread=1 sequence=496 RECID=3 STAMP=926802389
input archived log thread=1 sequence=497 RECID=4 STAMP=926802693
input archived log thread=1 sequence=498 RECID=5 STAMP=926802693
input archived log thread=1 sequence=499 RECID=6 STAMP=926802696
input archived log thread=1 sequence=500 RECID=7 STAMP=926802787
input archived log thread=1 sequence=501 RECID=8 STAMP=926802789
input archived log thread=1 sequence=502 RECID=9 STAMP=926802792
input archived log thread=1 sequence=503 RECID=10 STAMP=926802793
input archived log thread=1 sequence=504 RECID=11 STAMP=926802812
input archived log thread=1 sequence=505 RECID=12 STAMP=926802813
input archived log thread=1 sequence=506 RECID=13 STAMP=926802816
input archived log thread=1 sequence=507 RECID=14 STAMP=926803076
input archived log thread=1 sequence=508 RECID=15 STAMP=926803077
channel ORA_DISK_1: starting piece 1 at 01-NOV-16
channel ORA_DISK_1: finished piece 1 at 01-NOV-16
piece handle=/home/oracle/arch_20161101_05rjrp45_1_1.rman tag=TAG20161101T211757 comment=NONE
channel ORA_DISK_1: backup set complete, elapsed time: 00:00:03
channel ORA_DISK_1: deleting archived log(s)
archived log file name=/opt/oracle/flash_recovery_area/TEST/archivelog/2016_11_01/o1_mf_1_494_d1k4tkot_.arc RECID=1 STAMP=926802386
archived log file name=/opt/oracle/flash_recovery_area/TEST/archivelog/2016_11_01/o1_mf_1_495_d1k4tln7_.arc RECID=2 STAMP=926802386
archived log file name=/opt/oracle/flash_recovery_area/TEST/archivelog/2016_11_01/o1_mf_1_496_d1k4tot5_.arc RECID=3 STAMP=926802389
archived log file name=/opt/oracle/flash_recovery_area/TEST/archivelog/2016_11_01/o1_mf_1_497_d1k544w3_.arc RECID=4 STAMP=926802693
archived log file name=/opt/oracle/flash_recovery_area/TEST/archivelog/2016_11_01/o1_mf_1_498_d1k545wc_.arc RECID=5 STAMP=926802693
archived log file name=/opt/oracle/flash_recovery_area/TEST/archivelog/2016_11_01/o1_mf_1_499_d1k548bm_.arc RECID=6 STAMP=926802696
archived log file name=/opt/oracle/flash_recovery_area/TEST/archivelog/2016_11_01/o1_mf_1_500_d1k5734v_.arc RECID=7 STAMP=926802787
archived log file name=/opt/oracle/flash_recovery_area/TEST/archivelog/2016_11_01/o1_mf_1_501_d1k5752s_.arc RECID=8 STAMP=926802789
archived log file name=/opt/oracle/flash_recovery_area/TEST/archivelog/2016_11_01/o1_mf_1_502_d1k578c2_.arc RECID=9 STAMP=926802792
archived log file name=/opt/oracle/flash_recovery_area/TEST/archivelog/2016_11_01/o1_mf_1_503_d1k579hy_.arc RECID=10 STAMP=926802793
archived log file name=/opt/oracle/flash_recovery_area/TEST/archivelog/2016_11_01/o1_mf_1_504_d1k57w6s_.arc RECID=11 STAMP=926802812
archived log file name=/opt/oracle/flash_recovery_area/TEST/archivelog/2016_11_01/o1_mf_1_505_d1k57xj1_.arc RECID=12 STAMP=926802813
archived log file name=/opt/oracle/flash_recovery_area/TEST/archivelog/2016_11_01/o1_mf_1_506_d1k580hj_.arc RECID=13 STAMP=926802816
archived log file name=/opt/oracle/flash_recovery_area/TEST/archivelog/2016_11_01/o1_mf_1_507_d1k5j4q0_.arc RECID=14 STAMP=926803076
archived log file name=/opt/oracle/flash_recovery_area/TEST/archivelog/2016_11_01/o1_mf_1_508_d1k5j4yq_.arc RECID=15 STAMP=926803077
Finished backup at 01-NOV-16

RMAN> backup  format '/home/oracle/ctl_%T_%U.rman' current controlfile;

Starting backup at 01-NOV-16
using channel ORA_DISK_1
channel ORA_DISK_1: starting full datafile backup set
channel ORA_DISK_1: specifying datafile(s) in backup set
including current control file in backup set
channel ORA_DISK_1: starting piece 1 at 01-NOV-16
channel ORA_DISK_1: finished piece 1 at 01-NOV-16
piece handle=/home/oracle/ctl_20161101_06rjrp75_1_1.rman tag=TAG20161101T211933 comment=NONE
channel ORA_DISK_1: backup set complete, elapsed time: 00:00:01
Finished backup at 01-NOV-16

清理环境还原数据库

RMAN> shutdown immediate;

database closed
database dismounted
Oracle instance shut down

RMAN> exit


Recovery Manager complete.

[oracle@localhost .oradata]$ mv test  test_20161101
[oracle@localhost .oradata]$ mkdir test

还原数据库

[oracle@localhost ~]$ sqlplus / as sysdba

SQL*Plus: Release 11.2.0.1.0 Production on Tue Nov 1 21:21:09 2016

Copyright (c) 1982, 2009, Oracle.  All rights reserved.

Connected to an idle instance.

SQL> startup nomount;
ORACLE instance started.

Total System Global Area 2421825536 bytes
Fixed Size                  2215744 bytes
Variable Size            1795162304 bytes
Database Buffers          603979776 bytes
Redo Buffers               20467712 bytes
SQL> exit
Disconnected from Oracle Database 11g Enterprise Edition Release 11.2.0.1.0 - 64bit Production
With the Partitioning, OLAP, Data Mining and Real Application Testing options
[oracle@localhost ~]$ rman target /

Recovery Manager: Release 11.2.0.1.0 - Production on Tue Nov 1 21:21:22 2016

Copyright (c) 1982, 2009, Oracle and/or its affiliates.  All rights reserved.

connected to target database: TEST (not mounted)

RMAN> restore controlfile from '/home/oracle/ctl_20161101_06rjrp75_1_1.rman';

Starting restore at 01-NOV-16
using target database control file instead of recovery catalog
allocated channel: ORA_DISK_1
channel ORA_DISK_1: SID=63 device type=DISK

channel ORA_DISK_1: restoring control file
channel ORA_DISK_1: restore complete, elapsed time: 00:00:01
output file name=/home/oracle/.oradata/test/control01.ctl
Finished restore at 01-NOV-16

RMAN> alter database mount;

database mounted
released channel: ORA_DISK_1

RMAN> restore database;

Starting restore at 01-NOV-16
Starting implicit crosscheck backup at 01-NOV-16
allocated channel: ORA_DISK_1
channel ORA_DISK_1: SID=63 device type=DISK
Crosschecked 3 objects
Finished implicit crosscheck backup at 01-NOV-16

Starting implicit crosscheck copy at 01-NOV-16
using channel ORA_DISK_1
Finished implicit crosscheck copy at 01-NOV-16

searching for all files in the recovery area
cataloging files...
no files cataloged

using channel ORA_DISK_1

datafile 5 not processed because file is offline
datafile 6 not processed because file is offline
channel ORA_DISK_1: starting datafile backup set restore
channel ORA_DISK_1: specifying datafile(s) to restore from backup set
channel ORA_DISK_1: restoring datafile 00001 to /home/oracle/.oradata/test/system01.dbf
channel ORA_DISK_1: restoring datafile 00002 to /home/oracle/.oradata/test/sysaux01.dbf
channel ORA_DISK_1: restoring datafile 00003 to /home/oracle/.oradata/test/undotbs01.dbf
channel ORA_DISK_1: restoring datafile 00004 to /home/oracle/.oradata/test/users01.dbf
channel ORA_DISK_1: restoring datafile 00007 to /home/oracle/.oradata/test/readonly01.dbf
channel ORA_DISK_1: restoring datafile 00008 to /home/oracle/.oradata/test/readonly02.dbf
channel ORA_DISK_1: reading from backup piece /home/oracle/full_03rjrp0t_1_1.rman
channel ORA_DISK_1: piece handle=/home/oracle/full_03rjrp0t_1_1.rman tag=TAG20161101T211613
channel ORA_DISK_1: restored backup piece 1
channel ORA_DISK_1: restore complete, elapsed time: 00:00:15
Finished restore at 01-NOV-16

RMAN> exit


Recovery Manager complete.

检查数据库文件

通过Oracle Database Recovery Check很明显发现,这里看到文件状态是read only的.
recover database

[oracle@localhost ~]$ rman target /

Recovery Manager: Release 11.2.0.1.0 - Production on Tue Nov 1 21:28:14 2016

Copyright (c) 1982, 2009, Oracle and/or its affiliates.  All rights reserved.

connected to target database: TEST (DBID=2210907828, not open)

RMAN> recover database;

Starting recover at 01-NOV-16
using target database control file instead of recovery catalog
allocated channel: ORA_DISK_1
channel ORA_DISK_1: SID=63 device type=DISK
datafile 7 not processed because file is read-only    <<<<=====注意
datafile 8 not processed because file is read-only    <<<<=====注意

starting media recovery

channel ORA_DISK_1: starting archived log restore to default destination
channel ORA_DISK_1: restoring archived log
archived log thread=1 sequence=507
channel ORA_DISK_1: restoring archived log
archived log thread=1 sequence=508
channel ORA_DISK_1: reading from backup piece /home/oracle/arch_20161101_05rjrp45_1_1.rman
channel ORA_DISK_1: piece handle=/home/oracle/arch_20161101_05rjrp45_1_1.rman tag=TAG20161101T211757
channel ORA_DISK_1: restored backup piece 1
channel ORA_DISK_1: restore complete, elapsed time: 00:00:01
archived log file name=/opt/oracle/flash_recovery_area/TEST/archivelog/2016_11_01/o1_mf_1_507_d1k63pj8_.arc thread=1 sequence=507
channel default: deleting archived log(s)
archived log file name=/opt/oracle/flash_recovery_area/TEST/archivelog/2016_11_01/o1_mf_1_507_d1k63pj8_.arc RECID=16 STAMP=926803702
archived log file name=/opt/oracle/flash_recovery_area/TEST/archivelog/2016_11_01/o1_mf_1_508_d1k63pww_.arc thread=1 sequence=508
channel default: deleting archived log(s)
archived log file name=/opt/oracle/flash_recovery_area/TEST/archivelog/2016_11_01/o1_mf_1_508_d1k63pww_.arc RECID=17 STAMP=926803702
unable to find archived log
archived log thread=1 sequence=509
RMAN-00571: ===========================================================
RMAN-00569: =============== ERROR MESSAGE STACK FOLLOWS ===============
RMAN-00571: ===========================================================
RMAN-03002: failure of recover command at 11/01/2016 21:28:24
RMAN-06054: media recovery requesting unknown archived log for thread 1 with sequence 509 and starting SCN of 8933048

RMAN> exit

resetlogs 打开数据库

SQL> set numw 16
SQL> SELECT status,
checkpoint_change#,
  2    3  checkpoint_time,last_change#,
count(*) ROW_NUM
FROM v$datafile
GROUP BY status, checkpoint_change#, checkpoint_time,last_change#
ORDER BY status, checkpoint_change#, checkpoint_time;  4    5    6    7  

STATUS  CHECKPOINT_CHANGE# CHECKPOIN     LAST_CHANGE#          ROW_NUM
------- ------------------ --------- ---------------- ----------------
ONLINE             8932792 01-NOV-16                                 2
ONLINE             8933048 01-NOV-16                                 3
SYSTEM             8933048 01-NOV-16                                 1

SQL> SELECT status,
  2  checkpoint_change#,
  3  checkpoint_time,FUZZY,
  4  count(*) ROW_NUM
  5  FROM v$datafile_header
GROUP BY status, checkpoint_change#, checkpoint_time,fuzzy
ORDER BY status, checkpoint_change#, checkpoint_time;
  6    7  
STATUS  CHECKPOINT_CHANGE# CHECKPOIN FUZ          ROW_NUM
------- ------------------ --------- --- ----------------
ONLINE             8932792 01-NOV-16 NO                 2
ONLINE             8933048 01-NOV-16 NO                 4

SQL> alter database open resetlogs;

Database altered.

alert日志信息

Tue Nov 01 21:29:56 2016
alter database open resetlogs
Errors in file /opt/oracle/diag/rdbms/test/test/trace/test_ora_14479.trc:
ORA-00313: open failed for members of log group 1 of thread 1
ORA-00312: online log 1 thread 1: '/home/oracle/.oradata/test/redo01.log'
ORA-27037: unable to obtain file status
Linux-x86_64 Error: 2: No such file or directory
Additional information: 3
Errors in file /opt/oracle/diag/rdbms/test/test/trace/test_ora_14479.trc:
ORA-00313: open failed for members of log group 1 of thread 1
ORA-00312: online log 1 thread 1: '/home/oracle/.oradata/test/redo01.log'
ORA-27037: unable to obtain file status
Linux-x86_64 Error: 2: No such file or directory
Additional information: 3
Errors in file /opt/oracle/diag/rdbms/test/test/trace/test_ora_14479.trc:
ORA-00313: open failed for members of log group 2 of thread 1
ORA-00312: online log 2 thread 1: '/home/oracle/.oradata/test/redo02.log'
ORA-27037: unable to obtain file status
Linux-x86_64 Error: 2: No such file or directory
Additional information: 3
Errors in file /opt/oracle/diag/rdbms/test/test/trace/test_ora_14479.trc:
ORA-00313: open failed for members of log group 2 of thread 1
ORA-00312: online log 2 thread 1: '/home/oracle/.oradata/test/redo02.log'
ORA-27037: unable to obtain file status
Linux-x86_64 Error: 2: No such file or directory
Additional information: 3
Errors in file /opt/oracle/diag/rdbms/test/test/trace/test_ora_14479.trc:
ORA-00313: open failed for members of log group 3 of thread 1
ORA-00312: online log 3 thread 1: '/home/oracle/.oradata/test/redo03.log'
ORA-27037: unable to obtain file status
Linux-x86_64 Error: 2: No such file or directory
Additional information: 3
Errors in file /opt/oracle/diag/rdbms/test/test/trace/test_ora_14479.trc:
ORA-00313: open failed for members of log group 3 of thread 1
ORA-00312: online log 3 thread 1: '/home/oracle/.oradata/test/redo03.log'
ORA-27037: unable to obtain file status
Linux-x86_64 Error: 2: No such file or directory
Additional information: 3
RESETLOGS after incomplete recovery UNTIL CHANGE 8933048
Resetting resetlogs activation ID 2210869684 (0x83c731b4)
Errors in file /opt/oracle/diag/rdbms/test/test/trace/test_ora_14479.trc:
ORA-00313: open failed for members of log group 1 of thread 1
ORA-00312: online log 1 thread 1: '/home/oracle/.oradata/test/redo01.log'
ORA-27037: unable to obtain file status
Linux-x86_64 Error: 2: No such file or directory
Additional information: 3
Errors in file /opt/oracle/diag/rdbms/test/test/trace/test_ora_14479.trc:
ORA-00313: open failed for members of log group 1 of thread 1
ORA-00312: online log 1 thread 1: '/home/oracle/.oradata/test/redo01.log'
ORA-27037: unable to obtain file status
Linux-x86_64 Error: 2: No such file or directory
Additional information: 3
Errors in file /opt/oracle/diag/rdbms/test/test/trace/test_ora_14479.trc:
ORA-00313: open failed for members of log group 2 of thread 1
ORA-00312: online log 2 thread 1: '/home/oracle/.oradata/test/redo02.log'
ORA-27037: unable to obtain file status
Linux-x86_64 Error: 2: No such file or directory
Additional information: 3
Errors in file /opt/oracle/diag/rdbms/test/test/trace/test_ora_14479.trc:
ORA-00313: open failed for members of log group 2 of thread 1
ORA-00312: online log 2 thread 1: '/home/oracle/.oradata/test/redo02.log'
ORA-27037: unable to obtain file status
Linux-x86_64 Error: 2: No such file or directory
Additional information: 3
Errors in file /opt/oracle/diag/rdbms/test/test/trace/test_ora_14479.trc:
ORA-00313: open failed for members of log group 3 of thread 1
ORA-00312: online log 3 thread 1: '/home/oracle/.oradata/test/redo03.log'
ORA-27037: unable to obtain file status
Linux-x86_64 Error: 2: No such file or directory
Additional information: 3
Errors in file /opt/oracle/diag/rdbms/test/test/trace/test_ora_14479.trc:
ORA-00313: open failed for members of log group 3 of thread 1
ORA-00312: online log 3 thread 1: '/home/oracle/.oradata/test/redo03.log'
ORA-27037: unable to obtain file status
Linux-x86_64 Error: 2: No such file or directory
Additional information: 3
Tue Nov 01 21:29:58 2016
Setting recovery target incarnation to 3
Tue Nov 01 21:29:58 2016
Assigning activation ID 2224900353 (0x849d4901)
LGWR: STARTING ARCH PROCESSES
Tue Nov 01 21:29:58 2016
ARC0 started with pid=20, OS id=14486
ARC0: Archival started
LGWR: STARTING ARCH PROCESSES COMPLETE
ARC0: STARTING ARCH PROCESSES
Tue Nov 01 21:29:59 2016
ARC1 started with pid=21, OS id=14488
Tue Nov 01 21:29:59 2016
ARC2 started with pid=22, OS id=14490
ARC1: Archival started
Tue Nov 01 21:29:59 2016
ARC3 started with pid=23, OS id=14492
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 1
  Current log# 1 seq# 1 mem# 0: /home/oracle/.oradata/test/redo01.log
Successful open of redo thread 1
MTTR advisory is disabled because FAST_START_MTTR_TARGET is not set
Tue Nov 01 21:29:59 2016
SMON: enabling cache recovery
Successfully onlined Undo Tablespace 2.
Dictionary check beginning
File #7 is offline, but is part of an online tablespace.
data file 7: '/home/oracle/.oradata/test/readonly01.dbf'
Successfuly brought file #7 online.
File #8 is offline, but is part of an online tablespace.
data file 8: '/home/oracle/.oradata/test/readonly02.dbf'
Successfuly brought file #8 online.
Tue Nov 01 21:29:59 2016
Errors in file /opt/oracle/diag/rdbms/test/test/trace/test_dbw0_14226.trc:
ORA-01157: cannot identify/lock data file 201 - see DBWR trace file
ORA-01110: data file 201: '/home/oracle/.oradata/test/temp01.dbf'
ORA-27037: unable to obtain file status
Linux-x86_64 Error: 2: No such file or directory
Additional information: 3
Errors in file /opt/oracle/diag/rdbms/test/test/trace/test_dbw0_14226.trc:
ORA-01186: file 201 failed verification tests
ORA-01157: cannot identify/lock data file 201 - see DBWR trace file
ORA-01110: data file 201: '/home/oracle/.oradata/test/temp01.dbf'
File 201 not verified due to error ORA-01157
Dictionary check complete
Verifying file header compatibility for 11g tablespace encryption..
Verifying 11g file header compatibility for tablespace encryption completed
SMON: enabling tx recovery
Re-creating tempfile /home/oracle/.oradata/test/temp01.dbf
Database Characterset is AL32UTF8
No Resource Manager plan active
replication_dependency_tracking turned off (no async multimaster replication found)
Starting background process QMNC
Tue Nov 01 21:30:00 2016
QMNC started with pid=24, OS id=14494
LOGSTDBY: Validating controlfile with logical metadata
LOGSTDBY: Validation complete
ARC3: Archival started
ARC0: STARTING ARCH PROCESSES COMPLETE
Completed: alter database open resetlogs

这里看到了我们期待的警告
File #7 is offline, but is part of an online tablespace.
data file 7: ‘/home/oracle/.oradata/test/readonly01.dbf’
Successfuly brought file #7 online.
File #8 is offline, but is part of an online tablespace.
data file 8: ‘/home/oracle/.oradata/test/readonly02.dbf’
Successfuly brought file #8 online.
结论：如果数据库的表空间之前是read only,然后resetlogs操作就会有类似提示(File #N is offline, but is part of an online tablespace).这样的整个恢复过程不影响read only表空间中的数据

发表在 Oracle备份恢复 | 标签为 file offline | 评论关闭

ORA-600 kcrfr_update_nab_2 故障恢复

发表于 2016 年 10 月 24 日由惜分飞

由于控制器掉线导致数据库启动报ORA-600 kcrfr_update_nab_2错误,导致无法正常open
数据库版本信息

ORACLE V10.2.0.4.0 - 64bit Production vsnsta=0
vsnsql=14 vsnxtr=3
Oracle Database 10g Enterprise Edition Release 10.2.0.4.0 - 64bit Production
With the Partitioning, OLAP, Data Mining and Real Application Testing options
Windows Server 2003 Version V5.2 Service Pack 2
CPU                 : 12 - type 8664, 2 Physical Cores
Process Affinity    : 0x0000000000000000
Memory (Avail/Total): Ph:22579M/32754M, Ph+PgF:24594M/33845M

ORA-600 kcrfr_update_nab_2报错

Mon Oct 24 17:42:57 2016
Database mounted in Exclusive Mode
Completed: ALTER DATABASE   MOUNT
Mon Oct 24 17:42:58 2016
ALTER DATABASE OPEN
Mon Oct 24 17:43:14 2016
Beginning crash recovery of 1 threads
 parallel recovery started with 11 processes
Mon Oct 24 17:43:14 2016
Started redo scan
Mon Oct 24 17:43:16 2016
Errors in file d:\oracle\product\10.2.0\admin\spcsjkdb\udump\spcsjkdb_ora_10108.trc:
ORA-00600: internal error code, arguments: [kcrfr_update_nab_2], [0x7FFC22A2150], [2], [], [], [], [], []

Mon Oct 24 17:43:18 2016
Aborting crash recovery due to error 600
Mon Oct 24 17:43:18 2016
Errors in file d:\oracle\product\10.2.0\admin\spcsjkdb\udump\spcsjkdb_ora_10108.trc:
ORA-00600: internal error code, arguments: [kcrfr_update_nab_2], [0x7FFC22A2150], [2], [], [], [], [], []

ORA-600 signalled during: ALTER DATABASE OPEN...

trace文件信息

*** 2016-10-24 17:43:14.515
*** ACTION NAME:() 2016-10-24 17:43:14.515
*** MODULE NAME:(sqlplus.exe) 2016-10-24 17:43:14.515
*** SERVICE NAME:() 2016-10-24 17:43:14.515
*** SESSION ID:(356.3) 2016-10-24 17:43:14.515
Successfully allocated 11 recovery slaves
Using 101 overflow buffers per recovery slave
Thread 1 checkpoint: logseq 33251, block 2, scn 14624215134369
  cache-low rba: logseq 33251, block 2463324
    on-disk rba: logseq 33251, block 2803965, scn 14624216078841
  start recovery at logseq 33251, block 2463324, scn 0
*** 2016-10-24 17:43:16.406
ksedmp: internal or fatal error
ORA-00600: internal error code, arguments: [kcrfr_update_nab_2], [0x7FFC22A2150], [2], [], [], [], [], []
Current SQL statement for this session:
ALTER DATABASE OPEN
----- Call Stack Trace -----
calling              call     entry                argument values in hex      
location             type     point                (? means dubious value)     
-------------------- -------- -------------------- ----------------------------
ksedmp+663           CALL???  ksedst+55            003C878B8 000000000 012B863E8
                                                   000000000
ksfdmp+19            CALL???  ksedmp+663           000000003 015572A70 007222698
                                                   003CACC80
kgerinv+158          CALL???  ksfdmp+19            015572430 000000000 0FFFFFFFF
                                                   000000000
kgeasnmierr+62       CALL???  kgerinv+158          000000000 000000000 000000000
                                                   004FD788F
kcrfr_update_nab+18  CALL???  kgeasnmierr+62       00BDA1170 000000000 000000000
6                                                  000000002
kcrfr_read+1078      CALL???  kcrfr_update_nab+18  007222698 00001E650 015572430
                              6                    0072229B8
kcrfrgv+8134         CALL???  kcrfr_read+1078      000000000 0051525D7 000000000
                                                   0051525D7
kcratr1+488          CALL???  kcrfrgv+8134         007222698 000000000 000000000
                                                   000000000
kcratr+412           CALL???  kcratr1+488          012B891C8 012B890A4 00727FFB8
                                                   00BEA7FF0
kctrec+1910          CALL???  kcratr+412           012B891C8 012B91E18 000000000
                                                   012B91E48
kcvcrv+3585          CALL???  kctrec+1910          012B92C58 000000000 00726DF00
                                                   00726BDB0
kcfopd+1007          CALL???  kcvcrv+3585          012B93350 000000000 000000000
                                                   000000000
adbdrv+55820         CALL???  kcfopd+1007          000000000 000000000 000000000
                                                   000000000
opiexe+13897         CALL???  adbdrv+55820         000000023 000000003 000000102
                                                   000000000
opiosq0+3558         CALL???  opiexe+13897         000000004 000000000 012B9B238
                                                   4155474E414C5F45
kpooprx+339          CALL???  opiosq0+3558         000000003 00000000E 012B9B3C8
                                                   0000000A4
kpoal8+894           CALL???  kpooprx+339          015587550 000000018 0041AE700
                                                   000000001
opiodr+1136          CALL???  kpoal8+894           00000005E 000000017 012B9E868
                                                   0072F5100
ttcpip+5146          CALL???  opiodr+1136          00000005E 000000017 012B9E868
                                                   2D8C00000000
opitsk+1818          CALL???  ttcpip+5146          015587550 000000000 000000000
                                                   000000000
opiino+1129          CALL???  opitsk+1818          00000001E 000000000 000000000
                                                   000000000
opiodr+1136          CALL???  opiino+1129          00000003C 000000004 012B9FB20
                                                   000000000
opidrv+815           CALL???  opiodr+1136          00000003C 000000004 012B9FB20
                                                   000000000
sou2o+52             CALL???  opidrv+815           00000003C 000000004 012B9FB20
                                                   7FF7FC48580
opimai_real+131      CALL???  sou2o+52             000000000 012B9FC40
                                                   7FFFFF7F258 077EF4D1C
opimai+96            CALL???  opimai_real+131      7FF7FC48580 7FFFFF7E000
                                                   0001F0003 000000000
OracleThreadStart+6  CALL???  opimai+96            012B9FEF0 01289FF3C 012B9FCC0
40                                                 7FF7FC48580
0000000077D6B6DA     CALL???  OracleThreadStart+6  01289FF3C 000000000 000000000
                              40                   012B9FFA8

官方描述
The assert ORA-600: [kcrfr_update_nab_2] is a direct result of a lost write in the current on line log that we are attempting to resolve.So, this confirms the theory that this is a OS/hardware lost write issue not an internal oracle bug. In fact the assert ORA-600: [kcrfr_update_nab_2] is how we detect a lost log write.
Bug 5692594
Hdr: 5692594 10.2.0.1 RDBMS 10.2.0.1 RECOVERY PRODID-5 PORTID-226 ORA-600
Abstract: AFTER DATABASE CRASHED DOESN’T OPEN ORA-600 [KCRFR_UPDATE_NAB_2]
Status: 95,Closed, Vendor OS Problem

Bug 6655116
Hdr: 6655116 10.2.0.3 RDBMS 10.2.0.3 RECOVERY PRODID-5 PORTID-23
Abstract: INSTANCES CRASH WITH ORA-600 [KCRFR_UPDATE_NAB_2] AFTER DISK FAILURE
根据官方的描述,结合故障情况,基本上可以确定是由于硬件异常导致Oracle写丢失,从而除非oracle相关bug导致数据库无法正常启动

ORA-600 [kcrfr_update_nab_2] [a] [b]


VERSIONS:
versions 10.2 to 11.1

DESCRIPTION:

Failure of upgrade of recovery node (RN) enqueue to SSX mode

ARGUMENTS:
Arg [a] State Object for redo nab enqueue for resilvering
Arg [b] Redo nab enqueue mode

FUNCTIONALITY:
Kernel Cache Redo File Read

IMPACT:

INSTANCE FAILURE

处理方法
1.如果有备份,利用备份进行不完全恢复,跳过最后异常的redo,数据库resetlogs打开
2.如果没有备份,尝试使用历史的控制文件进行不完全恢复,或者直接跳过数据库一致性打开库.
3.互联网有人解决删除redo第二组成员数据库open成功(http://blog.itpub.net/16976507/viewspace-1266952/)

发表在 ORA-xxxxx, Oracle备份恢复 | 标签为 kcrfr_update_nab_2, ORA-600 kcrfr_update_nab_2 | 评论关闭

存储精简卷导致asm磁盘组异常

发表于 2016 年 10 月 24 日由惜分飞

有朋友在一个存储空间给asm使用，发生空间不足，然后使用另外一个存储中的lun给asm的data磁盘组增加asm disk,运行了大概1天之后,asm磁盘组直接dismount,数据库crash.然后就无法正常mount.包括这个存储上的几个其他磁盘组也无法正常mount.
数据库异常日志

Sun Oct 23 08:43:59 2016
SUCCESS: diskgroup DATA was dismounted
SUCCESS: diskgroup DATA was dismounted
Sun Oct 23 08:44:00 2016
Errors in file /oracle/app/oracle/diag/rdbms/orcl/orcl1/trace/orcl1_lmon_79128.trc:
ORA-00202: control file: '+DATA/orcl/controlfile/current.278.892363163'
ORA-15078: ASM diskgroup was forcibly dismounted
Sun Oct 23 08:44:00 2016
Errors in file /oracle/app/oracle/diag/rdbms/orcl/orcl1/trace/orcl1_lgwr_79174.trc:
ORA-00345: redo log write error block 15924 count 2
ORA-00312: online log 2 thread 1: '+DATA/orcl/onlinelog/group_2.274.892363167'
ORA-15078: ASM diskgroup was forcibly dismounted
ORA-15078: ASM diskgroup was forcibly dismounted
Errors in file /oracle/app/oracle/diag/rdbms/orcl/orcl1/trace/orcl1_lgwr_79174.trc:
ORA-00202: control file: '+DATA/orcl/controlfile/current.278.892363163'
ORA-15078: ASM diskgroup was forcibly dismounted
Errors in file /oracle/app/oracle/diag/rdbms/orcl/orcl1/trace/orcl1_lgwr_79174.trc:
ORA-00204: error in reading (block 1, # blocks 1) of control file
ORA-00202: control file: '+DATA/orcl/controlfile/current.278.892363163'
ORA-15078: ASM diskgroup was forcibly dismounted
Sun Oct 23 08:44:00 2016
LGWR (ospid: 79174): terminating the instance due to error 204
Sun Oct 23 08:44:00 2016
opiodr aborting process unknown ospid (79742) as a result of ORA-1092
Sun Oct 23 08:44:01 2016
ORA-1092 : opitsk aborting process
Sun Oct 23 08:44:01 2016
ORA-1092 : opitsk aborting process
System state dump requested by (instance=1, osid=79174 (LGWR)), summary=[abnormal instance termination].
System State dumped to trace file /oracle/app/oracle/diag/rdbms/orcl/orcl1/trace/orcl1_diag_79118.trc
Instance terminated by LGWR, pid = 79174

很明显，数据库异常是由于asm diskgroup dismount,因此分析asm 日志

asm 日志

Sun Oct 23 07:00:31 2016
Time drift detected. Please check VKTM trace file for more details.
Sun Oct 23 08:43:55 2016
Errors in file /oracle/app/oracle/diag/asm/+asm/+ASM1/trace/+ASM1_arb0_8755.trc:
ORA-27061: waiting for async I/Os failed
Linux-x86_64 Error: 5: Input/output error
Additional information: -1
Additional information: 1048576
WARNING: Write Failed. group:1 disk:2 AU:1222738 offset:0 size:1048576
ERROR: failed to copy file +DATA.524, extent 15030
ERROR: ORA-15080 thrown in ARB0 for group number 1
Errors in file /oracle/app/oracle/diag/asm/+asm/+ASM1/trace/+ASM1_arb0_8755.trc:
ORA-15080: synchronous I/O operation to a disk failed
Sun Oct 23 08:43:55 2016
NOTE: stopping process ARB0
NOTE: rebalance interrupted for group 1/0xec689cdd (DATA)
NOTE: ASM did background COD recovery for group 1/0xec689cdd (DATA)
NOTE: starting rebalance of group 1/0xec689cdd (DATA) at power 1
Starting background process ARB0
Sun Oct 23 08:43:56 2016
ARB0 started with pid=24, OS id=103554 
NOTE: assigning ARB0 to group 1/0xec689cdd (DATA) with 1 parallel I/O
Errors in file /oracle/app/oracle/diag/asm/+asm/+ASM1/trace/+ASM1_arb0_103554.trc:
ORA-27061: waiting for async I/Os failed
Linux-x86_64 Error: 5: Input/output error
Additional information: -1
Additional information: 1048576
WARNING: Write Failed. group:1 disk:2 AU:1222738 offset:0 size:1048576
ERROR: failed to copy file +DATA.256, extent 6570
ERROR: ORA-15080 thrown in ARB0 for group number 1
Errors in file /oracle/app/oracle/diag/asm/+asm/+ASM1/trace/+ASM1_arb0_103554.trc:
ORA-15080: synchronous I/O operation to a disk failed
NOTE: stopping process ARB0
Sun Oct 23 08:43:58 2016
Errors in file /oracle/app/oracle/diag/asm/+asm/+ASM1/trace/+ASM1_dbw0_8521.trc:
ORA-27061: waiting for async I/Os failed
Linux-x86_64 Error: 5: Input/output error
Additional information: -1
Additional information: 4096
WARNING: Write Failed. group:1 disk:3 AU:6789 offset:24576 size:4096
NOTE: cache initiating offline of disk 3 group DATA
NOTE: process _dbw0_+asm1 (8521) initiating offline of disk 3.3915934787 (DATA_0003) with mask 0x7e in group 1
Sun Oct 23 08:43:58 2016
WARNING: Disk 3 (DATA_0003) in group 1 mode 0x7f is now being offlined
WARNING: Disk 3 (DATA_0003) in group 1 in mode 0x7f is now being taken offline on ASM inst 1
NOTE: initiating PST update: grp = 1, dsk = 3/0xe9686c43, mask = 0x6a, op = clear
GMON updating disk modes for group 1 at 14 for pid 14, osid 8521
ERROR: Disk 3 cannot be offlined, since diskgroup has external redundancy.
ERROR: too many offline disks in PST (grp 1)
Sun Oct 23 08:43:58 2016
NOTE: cache dismounting (not clean) group 1/0xEC689CDD (DATA) 
NOTE: messaging CKPT to quiesce pins Unix process pid: 103577, image: oracle@node1 (B000)
WARNING: Disk 3 (DATA_0003) in group 1 mode 0x7f offline is being aborted
WARNING: Offline of disk 3 (DATA_0003) in group 1 and mode 0x7f failed on ASM inst 1
NOTE: halting all I/Os to diskgroup 1 (DATA)
Sun Oct 23 08:43:59 2016
NOTE: LGWR doing non-clean dismount of group 1 (DATA)
NOTE: LGWR sync ABA=160.10145 last written ABA 160.10145

错误信息很明显，由于Write Failed导致asm diskgroup dismount.

系统日志

Oct 23 08:43:55 node1 kernel: sd 6:0:12:1: [sdd]  Result: hostbyte=DID_OK driverbyte=DRIVER_SENSE
Oct 23 08:43:55 node1 kernel: sd 6:0:12:1: [sdd]  Sense Key : Data Protect [current] 
Oct 23 08:43:55 node1 kernel: sd 6:0:12:1: [sdd]  Add. Sense: Space allocation failed write protect
Oct 23 08:43:55 node1 kernel: sd 6:0:12:1: [sdd] CDB: Write(16): 8a 00 00 00 00 02 e7 18 37 f9 00 00 00 07 00 00
Oct 23 08:43:55 node1 kernel: end_request: critical space allocation error, dev sdd, sector 12467058681
Oct 23 08:43:55 node1 kernel: end_request: critical space allocation error, dev dm-3, sector 12467058681
Oct 23 08:43:55 node1 kernel: sd 8:0:6:1: [sdh]  Result: hostbyte=DID_OK driverbyte=DRIVER_SENSE
Oct 23 08:43:55 node1 kernel: sd 8:0:6:1: [sdh]  Sense Key : Data Protect [current] 
Oct 23 08:43:55 node1 kernel: sd 8:0:6:1: [sdh]  Add. Sense: Space allocation failed write protect
Oct 23 08:43:55 node1 kernel: sd 8:0:6:1: [sdh] CDB: Write(16): 8a 00 00 00 00 02 e7 18
Oct 23 08:43:55 node1 kernel: sd 6:0:4:1: [sdb]  Result: hostbyte=DID_OK driverbyte=DRIVER_SENSE
Oct 23 08:43:55 node1 kernel: sd 6:0:4:1: [sdb]  Sense Key : Data Protect [current] 
Oct 23 08:43:55 node1 kernel: sd 6:0:4:1: [sdb]   33Add. Sense: Space allocation failed write protect
Oct 23 08:43:55 node1 kernel: sd 6:0:4:1: [sdb] CDB: Write(16): 8a 00 00 00 00 02 e7 18 30 00 00 00 03 f9 00 00
Oct 23 08:43:55 node1 kernel: end_request: critical space allocation error, dev sdb, sector 12467056640
Oct 23 08:43:55 node1 kernel: f9 00 00 04 00
Oct 23 08:43:55 node1 kernel: end_request: critical space allocation error, dev dm-3, sector 12467056640
Oct 23 08:43:55 node1 kernel: 00 00
Oct 23 08:43:55 node1 kernel: end_request: critical space allocation error, dev sdh, sector 12467057657
Oct 23 08:43:55 node1 kernel: end_request: critical space allocation error, dev dm-3, sector 12467057657
Oct 23 08:43:57 node1 kernel: sd 8:0:6:1: [sdh]  Result: hostbyte=DID_OK driverbyte=DRIVER_SENSE
Oct 23 08:43:57 node1 kernel: sd 8:0:6:1: [sdh]  Sense Key : Data Protect [current] 
Oct 23 08:43:57 node1 kernel: sd 8:0:6:1: [sdh]  Add. Sense: Space allocation failed write protect
Oct 23 08:43:57 node1 kernel: sd 8:0:6:1: [sdh] CDB: Write(16): 8a 00 00 00 00 02 e7 18 37 f9 00 00 00 07 00 00
Oct 23 08:43:57 node1 kernel: end_request: critical space allocation error, dev sdh, sector 12467058681
Oct 23 08:43:57 node1 kernel: end_request: critical space allocation error, dev dm-3, sector 12467058681
Oct 23 08:43:57 node1 kernel: sd 8:0:12:1: [sdj]  Result: hostbyte=DID_OK driverbyte=DRIVER_SENSE
Oct 23 08:43:57 node1 kernel: sd 8:0:12:1: [sdj]  Sense Key : Data Protect [current] 
Oct 23 08:43:57 node1 kernel: sd 8:0:12:1: [sdj]  Add. Sense: Space allocation failed write protect
Oct 23 08:43:57 node1 kernel: sd 8:0:12:1: [sdj] CDB: Write(16): 8a 00 00 00 00 02 e7 18 30 00 00 00 03 f9 00 00
Oct 23 08:43:57 node1 kernel: end_request: critical space allocation error, dev sdj, sector 12467056640
Oct 23 08:43:57 node1 kernel: end_request: critical space allocation error, dev dm-3, sector 12467056640
Oct 23 08:43:57 node1 kernel: sd 6:0:4:1: [sdb]  Result: hostbyte=DID_OK driverbyte=DRIVER_SENSE
Oct 23 08:43:57 node1 kernel: sd 6:0:4:1: [sdb]  Sense Key : Data Protect [current] 
Oct 23 08:43:57 node1 kernel: sd 6:0:4:1: [sdb]  Add. Sense: Space allocation failed write protect
Oct 23 08:43:57 node1 kernel: sd 6:0:4:1: [sdb] CDB: Write(16): 8a 00 00 00 00 02 e7 18 33 f9 00 00 04 00 00 00
Oct 23 08:43:58 node1 kernel: sd 6:0:4:1: [sdb]  Result: hostbyte=DID_OK driverbyte=DRIVER_SENSE
Oct 23 08:43:58 node1 kernel: sd 6:0:4:1: [sdb]  Sense Key : Data Protect [current] 
Oct 23 08:43:58 node1 kernel: sd 6:0:4:1: [sdb]  Add. Sense: Space allocation failed write protect
Oct 23 08:43:58 node1 kernel: sd 6:0:4:1: [sdb] CDB: Write(16): 8a 00 00 00 00 03 3b 7e 78 30 00 00 00 08 00 00
Oct 23 10:50:59 node1 init: oracle-ohasd main process (6150) killed by TERM signal

错误信息为:critical space allocation error,严重空间分配错误.也就是linux在分配空间之时发生错误.在换而言之,由于分配空间错误导致asm 磁盘组dismount.

查看多路径信息

[root@node1 ~]# multipath -ll
36000d31003190c000000000000000003 dm-3 COMPELNT,Compellent Vol
size=80T features='1 queue_if_no_path' hwhandler='0' wp=rw
`-+- policy='round-robin 0' prio=1 status=active
  |- 6:0:9:1  sdd 8:48  active ready running
  `- 8:0:9:1  sdi 8:128 active ready running
delldisk2 (36000d310031908000000000000000003) dm-4 COMPELNT,Compellent Vol
size=8.0T features='1 queue_if_no_path' hwhandler='0' wp=rw
`-+- policy='round-robin 0' prio=1 status=active
  |- 6:0:12:1 sde 8:64  active ready running
  |- 8:0:6:1  sdh 8:112 active ready running
  |- 6:0:4:1  sdb 8:16  active ready running
  `- 8:0:12:1 sdj 8:144 active ready running
delldisk1 (36000d31003190a000000000000000007) dm-2 COMPELNT,Compellent Vol
size=12T features='1 queue_if_no_path' hwhandler='0' wp=rw
`-+- policy='round-robin 0' prio=1 status=active
  |- 6:0:1:1  sda 8:0   active ready running
  |- 8:0:2:1  sdf 8:80  active ready running
  |- 6:0:7:1  sdc 8:32  active ready running
  `- 8:0:3:1  sdg 8:96  active ready running

很明显报错的都是同一个lun(delldisk2),也就是存储空间使用完的存储.也就是说,由于delldisk2存储的空间使用尽了导致系统出现分配空间错误,从而导致asm 写失败,进而导致数据库异常.这种问题的本质其实就是存储给系统分配了8T,但是实际存储可以使用的空间不足8T,而os按照8T来使用从而出现该问题.专业名字叫做”存储精简卷”.因此各位在存储配置之时需要注意该问题.因为这种情况的出现一般只是写io异常,读依旧正常,因此不会丢失数据.

发表在 Oracle备份恢复 | 标签为 critical space allocation error, ORA-00345, ORA-15078, ORA-15080, ORA-27061 | 评论关闭

17813235971

QQ 咨询

分类目录归档：Oracle备份恢复

File #N is offline, but is part of an online tablespace

ORA-600 kcrfr_update_nab_2 故障恢复

存储精简卷导致asm磁盘组异常

文章分类

最近发表

分类目录归档：Oracle备份恢复

File #N is offline, but is part of an online tablespace

ORA-600 kcrfr_update_nab_2 故障恢复

存储精简卷导致asm磁盘组异常

标签云

文章分类

最近发表