Oracle非归档模式Media Recovery错误之--ORA-26040

Oracle非归档模式Media Recovery错误之--ORA-26040

系统环境：

操作系统：Linux RH55

Oracle：  Oracle 11gR2

模拟案例：

1、查看数据库模式

18:12:36 SYS@ prod>archive log list;

Database log mode              No Archive Mode

Automatic archival             Disabled

Archive destination            /dsk4/arch1

Oldest online log sequence     1

Current log sequence           3

2、创建新的Tablespace

18:13:19 SYS@ prod>create tablespace tbs2 18:13:30   2  datafile '/u01/app/oracle/oradata/prod/tbs2.dbf' size 10m;Tablespace created.

3、对数据库进行冷备

[oracle@rh6 ~]$ rman target /Recovery Manager: Release 11.2.0.1.0 - Production on Thu Jul 24 18:14:30 2014Copyright (c) 1982, 2009, Oracle and/or its affiliates.  All rights reserved.connected to target database: PROD (DBID=239333010)RMAN> run {2> shutdown immediate;3> startup mount;4> backup database format '/dsk3/bak/%s_%d.bak';5> alter database open;6> }

4、备份完成在新的Tablesapce上创建Object

18:19:40 SYS@ prod>conn scott/tigerConnected.18:30:13 SCOTT@ prod>create table t1 tablespace tbs2 as select * from emp;Table created.Elapsed: 00:00:01.0018:30:45 SCOTT@ prod>select count(*) from t1;  COUNT(*)----------        14Elapsed: 00:00:00.0218:30:56 SCOTT@ prod>insert into t1 select * from t1 where rownum=1;1 row created.Elapsed: 00:00:00.0218:31:16 SCOTT@ prod>commit;Commit complete.Elapsed: 00:00:00.0418:31:18 SCOTT@ prod>insert into t1 select * from t1 where rownum=1;1 row created.Elapsed: 00:00:00.0118:31:23 SCOTT@ prod>select count(*) from t1;  COUNT(*)----------        16

5、查看Redo Log信息

18:32:14 SYS@ prod>select group#,sequence# ,status from v$log;    GROUP#  SEQUENCE# STATUS---------- ---------- ----------------         1          4 CURRENT         2          2 INACTIVE         3          3 INACTIVEElapsed: 00:00:00.05

6、模拟数据文件被破坏

[oracle@rh6 ~]$ rm /u01/app/oracle/oradata/prod/tbs2.dbf

18:32:28 SYS@ prod>shutdown abort

ORACLE instance shut down.

重新启动Instance到mount，查看redo log，日志没有发生switch

18:33:06 SYS@ prod>startup mount;ORACLE instance started.Total System Global Area  835104768 bytesFixed Size                  2217952 bytesVariable Size             775948320 bytesDatabase Buffers           54525952 bytesRedo Buffers                2412544 bytesDatabase mounted.18:33:42 SYS@ prod>select group#,sequence# ,status from v$log;    GROUP#  SEQUENCE# STATUS---------- ---------- ----------------         1          4 CURRENT         3          3 INACTIVE         2          2 INACTIVE

Open database出现数据文件丢失错误：

18:34:17 SYS@ prod>alter database open;

alter database open

*

ERROR at line 1:

ORA-01157: cannot identify/lock data file 9 - see DBWR trace file

ORA-01110: data file 9: '/u01/app/oracle/oradata/prod/tbs2.dbf'

7、对Database做Media Recovery（因为没有日志切换，做complete recover）

[oracle@rh6 ~]$ rman target /Recovery Manager: Release 11.2.0.1.0 - Production on Thu Jul 24 18:34:35 2014Copyright (c) 1982, 2009, Oracle and/or its affiliates.  All rights reserved.connected to target database: PROD (DBID=239333010, not open)RMAN> restore datafile 9;Starting restore at 24-JUL-14using target database control file instead of recovery catalogallocated channel: ORA_DISK_1channel ORA_DISK_1: SID=18 device type=DISKchannel ORA_DISK_1: starting datafile backup set restorechannel ORA_DISK_1: specifying datafile(s) to restore from backup setchannel ORA_DISK_1: restoring datafile 00009 to /u01/app/oracle/oradata/prod/tbs2.dbfchannel ORA_DISK_1: reading from backup piece /dsk3/bak/34_PROD.bakchannel ORA_DISK_1: piece handle=/dsk3/bak/34_PROD.bak tag=TAG20140724T181640channel ORA_DISK_1: restored backup piece 1channel ORA_DISK_1: restore complete, elapsed time: 00:00:01Finished restore at 24-JUL-14RMAN> recover datafile 9;Starting recover at 24-JUL-14using channel ORA_DISK_1starting media recoverymedia recovery complete, elapsed time: 00:00:01Finished recover at 24-JUL-14

