掉電引起的ORA-1172錯誤解決過程（一）

由於UPS故障，導致機房連續多次掉電，問題解決後，發現一臺本地測試資料庫開啟時報錯，ORA-1172、ORA-1151錯誤。

 

 

同事告訴我一臺資料庫無法開啟，只能啟動到MOUNT狀態，於是連線資料庫嘗試開啟，報錯如下：

SQL> alter database open;
alter database open
*
ERROR at line 1:
ORA-01172: recovery of thread 1 stuck at block 1669 of file 2
ORA-01151: use media recovery to recover block, restore backup if needed

看來資料檔案已經出現了壞塊，估計需要透過備份來恢復了。檢查了一下資料庫的基本情況，發現雖然資料庫處於歸檔模式下，但是卻沒有做過備份。這也難怪，畢竟這個資料庫只是一個本地的測試環境。

根據錯誤提示，可以到了對資料庫進行一下恢復。不過為了穩妥起見，還是先將整個資料庫環境進行一下備份。這樣即使恢復過程出現了問題，至少可以將資料庫恢復到最終的狀態，不至於將問題變得更加糟糕，而且最重要的是，有了這個可恢復的現場，可以對恢復進行多次嘗試。

備份完成後，仔細檢查了一下資料庫的alert檔案，發現問題還真是不少：

Completed: ALTER DATABASE   MOUNT
Thu Jun  5 14:05:10 2008
ALTER DATABASE OPEN
Thu Jun  5 14:05:11 2008
Beginning crash recovery of 1 threads
 parallel recovery started with 7 processes
Thu Jun  5 14:05:11 2008
Started redo scan
Thu Jun  5 14:05:11 2008
Completed redo scan
 23473 redo blocks read, 49 data blocks need recovery
Thu Jun  5 14:05:11 2008
Started redo application at
 Thread 1: logseq 525, block 2, scn 6533560108
Thu Jun  5 14:05:11 2008
Recovery of Online Redo Log: Thread 1 Group 2 Seq 525 Reading mem 0
  Mem# 0: /data/oradata/test08/redo02.log
Thu Jun  5 14:05:11 2008
RECOVERY OF THREAD 1 STUCK AT BLOCK 21 OF FILE 2
Thu Jun  5 14:05:11 2008
RECOVERY OF THREAD 1 STUCK AT BLOCK 1669 OF FILE 2
Thu Jun  5 14:05:11 2008
RECOVERY OF THREAD 1 STUCK AT BLOCK 813 OF FILE 2
Thu Jun  5 14:05:11 2008
Completed redo application
Thu Jun  5 14:05:11 2008
Hex dump of (file 3, block 21009) in trace file /opt/ora10g/admin/test08/bdump/test08_p000_4369.trc
Corrupt block relative dba: 0x00c05211 (file 3, block 21009)
Fractured block found during crash/instance recovery
Data in bad block:
 type: 6 format: 2 rdba: 0x00c05211
 last change scn: 0x0001.8570a63d seq: 0x2 flg: 0x06
 spare1: 0x0 spare2: 0x0 spare3: 0x0
 consistency value in tail: 0xe8520602
 check value in block header: 0xf307
 computed block checksum: 0xe6c
