Shulou(Shulou.com)06/01 Report--

Media Recovery error in Oracle non-archiving mode-- ORA-26040

System environment:

Operating system: Linux RH55

Oracle: Oracle 11gR2

Simulation case:

1. View the database schema

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

Database log mode No Archive Mode

Automatic archival Disabled

Archive destination / dsk4/arch2

Oldest online log sequence 1

Current log sequence 3

2. Create a new Tablespace

18:13:19 SYS@ prod > create tablespace tbs2 18:13:30 2 datafile'/ u01 datafile'/ u01 created append create tablespace tbs2 create tablespace tbs2 oradata Accord Tablespace created.

3. Cold standby for the database

[oracle@rh7] $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. Backup completes and create Object on the new Tablesapce

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: 00tablespace tbs2 as select 01.0018 tablespace tbs2 as select 45 SCOTT@ prod > select count (*) from T1; COUNT (*)-14Elapsed: 0000 insert into 00.0218 30 SCOTT@ prod 56 SCOTT@ prod > insert into T1 select * from T1 where rownum=1;1 row created.Elapsed: 00.021831 SCOTT@ prod > commit Commit complete.Elapsed: 0000select 00.0418 insert into 31 SCOTT@ prod > from T1 select * from T1 where rownum=1;1 row created.Elapsed: 000000VOO00.0118VOLAR 31Rd 23 SCOTT@ prod > select count (*) from T1; COUNT (*)-16

5. View Redo Log information

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

6. The simulation data file is destroyed.

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

18:32:28 SYS@ prod > shutdown abort

ORACLE instance shut down.

Restart Instance to mount and check redo log. No switch occurred in the log.

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

A data file loss error occurred in 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 *

7. Media Recovery Database (since there is no log switch, do complete recover)

[oracle@rh7] $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

View the alarm log:

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

Through group1 and 3, media recovery!

8. Database open, found that T1 cannot be accessed (appears: 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 *

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

View the alarm log:

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 # 131ORA-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 # 131ORA-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 2418: 36:13 2014Trace dumping is performing id= [cdmp _ 20140724183613] Thu Jul 2418: 36:14 2014Sweep [inc] [139384]: completedSweep [inc] [139383]: completedSweep [inc2] [139383]: completedTrace dumping is performing id= [cdmp _ 20140724183617] Thu Jul 2418: 37:14 2014Sweep [inc2] [139384]: completed

9. Verify the data file through DBV

[oracle@rh7] $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)

On data file 9, there is a logical bad block!

10. Dump data blocks

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

System altered.

Block dump information:

[oracle@rh7 ~] $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: rh7Release: 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 P_w_picpath: p_w_picpath: oracle@rh7 (TNS V1-V3) * * 2014-07-25 1415 1515 TNS V1-V3 * SESSION ID: (28.16) 2014-07-25 1415 1415 3715 54.634 CLIENT ID: () 2014-07-25 1414 1415 3715 54.634 p_w_picpath * SERVICE NAME: (SYS$USERS) 2014-07-25 1414 14V 37V 54.634 MODULE NAME: (sqlplus@rh7 (TNS V1-V3)) 2014-07-25 14:37: 54.634 ACTION NAME: () 2014-07-25 14 purl 37purl 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

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

-you can see that except for the header message, the rest of block 131is' FFFFFFFF', should be a logical bad block!

11. Dump the corresponding 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@rh7 ~] $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: 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) 070x32d7cc14 scn 2014 18:27:42 Next scn: 0x0000.0021b4dc (2208988) 07xt 2014 18:35:45 Enabled scn: 0x0000.00206c24 (2124836) 07 Hammer 2014 17:59:42 Thread closed scn: 0x0000.0021b4da (2208986) 07max 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

-the action of "Direct Loader" is recorded in the redo log (OBJ:75139,OBJ:6214)

View the corresponding object:

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 T1Elapsed 00.0415 18 SYS@ prod 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: 0000 SYS@ prod 00.0515 1907 SYS@ prod >

From the above, it can be inferred that in the Media Recover phase, create table T1 as select * from adopted "Direct Loader", but it should have adopted the "nologging'" mode under non-archiving, so that the subsequent Insert data could not be recovered through redo log, resulting in logical bad blocks!

Remarks: (learn from the viewpoint of Maclean Liu blog)

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

[data recovery] error occurred in line 1 of NOLOGGING UNRECOVERABLE ORA-26040 parsing SQL > select count (*) from abc;select count (*) from abc*: ORA-01578: ORACLE data block is corrupted (file number 17, block number 131) ORA-01110: data file 17 ORADATA:\ APP\ XIANGBLI\ ORADATA\ DATAFILE\ O1_MF_NLOGGING_9475OCS5_.DBF'ORA-26040: data block is SQL > select UNRECOVERABLE_CHANGE#, UNRECOVERABLE_time from v$datafile where file#=17 loaded using the NOLOGGING option UNRECOVERABLE_CHANGE# UNRECOVERABLE_--6486756 26-September-13 (document number 17) Block number 2013-09-26 10:07:46.584Start dump data blocks tsn: 17 file#:17 minblk 131maxblk 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 (17xx131) 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: 0xfficient = "the corresponding SCN is 6486700 You can see that except for the header point, all the contents are 0XFF dump corresponding to redo logfile. You can see REDO RECORD-Thread:1 RBA: 0 × 0074.00015418.0078 LEN: 0x003c VLD: 0 × 01 CON_UID: 0SCN: 0 × 0000.0062faac SUBSCN: 10926 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== "here marks the range of block failure caused by direct path loading in redo. You can see a large number of similar data in redo logfile dump, that is, when reading redo when recover, and reading "Direct Loader invalidate block range redo entry" information, then all the contents of the corresponding data blocks are recorded as 0XFF except the kcbh header. When Oracle reads these blocks, you will know that these blocks are SOFT Corrupt, because they are caused by 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:

Welcome to subscribe "Shulou Technology Information " to get latest news, interesting things and hot topics in the IT industry, and controls the hottest and latest Internet news, technology news and IT industry trends.