查看告警日志：

Thu Jul 24 18:34:49 2014

Full restore complete of datafile 9 /u01/app/oracle/oradata/prod/tbs2.dbf.  Elapsed time: 0:00:00 

  checkpoint is 2168258

Thu Jul 24 18:34:57 2014

alter database recover datafile list clear

Completed: alter database recover datafile list clear

alter database recover if needed

 datafile 9

Media Recovery Start

Serial Media Recovery started

Recovery of Online Redo Log: Thread 1 Group 3 Seq 3 Reading mem 0

  Mem# 0: /dsk1/oradata/prod/redo03a.log

  Mem# 1: /dsk2/oradata/prod/redo03b.log

Recovery of Online Redo Log: Thread 1 Group 1 Seq 4 Reading mem 0

  Mem# 0: /dsk1/oradata/prod/redo01a.log

  Mem# 1: /dsk2/oradata/prod/redo01b.log

Media Recovery Complete (prod)

Completed: alter database recover if needed

 datafile 9

通过group1和3，进行了media recovery ！

8、数据库open，发现T1无法访问（出现：ORA-26040）

18:35:36 SYS@ prod>alter database open;

Database altered.

18:35:49 SYS@ prod>select count(*) from scott.t1;

select count(*) from scott.t1

*

ERROR at line 1:

