Friday, January 25, 2013

Cotinue to paly with RMAN manual block recover

I am puzzled with previous (Failed to ) Play with RMAN RECOVER BLOCK command , so continue to play it.

 Did I corrupted wrong block? Why not try the same command against 2nd block ?

1. Use RMAN to take the full backup again.


delete noprompt expired backup;
delete noprompt expired archivelog all;
sql 'alter system switch logfile';
backup database plus archivelog delete all input ;
delete noprompt obsolete;


2. shutdown the physical standby

SYS@DGS> shutdown immediate
Database closed.
Database dismounted.
ORACLE instance shut down.


3. Corrupt 132nd block of data file 4, which is 2nd data block of table liqy.t1

orarac1poc:DG:/home/oracle/ops/logs> dd of=/u01/oradata/DG/users01.dbf count=1  bs=8192 seek=132 conv=notrunc <> corrupt a none T1 table's block
> EOF
0+1 records in
0+1 records out
32 bytes (32 B) copied, 7.3e-05 seconds, 438 kB/s
orarac1poc:DG:/home/oracle/ops/logs> dbv file=/u01/oradata/DG/users01.dbf blocksize=8192

DBVERIFY: Release 11.2.0.2.0 - Production on Fri Jan 25 09:14:57 2013

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

DBVERIFY - Verification starting : FILE = /u01/oradata/DG/users01.dbf
Page 132 is marked corrupt
Corrupt block relative dba: 0x01000084 (file 4, block 132)
Bad header found during dbv:
Data in bad block:
 type: 99 format: 7 rdba: 0x20747075
 last change scn: 0x656e.6f6e2061 seq: 0x20 flg: 0x54
 spare1: 0x72 spare2: 0x72 spare3: 0x6174
 consistency value in tail: 0x38180601
 check value in block header: 0x2031
 computed block checksum: 0xc3c6


DBVERIFY - Verification complete

Total Pages Examined         : 640
Total Pages Processed (Data) : 4
Total Pages Failing   (Data) : 0
Total Pages Processed (Index): 0
Total Pages Failing   (Index): 0
Total Pages Processed (Other): 577
Total Pages Processed (Seg)  : 0
Total Pages Failing   (Seg)  : 0
Total Pages Empty            : 58
Total Pages Marked Corrupt   : 1
Total Pages Influx           : 0
Total Pages Encrypted        : 0
Highest block SCN            : 997407 (0.997407)


SYS@DG> alter system flush buffer_cache;

System altered.

