Product Oracle Server – Enterprise Edition
Product Version – 11.2.0.2
Operating System – Oracle Solaris on x86-64 (64-bit) OS Version- 10
Problem Description – Database not able to come in READ WRITE Mode
ORA-00333: redo log read error block 3656 count 7994
==========ALERT LOGS ===================================
Sat Nov 03 05:00:03 2012
Thread 1 advanced to log sequence 2032 (LGWR switch)
Current log# 1 seq# 2032 mem# 0: /u01/home/oracle/u01/app/oracle/oradata/orcl/redo01.log
Sat Nov 03 05:00:03 2012
Archived Log entry 2025 added for thread 1 sequence 2031 ID 0x4fa0c79f dest 1:
Sat Nov 03 05:00:04 2012
LOGMINER: End mining logfile for session 1 thread 1 sequence 2031, /u01/home/oracle/u01/app/oracle/oradata/orcl/redo03.log
LOGMINER: Begin mining logfile for session 1 thread 1 sequence 2032, /u01/home/oracle/u01/app/oracle/oradata/orcl/redo01.log
Sat Nov 03 08:36:25 2012
Starting ORACLE instance (normal)
LICENSE_MAX_SESSION = 0
LICENSE_SESSIONS_WARNING = 0
Picked latch-free SCN scheme 3
Autotune of undo retention is turned on.
IMODE=BR
ILAT =60
LICENSE_MAX_USERS = 0
SYS auditing is disabled
Starting up:
Oracle Database 11g Enterprise Edition Release 11.2.0.2.0 - 64bit Production
With the Partitioning, OLAP, Data Mining and Real Application Testing options.
Using parameter settings in server-side spfile /u01/home/oracle/u01/app/oracle/product/11.2.0/db_1/dbs/spfileorcl.ora
System parameters with non-default values:
processes = 1000
memory_target = 6560M
control_files = "/u01/home/oracle/u01/app/oracle/oradata/orcl/control01.ctl"
control_files = "/u01/home/oracle/u01/app/oracle/fast_recovery_area/orcl/control02.ctl"
db_block_size = 8192
compatible = "11.2.0.0.0"
log_archive_dest_1 = "location=/backup/oraarch"
log_archive_format = "arch_%t_%s_%r.arc"
db_recovery_file_dest = "/u01/home/oracle/u01/app/oracle/fast_recovery_area"
db_recovery_file_dest_size= 4062M
transactions = 600
undo_tablespace = "UNDOTBS1"
sec_case_sensitive_logon = FALSE
remote_login_passwordfile= "EXCLUSIVE"
db_domain = ""
global_names = TRUE
dispatchers = "(PROTOCOL=TCP) (SERVICE=orclXDB)"
audit_file_dest = "/u01/home/oracle/u01/app/oracle/admin/orcl/adump"
audit_trail = "DB"
db_name = "orcl"
open_cursors = 800
diagnostic_dest = "/u01/home/oracle/u01/app/oracle"
Sat Nov 03 08:36:30 2012
PMON started with pid=2, OS id=1349
Sat Nov 03 08:36:30 2012
PSP0 started with pid=3, OS id=1351
Sat Nov 03 08:36:32 2012
VKTM started with pid=4, OS id=1353 at elevated priority
VKTM running at (10)millisec precision with DBRM quantum (100)ms
Sat Nov 03 08:36:32 2012
GEN0 started with pid=5, OS id=1357
Sat Nov 03 08:36:32 2012
DIAG started with pid=6, OS id=1359
Sat Nov 03 08:36:32 2012
DBRM started with pid=7, OS id=1361
Sat Nov 03 08:36:32 2012
DIA0 started with pid=8, OS id=1363
Sat Nov 03 08:36:32 2012
MMAN started with pid=9, OS id=1365
Sat Nov 03 08:36:32 2012
DBW0 started with pid=10, OS id=1367
Sat Nov 03 08:36:32 2012
LGWR started with pid=11, OS id=1369
Sat Nov 03 08:36:32 2012
CKPT started with pid=12, OS id=1371
Sat Nov 03 08:36:32 2012
SMON started with pid=13, OS id=1373
Sat Nov 03 08:36:32 2012
RECO started with pid=14, OS id=1375
Sat Nov 03 08:36:32 2012
MMON started with pid=15, OS id=1377
starting up 1 dispatcher(s) for network address '(ADDRESS=(PARTIAL=YES)(PROTOCOL=TCP))'...
Sat Nov 03 08:36:32 2012
MMNL started with pid=16, OS id=1379
starting up 1 shared server(s) ...
DISM started, OS id=1385
ORACLE_BASE from environment = /u01/home/oracle/u01/app/oracle
Sat Nov 03 08:36:36 2012
ALTER DATABASE MOUNT
Successful mount of redo thread 1, with mount id 1356888724
Database mounted in Exclusive Mode
Lost write protection disabled
Completed: ALTER DATABASE MOUNT
Sat Nov 03 08:36:41 2012
ALTER DATABASE OPEN
Beginning crash recovery of 1 threads
parallel recovery started with 7 processes
Started redo scan
Aborting crash recovery due to error 333
Errors in file /u01/home/oracle/u01/app/oracle/diag/rdbms/orcl/orcl/trace/orcl_ora_1391.trc:
ORA-00333: redo log read error block 3656 count 7994
Errors in file /u01/home/oracle/u01/app/oracle/diag/rdbms/orcl/orcl/trace/orcl_ora_1391.trc:
ORA-00333: redo log read error block 3656 count 7994
ORA-333 signalled during: ALTER DATABASE OPEN...
Sat Nov 03 08:48:29 2012
db_recovery_file_dest_size of 4062 MB is 0.00% used. This is a
user-specified limit on the amount of space that will be used by this
database for recovery-related files, and does not reflect the amount of
space available in the underlying filesystem or ASM diskgroup.
Mon Nov 05 12:07:21 2012
ARCH: STARTING ARCH PROCESSES
Mon Nov 05 12:07:21 2012
ARC0 started with pid=22, OS id=12211
ARC0: Archival started
ARCH: STARTING ARCH PROCESSES COMPLETE
ARC0: STARTING ARCH PROCESSES
Mon Nov 05 12:07:22 2012
ARC1 started with pid=23, OS id=12225
Mon Nov 05 12:07:22 2012
ARC2 started with pid=24, OS id=12227
Mon Nov 05 12:07:22 2012
ARC3 started with pid=25, OS id=12229
ARC1: Archival started
ARC2: Archival started
ARC1: Becoming the 'no FAL' ARCH
ARC1: Becoming the 'no SRL' ARCH
ARC2: Becoming the heartbeat ARCH
ARC3: Archival started
ARC0: STARTING ARCH PROCESSES COMPLETE
Mon Nov 05 14:32:20 2012
=========================================================================================================
-v$datafile_header- SQL> SELECT status, checkpoint_change#, TO_CHAR(checkpoint_time, 'DD-MM-YYYY HH24:MI:SS') as checkpoint_time, count(*) FROM v$datafile_header GROUP BY status, checkpoint_change#, checkpoint_time ORDER BY status, checkpoint_change#, checkpoint_time; 2 3 4 5 6 7 STATUS CHECKPOINT_CHANGE# CHECKPOINT_TIME COUNT(*) ------- ------------------ ------------------- ---------------- ONLINE 35135011 03-11-2012 05:00:03 9
-v$archived_log-
SQL> SELECT recid, 2 thread#, 3 sequence#, 4 name, tO_CHAR(first_change#, '999999999999999') as first_change#, 5 6 to_char(NEXT_CHANGE#, '999999999999999') as next_change# , 7 archived, 8 deleted, 9 TO_CHAR(completion_time, 'DD-MM-YYYY HH24:MI:SS') as completed, 10 status 11 FROM v$archived_log; RECID THREAD# SEQUENCE# NAME FIRST_CHANGE# NEXT_CHANGE# ARC DEL COMPLETED S 2025 1 2031 /backup/oraarch/arch_1_2031_777416481.arc 35109311 35135011 YES NO 03-11-2012 05:00:03 A
v$recover_file
SQL> SELECT * FROM v$recover_file 2 3 ; FILE# ONLINE ONLINE_ ERROR CHANGE# TIME ---------------- ------- ------- ----------------------------------------------------------------- 1 ONLINE ONLINE 35135011 03-11-2012 05:00:03 2 ONLINE ONLINE 35135011 03-11-2012 05:00:03 3 ONLINE ONLINE 35135011 03-11-2012 05:00:03 4 ONLINE ONLINE 35135011 03-11-2012 05:00:03 5 ONLINE ONLINE 35135011 03-11-2012 05:00:03 6 ONLINE ONLINE 35135011 03-11-2012 05:00:03 7 ONLINE ONLINE 35135011 03-11-2012 05:00:03 8 ONLINE ONLINE 35135011 03-11-2012 05:00:03 9 ONLINE ONLINE 35135011 03-11-2012 05:00:03
v$datafile
SQL> SELECT name, 2 file#, 3 status, 4 enabled, 5 creation_change#, 6 TO_CHAR(creation_time, 'DD-MM-YYYY HH24:MI:SS') as creation_time, 7 TO_CHAR(checkpoint_change#, '999999999999999') as checkpoint_change#, 8 TO_CHAR(checkpoint_time, 'DD-MM-YYYY HH24:MI:SS') as checkpoint_time, 9 TO_CHAR(offline_change#, '999999999999999') as offline_change#, 10 TO_CHAR(online_change#, '999999999999999') as online_change#, 11 TO_CHAR(online_time, 'DD-MM-YYYY HH24:MI:SS') as online_time, 12 TO_CHAR(bytes, '9,999,999,999,990') as bytes 13 FROM v$datafile 14 ORDER BY checkpoint_change#; NAME FILE# STATUS ENABLED CREATION_CHANGE# CREATION_TIME CHECKPOINT_CHANG CHECKPOINT_TIME OFFLINE_CHANGE# ONLINE_CHANGE# ONLINE_TIME BYTES -------------------------------------------------- ---------------- ------- ---------- ---------------- ------------------- ---------------- ------------------- ---------------- ---------------- ------------------- ------------------ /u01/home/oracle/u01/app/oracle/oradata/orcl/syst 1 SYSTEM READ WRITE 13 11-09-2010 06:33:30 35135011 03-11-2012 05:00:03 908013 908014 08-03-2012 21:01:21 891,289,600 em01.dbf /u01/home/oracle/u01/app/oracle/oradata/orcl/sysa 2 ONLINE READ WRITE 2086 11-09-2010 06:33:58 35135011 03-11-2012 05:00:03 908013 908014 08-03-2012 21:01:21 964,689,920 ux01.dbf /u01/home/oracle/u01/app/oracle/oradata/orcl/undo 3 ONLINE READ WRITE 905473 11-09-2010 07:50:33 35135011 03-11-2012 05:00:03 908013 908014 08-03-2012 21:01:21 110,100,480 tbs01.dbf /u01/home/oracle/u01/app/oracle/oradata/orcl/user 4 ONLINE READ WRITE 17595 11-09-2010 06:35:16 35135011 03-11-2012 05:00:03 908013 908014 08-03-2012 21:01:21 5,242,880 s01.dbf /u01/home/oracle/u01/app/oracle/oradata/orcl/stre 9 ONLINE READ WRITE 1828075 19-03-2012 13:16:23 35135011 03-11-2012 05:00:03 0 0 374,865,920 ams_tbs.dbf /u01/home/oracle/u01/app/oracle/oradata/orcl/elit 6 ONLINE READ WRITE 1315794 12-03-2012 19:56:29 35135011 03-11-2012 05:00:03 0 0 104,857,600 eaaa62.dbf /u01/home/oracle/u01/app/oracle/oradata/orcl/elit 7 ONLINE READ WRITE 1696162 18-03-2012 00:41:26 35135011 03-11-2012 05:00:03 0 0 104,857,600 eaaasync.dbf /u01/home/oracle/u01/app/oracle/oradata/orcl/peli 8 ONLINE READ WRITE 1700589 18-03-2012 01:18:32 35135011 03-11-2012 05:00:03 0 0 104,857,600 teaaa.dbf /u01/home/oracle/u01/app/oracle/oradata/orcl/exam 5 ONLINE READ WRITE 938011 08-03-2012 21:01:49 35135011 03-11-2012 05:00:03 938011 938016 08-03-2012 21:01:49 348,651,520 ple01.dbf
v$archived_log and v$log
SQL> SELECT a.recid, 2 a.thread#, 3 a.sequence#, 4 a.name, 5 tO_CHAR(a.first_change#, '999999999999999') as first_change#, 6 to_char(a.NEXT_CHANGE#, '999999999999999') as next_change# , 7 a.archived, 8 a.deleted, 9 TO_CHAR(a.completion_time, 'DD-MM-YYYY HH24:MI:SS') as completed 10 FROM v$archived_log a, v$log l 11 WHERE a.thread# = l.thread# 12 AND a.sequence# = l.sequence#; RECID THREAD# SEQUENCE# NAME FIRST_CHANGE# NEXT_CHANGE# ARC DEL COMPLETED ---------------- ---------------- ---------------- 2024 1 2030 35099904 35109311 YES YES 02-11-2012 23:24:23 2025 1 2031 /backup/oraarch/arch_1_2031_777416481.arc 35109311 35135011 YES NO 03-11-2012 05:00:03
v$datafile_header
SQL> SELECT name, file#, status, error, creation_change#, TO_CHAR(creation_time, 'DD-MM-YYYY HH24:MI:SS') as creation_time, TO_CHAR(checkpoint_change#, '999999999999999') as checkpoint_change#, TO_CHAR(checkpoint_time, 'DD-MM-YYYY HH24:MI:SS') as checkpoint_time, TO_CHAR(resetlogs_change#, '999999999999999') as resetlogs_change#, TO_CHAR(resetlogs_time, 'DD-MM-YYYY HH24:MI:SS') as resetlogs_time, TO_CHAR(bytes, '9,999,999,999,990') as bytes FROM v$datafile_header ORDER BY checkpoint_change#; NAME FILE# STATUS ERROR CREATION_CHANGE# CREATION_TIME CHECKPOINT_CHANG CHECKPOINT_TIME RESETLOGS_CHANGE RESETLOGS_TIME BYTES -------------------------------------------------- ---------------- ------- ----------------------------------------------------------------- ---------------- ------------------- ---------------- ------------------- ---------------- ------------------- ------------------ /u01/home/oracle/u01/app/oracle/oradata/orcl/syst 1 ONLINE 13 11-09-2010 06:33:30 35135011 03-11-2012 05:00:03 908014 08-03-2012 21:01:21 891,289,600 em01.dbf /u01/home/oracle/u01/app/oracle/oradata/orcl/sysa 2 ONLINE 2086 11-09-2010 06:33:58 35135011 03-11-2012 05:00:03 908014 08-03-2012 21:01:21 964,689,920 ux01.dbf /u01/home/oracle/u01/app/oracle/oradata/orcl/undo 3 ONLINE 905473 11-09-2010 07:50:33 35135011 03-11-2012 05:00:03 908014 08-03-2012 21:01:21 110,100,480 tbs01.dbf /u01/home/oracle/u01/app/oracle/oradata/orcl/user 4 ONLINE 17595 11-09-2010 06:35:16 35135011 03-11-2012 05:00:03 908014 08-03-2012 21:01:21 5,242,880 s01.dbf /u01/home/oracle/u01/app/oracle/oradata/orcl/stre 9 ONLINE 1828075 19-03-2012 13:16:23 35135011 03-11-2012 05:00:03 908014 08-03-2012 21:01:21 374,865,920 ams_tbs.dbf /u01/home/oracle/u01/app/oracle/oradata/orcl/elit 6 ONLINE 1315794 12-03-2012 19:56:29 35135011 03-11-2012 05:00:03 908014 08-03-2012 21:01:21 104,857,600 eaaa62.dbf /u01/home/oracle/u01/app/oracle/oradata/orcl/elit 7 ONLINE 1696162 18-03-2012 00:41:26 35135011 03-11-2012 05:00:03 908014 08-03-2012 21:01:21 104,857,600 eaaasync.dbf /u01/home/oracle/u01/app/oracle/oradata/orcl/peli 8 ONLINE 1700589 18-03-2012 01:18:32 35135011 03-11-2012 05:00:03 908014 08-03-2012 21:01:21 104,857,600 teaaa.dbf /u01/home/oracle/u01/app/oracle/oradata/orcl/exam 5 ONLINE 938011 08-03-2012 21:01:49 35135011 03-11-2012 05:00:03 908014 08-03-2012 21:01:21 348,651,520 ple01.dbf
Solution
Action Plan-1
RMAN> run
{
allocate channel c1 device type disk;
restore database;
recover database;
alter database open;
};
using target database control file instead of recovery catalog
allocated channel: c1
channel c1: SID=958 device type=DISK
Starting restore at 05-NOV-12
skipping datafile 1; already restored to file /u01/home/oracle/u01/app/oracle/oradata/orcl/system01.dbf
skipping datafile 2; already restored to file /u01/home/oracle/u01/app/oracle/oradata/orcl/sysaux01.dbf
skipping datafile 3; already restored to file /u01/home/oracle/u01/app/oracle/oradata/orcl/undotbs01.dbf
skipping datafile 4; already restored to file /u01/home/oracle/u01/app/oracle/oradata/orcl/users01.dbf
skipping datafile 5; already restored to file /u01/home/oracle/u01/app/oracle/oradata/orcl/example01.dbf
skipping datafile 6; already restored to file /u01/home/oracle/u01/app/oracle/oradata/orcl/eliteaaa62.dbf
skipping datafile 7; already restored to file /u01/home/oracle/u01/app/oracle/oradata/orcl/eliteaaasync.dbf
skipping datafile 8; already restored to file /u01/home/oracle/u01/app/oracle/oradata/orcl/peliteaaa.dbf
skipping datafile 9; already restored to file /u01/home/oracle/u01/app/oracle/oradata/orcl/streams_tbs.dbf
restore not done; all files read only, offline, or already restored
Finished restore at 05-NOV-12
Starting recover at 05-NOV-12
starting media recovery
media recovery failed
released channel: c1
RMAN-00571: ===========================================================
RMAN-00569: =============== ERROR MESSAGE STACK FOLLOWS ===============
RMAN-00571: ===========================================================
RMAN-03002: failure of recover command at 11/05/2012 20:24:12
ORA-00283: recovery session canceled due to errors
RMAN-11003: failure during parse/execution of SQL statement: alter database recover if needed
start
ORA-00283: recovery session canceled due to errors
ORA-00333: redo log read error block 3656 count 440
RMAN-00571: ===========================================================
RMAN-00569: =============== ERROR MESSAGE STACK FOLLOWS ===============
RMAN-00571: ===========================================================
RMAN-00558: error encountered while parsing input commands
RMAN-01009: syntax error: found ";": expecting one of: "advise, allocate, alter, backup, @, catalog, change, configure, connect, convert, copy, create, crosscheck, delete, drop, duplicate, exit, flashback, grant, host, import, list, mount, open, print, quit, recover, register, release, repair, replace, report, reset, restore, resync, revoke, run, send, set, show, shutdown, spool, sql, startup, switch, transport, unregister, upgrade, validate, {, "
RMAN-01007: at line 0 column 2 file: standard input
RMAN>
Action Plan-2
bash-3.2$ echo $ORACLE_SID orcl -bash-3.2$ rman target / Recovery Manager: Release 11.2.0.2.0 - Production on Mon Nov 5 21:37:03 2012 Copyright (c) 1982, 2009, Oracle and/or its affiliates. All rights reserved. connected to target database: orcl (DBID=1335942047, not open) RMAN> RMAN> recover database noredo; Starting recover at 05-NOV-12 using target database control file instead of recovery catalog allocated channel: ORA_DISK_1 channel ORA_DISK_1: SID=958 device type=DISK Finished recover at 05-NOV-12 RMAN> alter database open; RMAN-00571: =========================================================== RMAN-00569: =============== ERROR MESSAGE STACK FOLLOWS =============== RMAN-00571: =========================================================== RMAN-03002: failure of alter db command at 11/05/2012 21:37:41 ORA-01113: file 1 needs media recovery ORA-01110: data file 1: '/u01/home/oracle/u01/app/oracle/oradata/orcl/system01.dbf' RMAN>
Action Plan-3
-bash-3.2$ rman target /
Recovery Manager: Release 11.2.0.2.0 - Production on Mon Nov 5 21:58:58 2012
Copyright (c) 1982, 2009, Oracle and/or its affiliates. All rights reserved.
connected to target database: orcl (DBID=1335942047, not open)
RMAN> run
{
set until sequence 2031 thread 1;
restore database;
}2> 3> 4> 5>
executing command: SET until clause
Starting restore at 05-NOV-12
using target database control file instead of recovery catalog
allocated channel: ORA_DISK_1
channel ORA_DISK_1: SID=958 device type=DISK
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 /u01/home/oracle/u01/app/oracle/oradata/orcl/system01.dbf
channel ORA_DISK_1: restoring datafile 00002 to /u01/home/oracle/u01/app/oracle/oradata/orcl/sysaux01.dbf
channel ORA_DISK_1: restoring datafile 00003 to /u01/home/oracle/u01/app/oracle/oradata/orcl/undotbs01.dbf
channel ORA_DISK_1: restoring datafile 00004 to /u01/home/oracle/u01/app/oracle/oradata/orcl/users01.dbf
channel ORA_DISK_1: restoring datafile 00005 to /u01/home/oracle/u01/app/oracle/oradata/orcl/example01.dbf
channel ORA_DISK_1: restoring datafile 00006 to /u01/home/oracle/u01/app/oracle/oradata/orcl/eliteaaa62.dbf
channel ORA_DISK_1: restoring datafile 00007 to /u01/home/oracle/u01/app/oracle/oradata/orcl/eliteaaasync.dbf
channel ORA_DISK_1: restoring datafile 00008 to /u01/home/oracle/u01/app/oracle/oradata/orcl/peliteaaa.dbf
channel ORA_DISK_1: restoring datafile 00009 to /u01/home/oracle/u01/app/oracle/oradata/orcl/streams_tbs.dbf
channel ORA_DISK_1: reading from backup piece /backup/rmanbackups/orcl_DB_4fnovdmc_143_1.rman
channel ORA_DISK_1: piece handle=/backup/rmanbackups/orcl_DB_4fnovdmc_143_1.rman tag=TAG20121029T120635
channel ORA_DISK_1: restored backup piece 1
channel ORA_DISK_1: restore complete, elapsed time: 00:01:05
SQL> recover automatic database until cancel;
ORA-00279: change 34478813 generated at 10/29/2012 12:06:36 needed for thread 1
ORA-00289: suggestion : /backup/oraarch/arch_1_1990_777416481.arc
ORA-00280: change 34478813 for thread 1 is in sequence #1990
ORA-00278: log file '/backup/oraarch/arch_1_1990_777416481.arc' no longer
needed for this recovery
ORA-00308: cannot open archived log '/backup/oraarch/arch_1_1990_777416481.arc'
ORA-27037: unable to obtain file status
Solaris-AMD64 Error: 2: No such file or directory
Additional information: 3
Specify log: {=suggested | filename | AUTO | CANCEL}
CANCEL
Media recovery cancelled.
SQL> alter database open resetlogs;
Database altered.
SQL> select open_mode from v$database;
OPEN_MODE
--------------------
READ WRITE
RCA
the current sequence needed to clear the fussiness should apply the changes in the online redo which is corrupted. GROUP# THREAD# SEQUENCE# MEMBERS ARC STATUS FIRST_CHANGE# ---------------- ---------------- ---------------- ---------------- --- ---------------- ---------------- 1 1 2032 1 NO CURRENT 35135011 <<<<<<<<<<<<<<< this is the corrupted redo 3 1 2031 1 YES INACTIVE 35109311 2 1 2030 1 YES INACTIVE 35099904