ORA-01578: ORACLE data block corrupted (file # 9, block # 131)

ORA-01110: data file 9: '/u01/app/oracle/oradata/prod/tbs2.dbf'

ORA-26040: Data block was loaded using the NOLOGGING option

查看告警日志：

alter database openBeginning crash recovery of 1 threadsStarted redo scanCompleted redo scan read 83 KB redo, 26 data blocks need recoveryStarted redo application at Thread 1: logseq 4, block 117Recovery of Online Redo Log: Thread 1 Group 1 Seq 4 Reading mem 0  Mem# 0: /dsk1/oradata/prod/redo01a.log  Mem# 1: /dsk2/oradata/prod/redo01b.logCompleted redo application of 0.02MBCompleted crash recovery at Thread 1: logseq 4, block 284, scn 2208986 26 data blocks read, 26 data blocks written, 83 redo k-bytes readThu Jul 24 18:35:45 2014Thread 1 advanced to log sequence 5 (thread open)Thread 1 opened at log sequence 5  Current log# 2 seq# 5 mem# 0: /dsk1/oradata/prod/redo02a.log  Current log# 2 seq# 5 mem# 1: /dsk2/oradata/prod/redo02b.logSuccessful open of redo thread 1MTTR advisory is disabled because FAST_START_MTTR_TARGET is not setThu Jul 24 18:35:45 2014SMON: enabling cache recoverySuccessfully onlined Undo Tablespace 5.Verifying file header compatibility for 11g tablespace encryption..Verifying 11g file header compatibility for tablespace encryption completedSMON: enabling tx recoveryDatabase Characterset is ZHS16GBKNo Resource Manager plan activereplication_dependency_tracking turned off (no async multimaster replication found)Starting background process QMNCThu Jul 24 18:35:48 2014QMNC started with pid=20, OS id=13934 Completed: alter database openThu Jul 24 18:35:54 2014Starting background process CJQ0Thu Jul 24 18:35:54 2014CJQ0 started with pid=23, OS id=13946 Thu Jul 24 18:36:06 2014Errors in file /u01/app/oracle/diag/rdbms/prod/prod/trace/prod_ora_13932.trc  (incident=139383):ORA-01578: ORACLE data block corrupted (file # 9, block # 131)ORA-01110: data file 9: '/u01/app/oracle/oradata/prod/tbs2.dbf'ORA-26040: Data block was loaded using the NOLOGGING optionIncident details in: /u01/app/oracle/diag/rdbms/prod/prod/incident/incdir_139383/prod_ora_13932_i139383.trcErrors in file /u01/app/oracle/diag/rdbms/prod/prod/trace/prod_ora_13932.trc  (incident=139384):ORA-01578: ORACLE data block corrupted (file # 9, block # 131)ORA-01110: data file 9: '/u01/app/oracle/oradata/prod/tbs2.dbf'ORA-26040: Data block was loaded using the NOLOGGING optionIncident details in: /u01/app/oracle/diag/rdbms/prod/prod/incident/incdir_139384/prod_ora_13932_i139384.trcThu Jul 24 18:36:13 2014Trace dumping is performing id=[cdmp_20140724183613]Thu Jul 24 18:36:14 2014Sweep [inc][139384]: completedSweep [inc][139383]: completedSweep [inc2][139383]: completedTrace dumping is performing id=[cdmp_20140724183617]Thu Jul 24 18:37:14 2014Sweep [inc2][139384]: completed

9、通过DBV验证数据文件

[oracle@rh6 ~]$ dbv file=/u01/app/oracle/oradata/prod/tbs2.dbf blocksize=8192DBVERIFY: Release 11.2.0.1.0 - Production on Thu Jul 24 18:45:59 2014Copyright (c) 1982, 2009, Oracle and/or its affiliates.  All rights reserved.DBVERIFY - Verification starting : FILE = /u01/app/oracle/oradata/prod/tbs2.dbfDBV-00201: Block, DBA 37748867, marked corrupt for invalid redo applicationDBVERIFY - Verification completeTotal Pages Examined         : 1280Total Pages Processed (Data) : 4Total Pages Failing   (Data) : 0Total Pages Processed (Index): 0Total Pages Failing   (Index): 0Total Pages Processed (Other): 1274Total Pages Processed (Seg)  : 0Total Pages Failing   (Seg)  : 0Total Pages Empty            : 2Total Pages Marked Corrupt   : 1Total Pages Influx           : 0Total Pages Encrypted        : 0Highest block SCN            : 2188961 (0.2188961)

在数据文件9上，出现了逻辑坏块 ！

10、转储数据块

14:35:48 SYS@ prod>alter system dump datafile 9 block 131;                   

System altered.

数据块转储信息：

[oracle@rh6 ~]$ cat /u01/app/oracle/diag/rdbms/prod/prod/trace/prod_ora_2822.trc|more

Trace file /u01/app/oracle/diag/rdbms/prod/prod/trace/prod_ora_2822.trcOracle Database 11g Enterprise Edition Release 11.2.0.1.0 - 64bit ProductionWith the Partitioning, OLAP, Data Mining and Real Application Testing optionsORACLE_HOME = /u01/app/oracle/product/11.2.0/db_1System name:    LinuxNode name:      rh6Release:        2.6.32-358.el6.x86_64Version:        #1 SMP Tue Jan 29 11:47:41 EST 2013Machine:        x86_64Instance name: prodRedo thread mounted by this instance: 1Oracle process number: 29Unix process pid: 2822, image: oracle@rh6 (TNS V1-V3)*** 2014-07-25 14:37:54.634*** SESSION ID:(28.16) 2014-07-25 14:37:54.634*** CLIENT ID:() 2014-07-25 14:37:54.634*** SERVICE NAME:(SYS$USERS) 2014-07-25 14:37:54.634*** MODULE NAME:(sqlplus@rh6 (TNS V1-V3)) 2014-07-25 14:37:54.634*** ACTION NAME:() 2014-07-25 14:37:54.634

Start dump data blocks tsn: 9 file#:9 minblk 131 maxblk 131

Block dump from cache:

Dump of buffer cache at level 4 for tsn=9, rdba=37748867

Block dump from disk:

buffer tsn: 9 rdba: 0x02400083 (9/131)

scn: 0x0000.00216666 seq: 0xff flg: 0x04 tail: 0x666600ff

frmt: 0x02 chkval: 0xa4e2 type: 0x00=unknown

Hex dump of block: st=0, typ_found=0

Dump of memory from 0x00007FDEF186CA00 to 0x00007FDEF186EA00

7FDEF186CA00 0000A200 02400083 00216666 04FF0000  [......@.ff!.....]

7FDEF186CA10 0000A4E2 FFFFFFFF FFFFFFFF FFFFFFFF  [................]

7FDEF186CA20 FFFFFFFF FFFFFFFF FFFFFFFF FFFFFFFF  [................]

        Repeat 508 times

7FDEF186E9F0 FFFFFFFF FFFFFFFF FFFFFFFF 666600FF  [..............ff]

End dump data blocks tsn: 9 file#: 9 minblk 131 maxblk 131

----可以看出block 131除了头部信息外，剩下的都是‘FFFFFFFF’，应该是一个逻辑坏块！

11、转储对应的logfile

14:35:48 SYS@ prod>alter system dump logfile '/dsk1/oradata/prod/redo01a.log'；System altered.14:35:53 SYS@ prod>alter system dump logfile '/dsk1/oradata/prod/redo03a.log'；System altered.[oracle@rh6 ~]$ cat /u01/app/oracle/diag/rdbms/prod/prod/trace/prod_ora_2406.trcDUMP OF REDO FROM FILE '/dsk1/oradata/prod/redo01a.log' Opcodes *.* RBAs: 0x000000.00000000.0000 thru 0xffffffff.ffffffff.ffff SCNs: scn: 0x0000.00000000 thru scn: 0xffff.ffffffff Times: creation thru eternity FILE HEADER:        Compatibility Vsn = 186646528=0xb200000        Db ID=239333010=0xe43ee92, Db Name='PROD'        Activation ID=264808982=0xfc8aa16        Control Seq=2747=0xabb, File size=102400=0x19000        File Number=1, Blksiz=512, File Type=2 LOG descrip:"Thread 0001, Seq# 0000000004, SCN 0x000000216562-0x00000021b4dc" thread: 1 nab: 0x11c seq: 0x00000004 hws: 0x6 eot: 0 dis: 0 resetlogs count: 0x32d7d50e scn: 0x0000.00206c24 (2124836) prev resetlogs count: 0x32d7cc14 scn: 0x0000.0020680f (2123791) Low  scn: 0x0000.00216562 (2188642) 07/24/2014 18:27:42 Next scn: 0x0000.0021b4dc (2208988) 07/24/2014 18:35:45 Enabled scn: 0x0000.00206c24 (2124836) 07/15/2014 17:59:42 Thread closed scn: 0x0000.0021b4da (2208986) 07/24/2014 18:33:04 Disk cksum: 0x1af0 Calc cksum: 0x1af0 Terminal recovery stop scn: 0x0000.00000000 Terminal recovery  01/01/1988 00:00:00 Most recent redo scn: 0x0000.00000000 Largest LWN: 0 blocks End-of-redo stream : No Unprotected mode Miscellaneous flags: 0x800000 Thread internal enable indicator: thr: 0, seq: 0 scn: 0x0000.00000000

REDO RECORD - Thread:1 RBA: 0x000004.000000c6.0198 LEN: 0x0034 VLD: 0x01

SCN: 0x0000.00216666 SUBSCN:  1 07/24/2014 18:30:45

CHANGE #1 INVLD AFN:9 DBA:0x02400083 BLKS:0x0001 OBJ:75139 SCN:0x0000.00216666 SEQ:1 OP:19.2 ENC:0

Direct Loader invalidate block range redo entry

REDO RECORD - Thread:1 RBA: 0x000006.000007b6.0110 LEN: 0x0034 VLD: 0x01

SCN: 0x0000.00220ad0 SUBSCN:  1 07/25/2014 14:22:51

CHANGE #1 INVLD AFN:2 DBA:0x0080f09c BLKS:0x0001 OBJ:6214 SCN:0x0000.00220ad0 SEQ:1 OP:19.2 ENC:0

Direct Loader invalidate block range redo entry

-在redo日志里记录了“Direct Loader”的动作（OBJ:75139，OBJ:6214）

查看对应的对象：

14:29:23 SYS@ prod>select owner,object_id,object_name from dba_objects15:18:47   2  where object_id=75139;OWNER                           OBJECT_ID OBJECT_NAME------------------------------ ---------- --------------------SCOTT                               75139 T1Elapsed: 00:00:00.0415:18:51 SYS@ prod>select owner,object_id,object_name from dba_objects15:18:58   2  where object_id=6214;OWNER                           OBJECT_ID OBJECT_NAME------------------------------ ---------- --------------------SYS                                  6214 SYS_LOB0000006213C00                                          038$$Elapsed: 00:00:00.0515:19:07 SYS@ prod>

   从以上，查看信息可以推断，在Media Recover阶段，create table T1 as select * from 采用了“Direct Loader”，在非归档下应该是采用了‘nologging’方式，以致后续的Insert的数据通过redo log无法被恢复，导致出现逻辑坏块！

备注：（借鉴Maclean Liu博客观点）

http://www.askmaclean.com/archives/nologging-unrecoverable.html

【数据恢复】NOLOGGING UNRECOVERABLE ORA-26040解析

SQL> select count(*) from abc;select count(*) from abc*第 1 行出现错误:ORA-01578: ORACLE 数据块损坏 (文件号 17, 块号 131)ORA-01110: 数据文件 17:‘C:\APP\XIANGBLI\ORADATA\MACLEAN\DATAFILE\O1_MF_NLOGGING_9475OCS5_.DBF’ORA-26040: 数据块是使用 NOLOGGING 选项加载的 SQL> select UNRECOVERABLE_CHANGE# , UNRECOVERABLE_time from v$datafile where file#=17;UNRECOVERABLE_CHANGE# UNRECOVERABLE_——————— ————–6486756 26-9月 -13 把 (文件号 17, 块号 131) dump出来看一下  *** 2013-09-26 10:07:46.584Start dump data blocks tsn: 17 file#:17 minblk 131 maxblk 131Block dump from cache:Dump of buffer cache at level 4 for pdb=0 tsn=17 rdba=71303299Block dump from disk:buffer tsn: 17 rdba: 0×04400083 (17/131)scn: 0×0.62faac seq: 0xff flg: 0×04 tail: 0xfaac00fffrmt: 0×02 chkval: 0xa2a1 type: 0×00=unknownHex dump of block: st=0, typ_found=0Dump of memory from 0x000000000BFF2200 to 0x000000000BFF420000BFF2200 0000A200 04400083 0062FAAC 04FF0000 [......@...b.....]00BFF2210 0000A2A1 FFFFFFFF FFFFFFFF FFFFFFFF [................]00BFF2220 FFFFFFFF FFFFFFFF FFFFFFFF FFFFFFFF [................]Repeat 508 times00BFF41F0 FFFFFFFF FFFFFFFF FFFFFFFF FAAC00FF [................]End dump data blocks tsn: 17 file#: 17 minblk 131 maxblk 131 scn: 0×0.62faac seq: 0xff==》 对应的SCN为6486700，可以看到内容除了头部一点外 全是0XFF dump 对应redo logfile 可以看到REDO RECORD – Thread:1 RBA: 0×000074.00015418.0078 LEN: 0x003c VLD: 0×01 CON_UID: 0SCN: 0×0000.0062faac SUBSCN: 1 09/26/2013 10:04:39CHANGE #1 INVLD CON_ID:0 AFN:17 DBA:0×04400083 BLKS:0x000d OBJ:123054 SCN:0×0000.0062faac SEQ:1 OP:19.2 ENC:0Direct Loader invalidate block range redo entry OP:19.2=》Layer 19 : Direct Loader Log Blocks – KCOCODLB Opcode 2 : Invalidate range – KCBLCOIR==》这里在redo里标记了 直接路径加载造成块失效的范围，在redo logfile dump中可以看到大量类似数据 即当recover时读取redo，读到“Direct Loader invalidate block range redo entry”信息时，则将对应的数据块的内容除了kcbh头部外全部记录为0XFF当Oracle读取到这些块时就会知道这些块是SOFT Corrupt ，原因是nologging造成的。Block is marked as SOFT Corrupt and has 0xff along the block. This is theformat used by Oracle to mark a block as corrupt due to redo invalidation(NOLOGGING).NOLOGGING OPERATION in redo:

本文出自 “天涯客的blog” 博客，请务必保留此出处http://tiany.blog.51cto.com/513694/1530094