Reread of rdba: 0x00c05211 (file 3, block 21009) found same corrupted data
Thu Jun  5 14:05:15 2008
Errors in file /opt/ora10g/admin/test08/bdump/test08_p002_4373.trc:
ORA-01172: recovery of thread 1 stuck at block 813 of file 2
ORA-01151: use media recovery to recover block, restore backup if needed
Thu Jun  5 14:05:15 2008
Errors in file /opt/ora10g/admin/test08/bdump/test08_p001_4371.trc:
ORA-10388: parallel query server interrupt (failure)
Thu Jun  5 14:05:15 2008
Errors in file /opt/ora10g/admin/test08/bdump/test08_p004_4377.trc:
ORA-10388: parallel query server interrupt (failure)
Thu Jun  5 14:05:15 2008
Errors in file /opt/ora10g/admin/test08/bdump/test08_p005_4379.trc:
ORA-10388: parallel query server interrupt (failure)
Thu Jun  5 14:05:15 2008
Errors in file /opt/ora10g/admin/test08/bdump/test08_p005_4379.trc:
ORA-01578: ORACLE data block corrupted (file # 1, block # 1895)
ORA-01110: data file 1: '/data/oradata/test08/system01.dbf'
ORA-10564: tablespace SYSTEM
ORA-01110: data file 1: '/data/oradata/test08/system01.dbf'
ORA-10561: block type 'TRANSACTION MANAGED DATA BLOCK', data object# 482
ORA-10388: parallel query server interrupt (failure)
Thu Jun  5 14:05:15 2008
Aborting crash recovery due to slave death, attempting serial crash recovery
Thu Jun  5 14:05:15 2008
Beginning crash recovery of 1 threads
Thu Jun  5 14:05:15 2008
Started redo scan
Thu Jun  5 14:05:15 2008
Completed redo scan
 23473 redo blocks read, 49 data blocks need recovery
Thu Jun  5 14:05:15 2008
Started redo application at
 Thread 1: logseq 525, block 2, scn 6533560108
Thu Jun  5 14:05:15 2008
Recovery of Online Redo Log: Thread 1 Group 2 Seq 525 Reading mem 0
  Mem# 0: /data/oradata/test08/redo02.log
Hex dump of (file 3, block 21009) in trace file /opt/ora10g/admin/test08/udump/test08_ora_4367.trc
Corrupt block relative dba: 0x00c05211 (file 3, block 21009)
Fractured block found during crash/instance recovery
Data in bad block:
 type: 6 format: 2 rdba: 0x00c05211
 last change scn: 0x0001.8570a63d seq: 0x2 flg: 0x06
 spare1: 0x0 spare2: 0x0 spare3: 0x0
 consistency value in tail: 0xe8520602
 check value in block header: 0xf307
 computed block checksum: 0xe6c
Reread of rdba: 0x00c05211 (file 3, block 21009) found same corrupted data
RECOVERY OF THREAD 1 STUCK AT BLOCK 1669 OF FILE 2
Thu Jun  5 14:05:15 2008
Aborting crash recovery due to error 1172
Thu Jun  5 14:05:15 2008
Errors in file /opt/ora10g/admin/test08/udump/test08_ora_4367.trc:
ORA-01172: recovery of thread 1 stuck at block 1669 of file 2
ORA-01151: use media recovery to recover block, restore backup if needed
ORA-1172 signalled during: ALTER DATABASE OPEN...

原本看到問題出在UNDO表空間時，覺得問題還不算太嚴重，因為如果是UNDO表空間的話，畢竟可以透過隱含引數嘗試強行RESETLOG開啟資料庫，雖然會丟失一些資料，並導致資料庫出現不一致的狀態，但是資料庫是可以開啟的，由於是測試資料庫，丟失部分資料和資料庫狀態不一致都是可以接受的。

但是從alert檔案看，SYSTEM表空間的資料檔案居然也出現了壞塊，看來問題不是那麼簡單了。

下面只能碰碰運氣了：

SQL> recover database;
Media recovery complete.

這一步倒是比較順利，下面看看能不能直接開啟。不過很懷疑能否這麼輕易的解決這個問題：

SQL> alter database open;
alter database open
*
ERROR at line 1:
ORA-03113: end-of-file on communication channel

果然不出所料，問題沒有那麼輕易的解決，資料庫開啟過程中出現了ORA-3113錯誤，看看alert檔案中到底出現了什麼問題：

ALTER DATABASE RECOVER  database 
Thu Jun  5 15:33:16 2008
Media Recovery Start
 parallel recovery started with 7 processes
Thu Jun  5 15:33:17 2008
Recovery of Online Redo Log: Thread 1 Group 2 Seq 525 Reading mem 0
  Mem# 0: /data/oradata/test08/redo02.log
Thu Jun  5 15:33:18 2008
Hex dump of (file 2, block 1095) in trace file /opt/ora10g/admin/test08/bdump/test08_p004_6330.trc
Corrupt block relative dba: 0x00800447 (file 2, block 1095)
Fractured block found during media recovery
Data in bad block:
 type: 2 format: 2 rdba: 0x00800447
 last change scn: 0x0001.81e8f3ea seq: 0x1 flg: 0x04
 spare1: 0x0 spare2: 0x0 spare3: 0x0
 consistency value in tail: 0x3f380250
 check value in block header: 0x43df
 computed block checksum: 0x696b
Reread of rdba: 0x00800447 (file 2, block 1095) found same corrupted data
Thu Jun  5 15:33:18 2008
Hex dump of (file 3, block 4417) in trace file /opt/ora10g/admin/test08/bdump/test08_p000_6322.trc
Corrupt block relative dba: 0x00c01141 (file 3, block 4417)
Fractured block found during media recovery
Data in bad block:
 type: 6 format: 2 rdba: 0x00c01141
 last change scn: 0x0001.856e4319 seq: 0x1 flg: 0x06
 spare1: 0x0 spare2: 0x0 spare3: 0x0
 consistency value in tail: 0x87540601
 check value in block header: 0x4a80
 computed block checksum: 0x3564
Reread of rdba: 0x00c01141 (file 3, block 4417) found same corrupted data
.
.
.
Hex dump of (file 3, block 36842) in trace file /opt/ora10g/admin/test08/bdump/test08_p006_6334.trc
Corrupt block relative dba: 0x00c08fea (file 3, block 36842)
Fractured block found during media recovery
Data in bad block:
 type: 6 format: 2 rdba: 0x00c08fea
 last change scn: 0x0001.856e421e seq: 0x1 flg: 0x06
 spare1: 0x0 spare2: 0x0 spare3: 0x0
 consistency value in tail: 0xef620601
 check value in block header: 0x7673
 computed block checksum: 0xac7e
Reread of rdba: 0x00c08fea (file 3, block 36842) found same corrupted data
Thu Jun  5 15:33:20 2008
Media Recovery Complete (test08)
Thu Jun  5 15:33:21 2008
Completed: ALTER DATABASE RECOVER  database 
Thu Jun  5 15:33:30 2008
alter database open
Thu Jun  5 15:33:31 2008
Beginning crash recovery of 1 threads
 parallel recovery started with 7 processes
Thu Jun  5 15:33:31 2008
Started redo scan
Thu Jun  5 15:33:31 2008
Completed redo scan
 23473 redo blocks read, 0 data blocks need recovery
Thu Jun  5 15:33:31 2008
Started redo application at
 Thread 1: logseq 525, block 2, scn 6533560108
Thu Jun  5 15:33:31 2008
Recovery of Online Redo Log: Thread 1 Group 2 Seq 525 Reading mem 0
  Mem# 0: /data/oradata/test08/redo02.log
Thu Jun  5 15:33:31 2008
Completed redo application
Thu Jun  5 15:33:31 2008
Completed crash recovery at
 Thread 1: logseq 525, block 23475, scn 6533584244
 0 data blocks read, 0 data blocks written, 23473 redo blocks read
Thu Jun  5 15:33:31 2008
LGWR: STARTING ARCH PROCESSES
ARC0 started with pid=23, OS id=6336
Thu Jun  5 15:33:31 2008
ARC0: Archival started
ARC1 started with pid=24, OS id=6338
Thu Jun  5 15:33:31 2008
ARC1: Archival started
LGWR: STARTING ARCH PROCESSES COMPLETE
Thread 1 advanced to log sequence 526
Thread 1 opened at log sequence 526
  Current log# 3 seq# 526 mem# 0: /data/oradata/test08/redo03.log
Successful open of redo thread 1
Thu Jun  5 15:33:31 2008
ARC1: Becoming the 'no FAL' ARCH
ARC1: Becoming the 'no SRL' ARCH
Thu Jun  5 15:33:31 2008
ARC0: Becoming the heartbeat ARCH
Thu Jun  5 15:33:31 2008
MTTR advisory is disabled because FAST_START_MTTR_TARGET is not set
Thu Jun  5 15:33:31 2008
SMON: enabling cache recovery
Thu Jun  5 15:33:33 2008
Errors in file /opt/ora10g/admin/test08/udump/test08_ora_5406.trc:
ORA-00600: internal error code, arguments: [2662], [1], [2238616959], [1], [2238756337], [8388637], [], []
Thu Jun  5 15:33:35 2008
Errors in file /opt/ora10g/admin/test08/udump/test08_ora_5406.trc:
ORA-00600: internal error code, arguments: [2662], [1], [2238616959], [1], [2238756337], [8388637], [], []
Thu Jun  5 15:33:35 2008
Error 600 happened during db open, shutting down database
USER: terminating instance due to error 600
Instance terminated by USER, pid = 5406
ORA-1092 signalled during: alter database open...

開啟的過程中出現了ORA-600 [2662]的錯誤，看到這個錯誤後放了一半的心，因為前一陣處理過一個類似的錯誤，由於現在的SCN比資料庫中的SCN要小，可以透過甚至EVENTS的方式來增大當前SCN，關於更多的描述可以參考：ORA-600(2662)錯誤的重現和解決（一）：http://yangtingkun.itpub.net/post/468/464682和ORA-600(2662)錯誤的重現和解決（二）：http://yangtingkun.itpub.net/post/468/464701