SYS@DG> select * from liqy.t1;
ERROR:
ORA-01578: ORACLE data block corrupted (file # 4, block # 132)
ORA-01110: data file 4: '/u01/oradata/DG/users01.dbf'

no rows selected


SYS@DG> select * from v$database_block_corruption;

     FILE#     BLOCK#     BLOCKS CORRUPTION_CHANGE# CORRUPTIO
---------- ---------- ---------- ------------------ ---------
         4        132          1                  0 CORRUPT


***********************************************************************

Fatal NI connect error 12514, connecting to:
 (DESCRIPTION=(ADDRESS=(PROTOCOL=TCP)(HOST=orarac2poc)(PORT=1521))(CONNECT_DATA=(SERVER=DEDICATED)(SERVICE_NAME=DGS.POC)(CID=(PROGRAM=oracle)(HOST=orarac1poc)(USER=oracle))))

  VERSION INFORMATION:
        TNS for Linux: Version 11.2.0.2.0 - Production
        TCP/IP NT Protocol Adapter for Linux: Version 11.2.0.2.0 - Production
  Time: 25-JAN-2013 09:15:17
  Tracing not turned on.
  Tns error struct:
    ns main err code: 12564

TNS-12564: TNS:connection refused
    ns secondary err code: 0
    nt main err code: 0
    nt secondary err code: 0
    nt OS err code: 0
Errors in file /u01/app/oracle/diag/rdbms/dg/DG/trace/DG_bmr0_21467.trc:
ORA-17627: ORA-12514: TNS:listener does not currently know of service requested in connect descriptor
ORA-17629: Cannot connect to the remote database server
Automatic block media recovery failed for (file# 4, block# 132)    #as I stopped active data guard
        [No standby available]
Automatic block media recovery requested for (file# 4, block# 132)
Automatic block media recovery failed for (file# 4, block# 132)
        [request flood controlled]
Fri Jan 25 09:15:17 2013
Corrupt Block Found
         TSN = 4, TSNAME = USERS
         RFN = 4, BLK = 132, RDBA = 16777348
         OBJN = 61354, OBJD = 61354, OBJECT = T1, SUBOBJECT =
         SEGMENT OWNER = LIQY, SEGMENT TYPE = Table Segment
Errors in file /u01/app/oracle/diag/rdbms/dg/DG/trace/DG_ora_21440.trc  (incident=63838):
ORA-01578: ORACLE data block corrupted (file # 4, block # 132)
ORA-01110: data file 4: '/u01/oradata/DG/users01.dbf'
Incident details in: /u01/app/oracle/diag/rdbms/dg/DG/incident/incdir_63838/DG_ora_21440_i63838.trc
Fri Jan 25 09:15:21 2013
Sweep [inc][63838]: completed
Hex dump of (file 4, block 132) in trace file /u01/app/oracle/diag/rdbms/dg/DG/incident/incdir_63838/DG_m000_21473_i63838_a.trc
Corrupt block relative dba: 0x01000084 (file 4, block 132)
Bad header found during validation
Data in bad block:
 type: 99 format: 7 rdba: 0x20747075
 last change scn: 0x656e.6f6e2061 seq: 0x20 flg: 0x54
 spare1: 0x72 spare2: 0x72 spare3: 0x6174
 consistency value in tail: 0x38180601
 check value in block header: 0x2031
 computed block checksum: 0xc3c6
Reread of blocknum=132, file=/u01/oradata/DG/users01.dbf. found same corrupt data
Reread of blocknum=132, file=/u01/oradata/DG/users01.dbf. found same corrupt data
Reread of blocknum=132, file=/u01/oradata/DG/users01.dbf. found same corrupt data
Reread of blocknum=132, file=/u01/oradata/DG/users01.dbf. found same corrupt data
Reread of blocknum=132, file=/u01/oradata/DG/users01.dbf. found same corrupt data
Fri Jan 25 09:15:21 2013
Dumping diagnostic data in directory=[cdmp_20130125091521], requested by (instance=1, osid=21440), summary=[incident=63838].
Checker run found 1 new persistent data failures
Fri Jan 25 09:15:22 2013


***********************************************************************


The relevant trace file


orarac1poc:DG:/u01/app/oracle/diag/rdbms/dg/DG/trace> cat DG_bmr0_21467.trc
Trace file /u01/app/oracle/diag/rdbms/dg/DG/trace/DG_bmr0_21467.trc
Oracle Database 11g Enterprise Edition Release 11.2.0.2.0 - 64bit Production
With the Partitioning, Real Application Clusters, OLAP, Data Mining
and Real Application Testing options
ORACLE_HOME = /u01/app/oracle/product/11.2.0/db_2
System name:    Linux
Node name:      orarac1poc
Release:        2.6.18-238.el5
Version:        #1 SMP Sun Dec 19 14:22:44 EST 2010
Machine:        x86_64
VM name:        VMWare Version: 6
Instance name: DG
Redo thread mounted by this instance: 1
Oracle process number: 36
Unix process pid: 21467, image: oracle@orarac1poc (BMR0)


*** 2013-01-25 09:15:17.729
*** SESSION ID:(56.1795) 2013-01-25 09:15:17.729
*** CLIENT ID:() 2013-01-25 09:15:17.729
*** SERVICE NAME:(SYS$BACKGROUND) 2013-01-25 09:15:17.729
*** MODULE NAME:() 2013-01-25 09:15:17.729
*** ACTION NAME:() 2013-01-25 09:15:17.729

OCI error val is 12514 and errmsg is 'ORA-12514: TNS:listener does not currently know of service requested in connect descriptor
'
ORA-17627: ORA-12514: TNS:listener does not currently know of service requested in connect descriptor
ORA-17629: Cannot connect to the remote database server

4.  Use RMAN to repair the block


RMAN> recover datafile 4 block 132;

Starting recover at Jan 25 2013 09:17:28
allocated channel: ORA_DISK_1
channel ORA_DISK_1: SID=181 device type=DISK
searching flashback logs for block images until SCN 4053936
finished flashback log search, restored 0 blocks

channel ORA_DISK_1: restoring block(s)
channel ORA_DISK_1: specifying block(s) to restore from backup set
restoring blocks of datafile 00004
channel ORA_DISK_1: reading from backup piece /u01/oradata/DG/FRA/DG/backupset/2013_01_25/o1_mf_nnndf_TAG20130125T090450_8j3pko2q_.bkp
channel ORA_DISK_1: piece handle=/u01/oradata/DG/FRA/DG/backupset/2013_01_25/o1_mf_nnndf_TAG20130125T090450_8j3pko2q_.bkp tag=TAG20130125T090450
channel ORA_DISK_1: restored block(s) from backup piece 1
channel ORA_DISK_1: block restore complete, elapsed time: 00:00:01

starting media recovery
media recovery complete, elapsed time: 00:00:01


Finished recover at Jan 25 2013 09:17:34


The relevant log.

***********************************************************************

Fatal NI connect error 12514, connecting to:
 (DESCRIPTION=(ADDRESS=(PROTOCOL=TCP)(HOST=orarac2poc)(PORT=1521))(CONNECT_DATA=(SERVER=DEDICATED)(SERVICE_NAME=DGS.POC)(CID=(PROGRAM=oracle)(HOST=orarac1poc)(USER=oracle))))

  VERSION INFORMATION:
        TNS for Linux: Version 11.2.0.2.0 - Production
        Oracle Bequeath NT Protocol Adapter for Linux: Version 11.2.0.2.0 - Production
        TCP/IP NT Protocol Adapter for Linux: Version 11.2.0.2.0 - Production
  Time: 25-JAN-2013 09:17:31
  Tracing not turned on.
  Tns error struct:
    ns main err code: 12564

TNS-12564: TNS:connection refused
    ns secondary err code: 0
    nt main err code: 0
    nt secondary err code: 0
    nt OS err code: 0
Errors in file /u01/app/oracle/diag/rdbms/dg/DG/trace/DG_ora_21638.trc:
ORA-17627: ORA-12514: TNS:listener does not currently know of service requested in connect descriptor
ORA-17629: Cannot connect to the remote database server
alter database recover datafile list clear
Completed: alter database recover datafile list clear
Started Block Media Recovery
Recovery of Online Redo Log: Thread 1 Group 3 Seq 66 Reading mem 0
  Mem# 0: /u01/oradata/DG/redo03.log
Recovery of Online Redo Log: Thread 1 Group 1 Seq 67 Reading mem 0
  Mem# 0: /u01/oradata/DG/redo01.log
Completed Block Media Recovery

Fri Jan 25 09:17:35 2013


***********************************************************************



orarac1poc:DG:/u01/app/oracle/diag/rdbms/dg/DG/trace> cat DG_ora_21638.trc
Trace file /u01/app/oracle/diag/rdbms/dg/DG/trace/DG_ora_21638.trc
Oracle Database 11g Enterprise Edition Release 11.2.0.2.0 - 64bit Production
With the Partitioning, Real Application Clusters, OLAP, Data Mining
and Real Application Testing options
ORACLE_HOME = /u01/app/oracle/product/11.2.0/db_2
System name:    Linux
Node name:      orarac1poc
Release:        2.6.18-238.el5
Version:        #1 SMP Sun Dec 19 14:22:44 EST 2010
Machine:        x86_64
VM name:        VMWare Version: 6
Instance name: DG
Redo thread mounted by this instance: 1
Oracle process number: 83
Unix process pid: 21638, image: oracle@orarac1poc (TNS V1-V3)


*** 2013-01-25 09:17:31.288
*** SESSION ID:(181.1561) 2013-01-25 09:17:31.288
*** CLIENT ID:() 2013-01-25 09:17:31.288
*** SERVICE NAME:(SYS$USERS) 2013-01-25 09:17:31.288
*** MODULE NAME:(rman@orarac1poc (TNS V1-V3)) 2013-01-25 09:17:31.288
*** ACTION NAME:(0000009 STARTED180) 2013-01-25 09:17:31.288

OCI error val is 12514 and errmsg is 'ORA-12514: TNS:listener does not currently know of service requested in connect descriptor
'
ORA-17627: ORA-12514: TNS:listener does not currently know of service requested in connect descriptor
ORA-17629: Cannot connect to the remote database server
*** ACTION NAME:(0000012 STARTED169) 2013-01-25 09:17:31.569

Flashback async buffers are set to 16

*** 2013-01-25 09:17:31.664
*** MODULE NAME:(restore full datafile) 2013-01-25 09:17:31.847
*** ACTION NAME:(0000021 STARTED40) 2013-01-25 09:17:31.847

The input backup piece /u01/oradata/DG/FRA/DG/backupset/2013_01_25/o1_mf_nnndf_TAG20130125T090450_8j3pko2q_.bkp is in BASIC 11.2 compressed format.
krbr1b2b: saved block under name /u01/app/oracle/diag/rdbms/dg/DG/trace/4_132_0_997400.bkd

*** 2013-01-25 09:17:32.961
*** ACTION NAME:(0000026 STARTED104) 2013-01-25 09:17:32.961

Begin Media Recovery of 1 blocks
Dumping database incarnation table:
Resetlogs 0 scn and time: 0x0000.00375e2e 01/21/2013 18:27:03
Initial buffer sizes: read 1024K, overflow 832K, change 805K

*** 2013-01-25 09:17:32.983
Media Recovery add redo thread 1
Start recovery at thread 1 ckpt scn 4053936 logseq 66 block 22
End recovery at scn 4055250

*** 2013-01-25 09:17:33.117
Recovery of Online Redo Log: Thread 1 Group 3 Seq 66 Reading mem 0
Log read is SYNCHRONOUS though disk_asynch_io is enabled!

*** 2013-01-25 09:17:33.119
Recovery of Online Redo Log: Thread 1 Group 1 Seq 67 Reading mem 0
Log read is SYNCHRONOUS though disk_asynch_io is enabled!
----- Redo read statistics for thread 1 -----
Read rate (SYNC): 745Kb in 0.13s => 5.60 Mb/sec
Total redo bytes: 1219Kb Longest record: 8Kb, moves: 0/1206 moved: 0Mb (0%)
Longest LWN: 45Kb, reads: 843
Last redo scn: 0x0000.003de0d1 (4055249)
Change vector header moves = 111/2278 (4%)
----------------------------------------------

*** 2013-01-25 09:17:33.123
Media Recovery drop redo thread 1
Completed Block Media Recovery of file 4, block 132



orarac1poc:DG:/home/oracle/ops/logs> dbv file=/u01/oradata/DG/users01.dbf blocksize=8192

DBVERIFY: Release 11.2.0.2.0 - Production on Fri Jan 25 09:30:51 2013

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

DBVERIFY - Verification starting : FILE = /u01/oradata/DG/users01.dbf


DBVERIFY - Verification complete

Total Pages Examined         : 640
Total Pages Processed (Data) : 5
Total Pages Failing   (Data) : 0
Total Pages Processed (Index): 0
Total Pages Failing   (Index): 0
Total Pages Processed (Other): 577
Total Pages Processed (Seg)  : 0
Total Pages Failing   (Seg)  : 0
Total Pages Empty            : 58
Total Pages Marked Corrupt   : 0
Total Pages Influx           : 0
Total Pages Encrypted        : 0
Highest block SCN            : 997407 (0.997407)

SYS@DG> select * from v$database_block_corruption;

no rows selected

SYS@DG> select * from liqy.t1;

        F1
----------
         1


Succeed to use RMAN block recoery, but why not working for the 1st block,i.e. 131st block in my database.


5. Have to Exam the block type of 131st block, to ensure the correct block to be corrupted.

SYS@DG>  select HEADER_FILE, HEADER_BLOCK from dba_segments where segment_name='T1' and owner='LIQY';

HEADER_FILE HEADER_BLOCK
----------- ------------
          4          130

SYS@DG> select header_block,blocks, extents from  dba_segments where segment_name='T1';

HEADER_BLOCK     BLOCKS    EXTENTS
------------ ---------- ----------
         130          8          1

SYS@DG> select extent_id, block_id,  blocks, bytes from dba_extents where segment_name='T1';

 EXTENT_ID   BLOCK_ID     BLOCKS      BYTES
---------- ---------- ---------- ----------
         0        128          8      65536

SYS@DG> alter session set tracefile_identifier=dump130;

Session altered.

SYS@DG> alter system dump datafile 4 block 130;

System altered.


Start dump data blocks tsn: 4 file#:4 minblk 130 maxblk 130
Block dump from cache:
Dump of buffer cache at level 4 for tsn=4, rdba=16777346
BH (0x6cff9418) file#: 4 rdba: 0x01000082 (4/130) class: 4 ba: 0x6cf82000
  set: 6 pool: 3 bsz: 8192 bsi: 0 sflg: 2 pwc: 346,28
  dbwrid: 0 obj: 61354 objn: 61354 tsn: 4 afn: 4 hint: f
  hash: [0x86f1ea00,0x86f1ea00] lru: [0x6cff9630,0x6cff93d0]
  ckptq: [NULL] fileq: [NULL] objq: [0x82d05080,0x6cff93f8] objaq: [0x82d05070,0x6cff9408]
  st: XCURRENT md: NULL tch: 2
  flags:
  LRBA: [0x0.0.0] LSCN: [0x0.0] HSCN: [0xffff.ffffffff] HSUB: [65535]
  cr pin refcnt: 0 sh pin refcnt: 0
Block dump from disk:
buffer tsn: 4 rdba: 0x01000082 (4/130)
scn: 0x0000.000f3818 seq: 0x01 flg: 0x04 tail: 0x38182301
frmt: 0x02 chkval: 0x442e type: 0x23=PAGETABLE SEGMENT HEADER
Hex dump of block: st=0, typ_found=1
Dump of memory from 0x00002AFE83CA8A00 to 0x00002AFE83CAAA00


-- continue to dump block 131


SYS@DG> alter session set tracefile_identifier=dump131;

Session altered.

SYS@DG> alter system dump datafile 4 block 131;

System altered.

SYS@DG> exit


Start dump data blocks tsn: 4 file#:4 minblk 131 maxblk 131
Block dump from cache:
Dump of buffer cache at level 4 for tsn=4, rdba=16777347
BH (0x6cfe4fe8) file#: 4 rdba: 0x01000083 (4/131) class: 1 ba: 0x6cd60000
  set: 5 pool: 3 bsz: 8192 bsi: 0 sflg: 2 pwc: 346,28
  dbwrid: 0 obj: 61354 objn: 61354 tsn: 4 afn: 4 hint: f
  hash: [0x86ffaf30,0x86ffaf30] lru: [0x6cfe5200,0x6cfe4fa0]
  ckptq: [NULL] fileq: [NULL] objq: [0x82d03e60,0x6cfe4fc8] objaq: [0x82d03e50,0x6cfe4fd8]
  st: XCURRENT md: NULL tch: 1
  flags: only_sequential_access
  LRBA: [0x0.0.0] LSCN: [0x0.0] HSCN: [0xffff.ffffffff] HSUB: [65535]
  cr pin refcnt: 0 sh pin refcnt: 0
Block dump from disk:
buffer tsn: 4 rdba: 0x01000083 (4/131)
scn: 0x0000.000f381f seq: 0x01 flg: 0x06 tail: 0x381f0601
frmt: 0x02 chkval: 0x90cd type: 0x06=trans data
Hex dump of block: st=0, typ_found=1
Dump of memory from 0x00002B17B9097A00 to 0x00002B17B9099A00


SYS@DG> alter session set tracefile_identifier=dump132;

Session altered.


SYS@DG> alter system dump datafile 4 block 132;

System altered.



orarac1poc:DG:/u01/app/oracle/diag/rdbms/dg/DG/trace> ls -lrt *DUMP*
-rw-r----- 1 oracle asmadmin   76 Jan 25 10:11 DG_ora_27034_DUMP130.trm
-rw-r----- 1 oracle asmadmin 5046 Jan 25 10:11 DG_ora_27034_DUMP130.trc
-rw-r----- 1 oracle asmadmin   95 Jan 25 10:15 DG_ora_28183_DUMP131.trm
-rw-r----- 1 oracle asmadmin 3379 Jan 25 10:15 DG_ora_28183_DUMP131.trc
-rw-r----- 1 oracle asmadmin  106 Jan 25 13:48 DG_ora_21153_DUMP132.trm
-rw-r----- 1 oracle asmadmin 3137 Jan 25 13:48 DG_ora_21153_DUMP132.trc


Start dump data blocks tsn: 4 file#:4 minblk 132 maxblk 132
Block dump from cache:
Dump of buffer cache at level 4 for tsn=4, rdba=16777348
BH (0x6d3f06c8) file#: 4 rdba: 0x01000084 (4/132) class: 1 ba: 0x6d294000
  set: 5 pool: 3 bsz: 8192 bsi: 0 sflg: 2 pwc: 386,28
  dbwrid: 0 obj: 61354 objn: 61354 tsn: 4 afn: 4 hint: f
  hash: [0x86f72e20,0x86f72e20] lru: [0x6d3f08e0,0x6d3f0680]
  ckptq: [NULL] fileq: [NULL] objq: [0x6d3f0908,0x6d3f06a8] objaq: [0x6d3f0918,0x6d3f06b8]
  st: XCURRENT md: NULL tch: 1
  flags: only_sequential_access
  LRBA: [0x0.0.0] LSCN: [0x0.0] HSCN: [0xffff.ffffffff] HSUB: [65535]
  cr pin refcnt: 0 sh pin refcnt: 0
Block dump from disk:
buffer tsn: 4 rdba: 0x01000084 (4/132)
scn: 0x0000.000f3818 seq: 0x01 flg: 0x04 tail: 0x38180601
frmt: 0x02 chkval: 0x97e8 type: 0x06=trans data
Hex dump of block: st=0, typ_found=1
Dump of memory from 0x00002B5E0B1C6A00 to 0x00002B5E0B1C8A00


--block 131 and 132 has same type, shown as "trans data". Confirmed block 131 is a table data block.

6. Review the corruption of block 131


dd of=/u01/oradata/DG/users01.dbf count=1  bs=8192 seek=131 conv=notrunc <> corrupt 131st block
> EOF
0+1 records in
0+1 records out
20 bytes (20 B) copied, 8.1e-05 seconds, 247 kB/s



RMAN> recover datafile 4 block 131;

Starting recover at Jan 25 2013 09:37:04
using channel ORA_DISK_1
searching flashback logs for block images until SCN 4053936
finished flashback log search, restored 0 blocks

channel ORA_DISK_1: restoring block(s)
channel ORA_DISK_1: specifying block(s) to restore from backup set
restoring blocks of datafile 00004
channel ORA_DISK_1: reading from backup piece /u01/oradata/DG/FRA/DG/backupset/2013_01_25/o1_mf_nnndf_TAG20130125T090450_8j3pko2q_.bkp
channel ORA_DISK_1: piece handle=/u01/oradata/DG/FRA/DG/backupset/2013_01_25/o1_mf_nnndf_TAG20130125T090450_8j3pko2q_.bkp tag=TAG20130125T090450
channel ORA_DISK_1: restored block(s) from backup piece 1
channel ORA_DISK_1: block restore complete, elapsed time: 00:00:01

starting media recovery
some blocks not recovered: See trace file for details
media recovery complete, elapsed time: 00:00:01

Finished recover at Jan 25 2013 09:37:06




orarac1poc:DG:/u01/app/oracle/diag/rdbms/dg/DG/trace> cat DG_ora_23626.trc
Trace file /u01/app/oracle/diag/rdbms/dg/DG/trace/DG_ora_23626.trc
Oracle Database 11g Enterprise Edition Release 11.2.0.2.0 - 64bit Production
With the Partitioning, Real Application Clusters, OLAP, Data Mining
and Real Application Testing options
ORACLE_HOME = /u01/app/oracle/product/11.2.0/db_2
System name:    Linux
Node name:      orarac1poc
Release:        2.6.18-238.el5
Version:        #1 SMP Sun Dec 19 14:22:44 EST 2010
Machine:        x86_64
VM name:        VMWare Version: 6
Instance name: DG
Redo thread mounted by this instance: 1
Oracle process number: 32
Unix process pid: 23626, image: oracle@orarac1poc (TNS V1-V3)


*** 2013-01-25 09:36:56.880
*** SESSION ID:(57.119) 2013-01-25 09:36:56.880
*** CLIENT ID:() 2013-01-25 09:36:56.880
*** SERVICE NAME:(SYS$USERS) 2013-01-25 09:36:56.880
*** MODULE NAME:(rman@orarac1poc (TNS V1-V3)) 2013-01-25 09:36:56.880
*** ACTION NAME:(0000008 STARTED98) 2013-01-25 09:36:56.880

No recovery needed for file 4, block 130
*** ACTION NAME:(0000009 STARTED180) 2013-01-25 09:36:56.898

OCI error val is 12514 and errmsg is 'ORA-12514: TNS:listener does not currently know of service requested in connect descriptor
'
ORA-17627: ORA-12514: TNS:listener does not currently know of service requested in connect descriptor
ORA-17629: Cannot connect to the remote database server

*** 2013-01-25 09:37:00.814
*** ACTION NAME:(0000026 STARTED98) 2013-01-25 09:37:00.814

No recovery needed for file 4, block 132
*** ACTION NAME:(0000027 STARTED180) 2013-01-25 09:37:00.818

OCI error val is 12514 and errmsg is 'ORA-12514: TNS:listener does not currently know of service requested in connect descriptor
'
ORA-17627: ORA-12514: TNS:listener does not currently know of service requested in connect descriptor
ORA-17629: Cannot connect to the remote database server

*** 2013-01-25 09:37:04.582
*** ACTION NAME:(0000045 STARTED180) 2013-01-25 09:37:04.582

OCI error val is 12514 and errmsg is 'ORA-12514: TNS:listener does not currently know of service requested in connect descriptor
'
ORA-17627: ORA-12514: TNS:listener does not currently know of service requested in connect descriptor
ORA-17629: Cannot connect to the remote database server
*** ACTION NAME:(0000048 STARTED169) 2013-01-25 09:37:04.624

Flashback async buffers are set to 16

*** 2013-01-25 09:37:04.653
*** MODULE NAME:(restore full datafile) 2013-01-25 09:37:04.797
*** ACTION NAME:(0000057 STARTED40) 2013-01-25 09:37:04.797

The input backup piece /u01/oradata/DG/FRA/DG/backupset/2013_01_25/o1_mf_nnndf_TAG20130125T090450_8j3pko2q_.bkp is in BASIC 11.2 compressed format.
krbr1b2b: saved block under name /u01/app/oracle/diag/rdbms/dg/DG/trace/4_131_0_997407.bkd

*** 2013-01-25 09:37:05.892
*** ACTION NAME:(0000062 STARTED104) 2013-01-25 09:37:05.892

Begin Media Recovery of 1 blocks
Dumping database incarnation table:
Resetlogs 0 scn and time: 0x0000.00375e2e 01/21/2013 18:27:03
Initial buffer sizes: read 1024K, overflow 832K, change 805K

*** 2013-01-25 09:37:05.921
Media Recovery add redo thread 1

*** 2013-01-25 09:37:06.632
Start recovery at thread 1 ckpt scn 4053936 logseq 66 block 22
End recovery at scn 4057058

*** 2013-01-25 09:37:06.633
Recovery of Online Redo Log: Thread 1 Group 3 Seq 66 Reading mem 0
Log read is SYNCHRONOUS though disk_asynch_io is enabled!

*** 2013-01-25 09:37:06.634
Recovery of Online Redo Log: Thread 1 Group 1 Seq 67 Reading mem 0
Log read is SYNCHRONOUS though disk_asynch_io is enabled!
----- Redo read statistics for thread 1 -----
Read rate (SYNC): 1754Kb in 0.72s => 2.38 Mb/sec
Total redo bytes: 2243Kb Longest record: 8Kb, moves: 0/2719 moved: 0Mb (0%)
Longest LWN: 45Kb, reads: 2138
Last redo scn: 0x0000.003de7e1 (4057057)
Change vector header moves = 250/5003 (4%)
----------------------------------------------

*** 2013-01-25 09:37:06.639
Media Recovery drop redo thread 1
Recovery of file 4, block 131 failed: Flashback was enabled for the data file when the backup data block used for block media recovery had an unlogged change.


-- Notice the message above mentioned about Flashback database log.



but still failed even I specify recover from backup set next.

RMAN> recover datafile 4 block 120 to 150 from backupset;

Starting recover at Jan 25 2013 11:13:08
using channel ORA_DISK_1
searching flashback logs for block images until SCN 4059153
finished flashback log search, restored 0 blocks

channel ORA_DISK_1: restoring block(s)
channel ORA_DISK_1: specifying block(s) to restore from backup set
restoring blocks of datafile 00004
channel ORA_DISK_1: reading from backup piece /u01/oradata/DG/FRA/DG/backupset/2013_01_25/o1_mf_nnndf_TAG20130125T095902_8j3sq92g_.bkp
channel ORA_DISK_1: piece handle=/u01/oradata/DG/FRA/DG/backupset/2013_01_25/o1_mf_nnndf_TAG20130125T095902_8j3sq92g_.bkp tag=TAG20130125T095902
channel ORA_DISK_1: restored block(s) from backup piece 1
channel ORA_DISK_1: block restore complete, elapsed time: 00:00:01

starting media recovery

archived log for thread 1 with sequence 71 is already on disk as file /u01/oradata/DG/FRA/DG/archivelog/2013_01_25/o1_mf_1_71_8j3ssp9t_.arc
archived log for thread 1 with sequence 72 is already on disk as file /u01/oradata/DG/FRA/DG/archivelog/2013_01_25/o1_mf_1_72_8j3vb6b7_.arc
archived log for thread 1 with sequence 73 is already on disk as file /u01/oradata/DG/FRA/DG/archivelog/2013_01_25/o1_mf_1_73_8j3vb942_.arc
some blocks not recovered: See trace file for details
media recovery complete, elapsed time: 00:00:01
Finished recover at Jan 25 2013 11:13:12

*** 2013-01-25 11:13:11.178
Media Recovery drop redo thread 1
Recovery of file 4, block 131 failed: Flashback was enabled for the data file when the backup data block used for block media recovery had an unlogged change.



It seems "from backupset" option is ignored.

7. Decided to turn off flashback database.

Use RMAN validate to detection corruption.


RMAN> backup validate check logical database archivelog all;

Starting backup at Jan 25 2013 11:46:55
allocated channel: ORA_DISK_1
channel ORA_DISK_1: SID=177 device type=DISK
channel ORA_DISK_1: starting compressed full datafile backup set
channel ORA_DISK_1: specifying datafile(s) in backup set
input datafile file number=00001 name=/u01/oradata/DG/system01.dbf
input datafile file number=00002 name=/u01/oradata/DG/sysaux01.dbf
input datafile file number=00003 name=/u01/oradata/DG/undotbs01.dbf
input datafile file number=00005 name=/u01/oradata/DG/dg1_tbs01.dbf
input datafile file number=00004 name=/u01/oradata/DG/users01.dbf
channel ORA_DISK_1: backup set complete, elapsed time: 00:00:25
List of Datafiles
=================
File Status Marked Corrupt Empty Blocks Blocks Examined High SCN
---- ------ -------------- ------------ --------------- ----------
1    OK     0              72657        131072          4072253
  File Name: /u01/oradata/DG/system01.dbf
  Block Type Blocks Failing Blocks Processed
  ---------- -------------- ----------------
  Data       0              46196
  Index      0              9615
  Other      0              2604

File Status Marked Corrupt Empty Blocks Blocks Examined High SCN
---- ------ -------------- ------------ --------------- ----------
2    OK     0              31772        76800           4072251
  File Name: /u01/oradata/DG/sysaux01.dbf
  Block Type Blocks Failing Blocks Processed
  ---------- -------------- ----------------
  Data       0              16664
  Index      0              17105
  Other      0              11259

File Status Marked Corrupt Empty Blocks Blocks Examined High SCN
---- ------ -------------- ------------ --------------- ----------
3    OK     0              22273        64000           4072253
  File Name: /u01/oradata/DG/undotbs01.dbf
  Block Type Blocks Failing Blocks Processed
  ---------- -------------- ----------------
  Data       0              0
  Index      0              0
  Other      0              41727

File Status Marked Corrupt Empty Blocks Blocks Examined High SCN
---- ------ -------------- ------------ --------------- ----------
4    FAILED 0              58           641             997400
  File Name: /u01/oradata/DG/users01.dbf
  Block Type Blocks Failing Blocks Processed
  ---------- -------------- ----------------
  Data       0              4
  Index      0              0
  Other      1              578

File Status Marked Corrupt Empty Blocks Blocks Examined High SCN
---- ------ -------------- ------------ --------------- ----------
5    OK     0              1137         1280            1019839
  File Name: /u01/oradata/DG/dg1_tbs01.dbf
  Block Type Blocks Failing Blocks Processed
  ---------- -------------- ----------------
  Data       0              10
  Index      0              0
  Other      0              133

validate found one or more corrupt blocks
See trace file /u01/app/oracle/diag/rdbms/dg/DG/trace/DG_ora_6564.trc for details
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=66 RECID=806 STAMP=805626360
input archived log thread=1 sequence=67 RECID=807 STAMP=805629038
input archived log thread=1 sequence=68 RECID=808 STAMP=805629040
input archived log thread=1 sequence=69 RECID=809 STAMP=805629534
input archived log thread=1 sequence=70 RECID=810 STAMP=805629536
input archived log thread=1 sequence=71 RECID=811 STAMP=805629622
input archived log thread=1 sequence=72 RECID=812 STAMP=805631174
input archived log thread=1 sequence=73 RECID=813 STAMP=805631177
input archived log thread=1 sequence=74 RECID=814 STAMP=805634089
input archived log thread=1 sequence=75 RECID=815 STAMP=805634091
input archived log thread=1 sequence=76 RECID=816 STAMP=805634206
input archived log thread=1 sequence=77 RECID=817 STAMP=805634207
channel ORA_DISK_1: backup set complete, elapsed time: 00:00:01
List of Archived Logs
=====================
Thrd Seq     Status Blocks Failing Blocks Examined Name
---- ------- ------ -------------- --------------- ---------------
1    66      OK     0              414             /u01/oradata/DG/FRA/DG/archivelog/2013_01_25/o1_mf_1_66_8j3pmr7p                                          _.arc
1    67      OK     0              4309            /u01/oradata/DG/FRA/DG/archivelog/2013_01_25/o1_mf_1_67_8j3s7g12                                          _.arc
1    68      OK     0              57              /u01/oradata/DG/FRA/DG/archivelog/2013_01_25/o1_mf_1_68_8j3s7j2t                                          _.arc
1    69      OK     0              943             /u01/oradata/DG/FRA/DG/archivelog/2013_01_25/o1_mf_1_69_8j3spyms                                          _.arc
1    70      OK     0              3               /u01/oradata/DG/FRA/DG/archivelog/2013_01_25/o1_mf_1_70_8j3sq0jy                                          _.arc
1    71      OK     0              95              /u01/oradata/DG/FRA/DG/archivelog/2013_01_25/o1_mf_1_71_8j3ssp9t                                          _.arc
1    72      OK     0              7119            /u01/oradata/DG/FRA/DG/archivelog/2013_01_25/o1_mf_1_72_8j3vb6b7                                          _.arc
1    73      OK     0              102             /u01/oradata/DG/FRA/DG/archivelog/2013_01_25/o1_mf_1_73_8j3vb942                                          _.arc
1    74      OK     0              8668            /u01/oradata/DG/FRA/DG/archivelog/2013_01_25/o1_mf_1_74_8j3y593l                                          _.arc
1    75      OK     0              100             /u01/oradata/DG/FRA/DG/archivelog/2013_01_25/o1_mf_1_75_8j3y5c8p                                          _.arc
1    76      OK     0              482             /u01/oradata/DG/FRA/DG/archivelog/2013_01_25/o1_mf_1_76_8j3y8yjj                                          _.arc
1    77      OK     0              75              /u01/oradata/DG/FRA/DG/archivelog/2013_01_25/o1_mf_1_77_8j3y8z11                                          _.arc
channel ORA_DISK_1: starting compressed 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: backup set complete, elapsed time: 00:00:01
List of Control File and SPFILE
===============================
File Type    Status Blocks Failing Blocks Examined
------------ ------ -------------- ---------------
SPFILE       OK     0              2
Control File OK     0              624
Finished backup at Jan 25 2013 11:47:26


RMAN> shutdown immediate

database closed
database dismounted
Oracle instance shut down

RMAN> startup mount

connected to target database (not started)
Oracle instance started
database mounted

Total System Global Area     680607744 bytes

Fixed Size                     2229600 bytes
Variable Size                419433120 bytes
Database Buffers             251658240 bytes
Redo Buffers                   7286784 bytes

RMAN> exit


Recovery Manager complete.
orarac1poc:DG:/home/oracle/ops/logs> sqlplus / as sysdba

SQL*Plus: Release 11.2.0.2.0 Production on Fri Jan 25 11:50:18 2013

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


Connected to:
Oracle Database 11g Enterprise Edition Release 11.2.0.2.0 - 64bit Production
With the Partitioning, Real Application Clusters, OLAP, Data Mining
and Real Application Testing options

SYS@DG> select flashback_on from v$database;

FLASHBACK_ON
------------------
YES

SYS@DG> alter database flashback off;

Database altered.

SYS@DG> select flashback_on from v$database;

FLASHBACK_ON
------------------
NO

SYS@DG> exit
Disconnected from Oracle Database 11g Enterprise Edition Release 11.2.0.2.0 - 64bit Production
With the Partitioning, Real Application Clusters, OLAP, Data Mining
and Real Application Testing options
orarac1poc:DG:/home/oracle/ops/logs> rman target / catalog rman/rman123@RCAT

Recovery Manager: Release 11.2.0.2.0 - Production on Fri Jan 25 11:50:49 2013

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

connected to target database: DG (DBID=1716975309, not open)
connected to recovery catalog database

RMAN> recover datafile 4 block 131 from backupset;

Starting recover at Jan 25 2013 11:51:02
allocated channel: ORA_DISK_1
channel ORA_DISK_1: SID=143 device type=DISK

channel ORA_DISK_1: restoring block(s)
channel ORA_DISK_1: specifying block(s) to restore from backup set
restoring blocks of datafile 00004
channel ORA_DISK_1: reading from backup piece /u01/oradata/DG/FRA/DG/backupset/2013_01_25/o1_mf_nnndf_TAG20130125T0                                          95902_8j3sq92g_.bkp
channel ORA_DISK_1: piece handle=/u01/oradata/DG/FRA/DG/backupset/2013_01_25/o1_mf_nnndf_TAG20130125T095902_8j3sq92                                          g_.bkp tag=TAG20130125T095902
channel ORA_DISK_1: restored block(s) from backup piece 1
channel ORA_DISK_1: block restore complete, elapsed time: 00:00:01

starting media recovery

archived log for thread 1 with sequence 71 is already on disk as file /u01/oradata/DG/FRA/DG/archivelog/2013_01_25/                                          o1_mf_1_71_8j3ssp9t_.arc
archived log for thread 1 with sequence 72 is already on disk as file /u01/oradata/DG/FRA/DG/archivelog/2013_01_25/                                          o1_mf_1_72_8j3vb6b7_.arc
archived log for thread 1 with sequence 73 is already on disk as file /u01/oradata/DG/FRA/DG/archivelog/2013_01_25/                                          o1_mf_1_73_8j3vb942_.arc
archived log for thread 1 with sequence 74 is already on disk as file /u01/oradata/DG/FRA/DG/archivelog/2013_01_25/                                          o1_mf_1_74_8j3y593l_.arc
archived log for thread 1 with sequence 75 is already on disk as file /u01/oradata/DG/FRA/DG/archivelog/2013_01_25/                                          o1_mf_1_75_8j3y5c8p_.arc
archived log for thread 1 with sequence 76 is already on disk as file /u01/oradata/DG/FRA/DG/archivelog/2013_01_25/                                          o1_mf_1_76_8j3y8yjj_.arc
archived log for thread 1 with sequence 77 is already on disk as file /u01/oradata/DG/FRA/DG/archivelog/2013_01_25/                                          o1_mf_1_77_8j3y8z11_.arc
media recovery complete, elapsed time: 00:00:06
Finished recover at Jan 25 2013 11:51:11



Finally, I see the right message .

RMAN> open database;

database opened

RMAN> exit


Recovery Manager complete.
orarac1poc:DG:/home/oracle/ops/logs> sqlplus / as sysdba

SQL*Plus: Release 11.2.0.2.0 Production on Fri Jan 25 11:51:49 2013

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


Connected to:
Oracle Database 11g Enterprise Edition Release 11.2.0.2.0 - 64bit Production
With the Partitioning, Real Application Clusters, OLAP, Data Mining
and Real Application Testing options

SYS@DG> select * from v$database_block_corruption;

no rows selected

SYS@DG> select * from liqy.t1 ;

        F1
----------
         1

SYS@DG> exit
Disconnected from Oracle Database 11g Enterprise Edition Release 11.2.0.2.0 - 64bit Production
With the Partitioning, Real Application Clusters, OLAP, Data Mining
and Real Application Testing options
orarac1poc:DG:/home/oracle/ops/logs> dbv file=/u01/oradata/DG/users01.dbf blocksize=8192                                                                    
DBVERIFY: Release 11.2.0.2.0 - Production on Fri Jan 25 11:52:12 2013

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

DBVERIFY - Verification starting : FILE = /u01/oradata/DG/users01.dbf


DBVERIFY - Verification complete

Total Pages Examined         : 640
Total Pages Processed (Data) : 5
Total Pages Failing   (Data) : 0
Total Pages Processed (Index): 0
Total Pages Failing   (Index): 0
Total Pages Processed (Other): 577
Total Pages Processed (Seg)  : 0
Total Pages Failing   (Seg)  : 0
Total Pages Empty            : 58
Total Pages Marked Corrupt   : 0
Total Pages Influx           : 0
Total Pages Encrypted        : 0
Highest block SCN            : 997407 (0.997407)



8. Findings & Conclusion

8.1 It seems with flashback database on, there is problem to recover 1st table block with RMAN block recover.

8.2  Something wrong with Oracle design,  trying to use flashback log to recover media (physical block) courruption  by dd command (human mistaken), and it ignores "from backupset " option.

Bugs here ?

No comments:

Post a Comment