上篇中我們著重討論了Log File的Invalid狀態，現在我們研究一下這種狀態如果進行處理，會對資料庫有何種影響。

4、Invalid狀態日誌對Startup作用

Online Redo Log對於資料庫啟動起到至關重要的作用。如果在關閉的時候是一個不完全的過程，Oracle在mount到open的過程中，是需要日誌進行Instance Recovery的。即使不需要進行Instance Recovery，Oracle也會在啟動時候檢查日誌檔案的狀態和一致性。

繼上篇的實驗繼續，整理狀態如下：

SQL> select group#, sequence#, members, status, first_change#, next_change# from v$log;

GROUP# SEQUENCE# MEMBERS STATUS FIRST_CHANGE# NEXT_CHANGE#

---------- ---------- ---------- ---------------- ------------- ------------

1 79 4 ACTIVE 1603673 1603724

2 80 2 CURRENT 1603724 281474976710

3 78 2 ACTIVE 1603669 1603673

為了增加嚴重性，我們向current新增Invalid日誌。

SQL> alter database add logfile member '/u01/flash_recovery_area/WILSON/onlinelog/redolog02a.log' to group 2;

Database altered

SQL> select group#, sequence#, members, status, first_change#, next_change# from v$log;

GROUP# SEQUENCE# MEMBERS STATUS FIRST_CHANGE# NEXT_CHANGE#

---------- ---------- ---------- ---------------- ------------- ------------

1 79 4 ACTIVE 1603673 1603724

2 80 3 CURRENT 1603724 281474976710

3 78 2 ACTIVE 1603669 1603673

SQL> select group#, status, type, member from v$logfile;

GROUP# STATUS TYPE MEMBER

---------- ------- ------- --------------------------------------------------------------------------------

（篇幅原因，省略部分……）

1 ONLINE /u01/flash_recovery_area/WILSON/onlinelog/redolog01b.log

2 INVALID ONLINE /u01/flash_recovery_area/WILSON/onlinelog/redolog02a.log

9 rows selected

重啟資料庫，觀察情況。

SQL> conn / as sysdba

Connected.

SQL> shutdown immediate;

Database closed.

Database dismounted.

ORACLE instance shut down.

SQL> startup

ORACLE instance started.

Total System Global Area 849530880 bytes

Fixed Size 1339824 bytes

Variable Size 536874576 bytes

Database Buffers 306184192 bytes

Redo Buffers 5132288 bytes

Database mounted.

Database opened.

啟動成功，此時日誌和日誌組情況如下：

SQL> select group#, sequence#, members, status, first_change#, next_change# from v$log;

Warning: connection was lost and re-established

GROUP# SEQUENCE# MEMBERS STATUS FIRST_CHANGE# NEXT_CHANGE#

---------- ---------- ---------- ---------------- ------------- ------------

1 79 4 INACTIVE 1603673 1603724

2 80 3 CURRENT 1603724 281474976710

3 78 2 INACTIVE 1603669 1603673

SQL> select group#, status, type, member from v$logfile;

GROUP# STATUS TYPE MEMBER

---------- ------- ------- --------------------------------------------------------------------------------

（篇幅原因，省略……）

1 ONLINE /u01/flash_recovery_area/WILSON/onlinelog/redolog01b.log

2 INVALID ONLINE /u01/flash_recovery_area/WILSON/onlinelog/redolog02a.log

9 rows selected

這個過程幾個問題需要注意：首先Oracle雖然日誌組成員出現Invalid狀態，但是還是啟動了，明顯是利用正確的日誌成員。其次是啟動之後，檔案的Invalid狀態沒有變化。

在alert log中，我們的確看到了這個引起的問題。

Mon Sep 10 04:18:12 2012

ALTER DATABASE OPEN

LGWR: STARTING ARCH PROCESSES

Mon Sep 10 04:18:12 2012

ARC0 started with pid=20, OS id=4600

ARC0: Archival started

LGWR: STARTING ARCH PROCESSES COMPLETE

ARC0: STARTING ARCH PROCESSES

Errors in file /u01/diag/rdbms/wilson/wilson/trace/wilson_lgwr_4483.trc:

ORA-00313: open failed for members of log group 2 of thread 1

Errors in file /u01/diag/rdbms/wilson/wilson/trace/wilson_lgwr_4483.trc:

ORA-00313: open failed for members of log group 2 of thread 1

Thread 1 opened at log sequence 80

Current log# 2 seq# 80 mem# 0: /u01/oradata/WILSON/onlinelog/o1_mf_2_7xt44w3k_.log

Current log# 2 seq# 80 mem# 1: /u01/flash_recovery_area/WILSON/onlinelog/o1_mf_2_7xt450rv_.log

Successful open of redo thread 1

MTTR advisory is disabled because FAST_START_MTTR_TARGET is not set

Mon Sep 10 04:18:14 2012

ARC2 started with pid=23, OS id=4612

Oracle在啟動的時候，從mount到open狀態中的確發現了當前日誌Current組成員的問題，並且報錯ORA_00313錯誤。之後，Oracle就是用了正確的兩個成員mem#0和mem#1啟動，拋棄了那個錯誤的日誌檔案。

在輸出的Dump檔案中，我們找到如下過程：

[oracle@bspdev trace]$ pwd

/u01/diag/rdbms/wilson/wilson/trace

[oracle@bspdev trace]$ ls -l | grep wilson_lgwr_4483.trc

-rw-r----- 1 oracle oinstall 1451 Sep 10 04:18 wilson_lgwr_4483.trc

[oracle@bspdev trace]$ cat wilson_lgwr_4483.trc

Trace file /u01/diag/rdbms/wilson/wilson/trace/wilson_lgwr_4483.trc

Oracle Database 11g Enterprise Edition Release 11.2.0.1.0 - Production

With the Partitioning, OLAP, Data Mining and Real Application Testing options

ORACLE_HOME = /u01/oracle

System name: Linux

Node name: bspdev.localdomain

Release: 2.6.18-308.el5

Version: #1 SMP Tue Feb 21 20:05:41 EST 2012

Machine: i686

Instance name: wilson

Redo thread mounted by this instance: 1

Oracle process number: 11

Unix process pid: 4483, image: oracle@bspdev.localdomain (LGWR)

*** 2012-09-10 04:18:13.977

*** SESSION ID:(11.1) 2012-09-10 04:18:13.977

*** CLIENT ID:() 2012-09-10 04:18:13.977

*** SERVICE NAME:() 2012-09-10 04:18:13.977

*** MODULE NAME:() 2012-09-10 04:18:13.977

*** ACTION NAME:() 2012-09-10 04:18:13.977

DDE rules only execution for: ORA 313

----- START Event Driven Actions Dump ----

---- END Event Driven Actions Dump ----

----- START DDE Actions Dump -----

Executing SYNC actions

----- START DDE Action: 'DB_STRUCTURE_INTEGRITY_CHECK' (Async) -----

Successfully dispatched

----- END DDE Action: 'DB_STRUCTURE_INTEGRITY_CHECK' (SUCCESS, 0 csec) -----

Executing ASYNC actions

----- END DDE Actions Dump (total 0 csec) -----

ORA-00313: open failed for members of log group 2 of thread 1

DDE: Problem Key 'ORA 313' was flood controlled (0x1) (no incident)

ORA-00313: open failed for members of log group 2 of thread 1

[oracle@bspdev trace]$

[oracle@bspdev trace]$ oerr ora 313

00313, 00000, "open failed for members of log group %s of thread %s"

// *Cause: The online log cannot be opened. May not be able to find file.

// *Action: See accompanying errors and make log available.

[oracle@bspdev trace]$

上面Dump的Trace檔案中，說明在oracle進行啟動過程中，進行了資料庫結構完整性檢查。這個中間發現了日誌檔案的不一致，報錯之後，使用正確的檔案啟動資料庫。

那麼，最後討論一下，這個Invalid狀態到底記錄在哪裡？Invalid在庫啟動之後就出現了。可以驗證的方面只有兩個，控制檔案或者Redo log檔案頭。下面我們透過簡單實驗證明。

5、Invalid狀態來源

雖然Redo Log狀態是Invalid，但是如果在Invalid的檔案頭中記錄這個，就意味著：如果我們使用相同的日誌檔案，只是複製過去，和正常檔案相同時候，看看啟動是否報錯。

SQL> shutdown immediate;

Database closed.

Database dismounted.

ORACLE instance shut down.

SQL>

[oracle@bspdev trace]$ cd /u01/flash_recovery_area/WILSON/onlinelog/

[oracle@bspdev onlinelog]$ ls -l

total 307560

-rw-r----- 1 oracle oinstall 52429312 Sep 10 04:18 o1_mf_1_7xt44qt6_.log

-rw-r----- 1 oracle oinstall 52429312 Sep 10 04:27 o1_mf_2_7xt450rv_.log

-rw-r----- 1 oracle oinstall 52429312 Sep 10 04:18 o1_mf_3_7xt45bvp_.log

-rw-r----- 1 oracle oinstall 52429312 Sep 10 04:18 redolog01a.log

-rw-r----- 1 oracle oinstall 52429312 Sep 10 04:18 redolog01b.log

-rw-r----- 1 oracle oinstall 52429312 Sep 10 04:16 redolog02a.log

[oracle@bspdev onlinelog]$ cp /u01/oradata/WILSON/onlinelog/o1_mf_2_7xt44w3k_.log /u01/flash_recovery_area/WILSON/onlinelog/redolog02a.log

[oracle@bspdev onlinelog]$ ls -l

total 307560

-rw-r----- 1 oracle oinstall 52429312 Sep 10 04:18 o1_mf_1_7xt44qt6_.log

-rw-r----- 1 oracle oinstall 52429312 Sep 10 04:27 o1_mf_2_7xt450rv_.log

-rw-r----- 1 oracle oinstall 52429312 Sep 10 04:18 o1_mf_3_7xt45bvp_.log

-rw-r----- 1 oracle oinstall 52429312 Sep 10 04:18 redolog01a.log

-rw-r----- 1 oracle oinstall 52429312 Sep 10 04:18 redolog01b.log

-rw-r----- 1 oracle oinstall 52429312 Sep 10 04:28 redolog02a.log

複製之後，重新啟動。

SQL> startup

ORACLE instance started.

Total System Global Area 849530880 bytes

Fixed Size 1339824 bytes

Variable Size 536874576 bytes

Database Buffers 306184192 bytes

Redo Buffers 5132288 bytes

Database mounted.

Database opened.

--Alert Log中

ALTER DATABASE OPEN

LGWR: STARTING ARCH PROCESSES

Mon Sep 10 04:29:23 2012

ARC0 started with pid=20, OS id=5005

ARC0: Archival started

LGWR: STARTING ARCH PROCESSES COMPLETE

ARC0: STARTING ARCH PROCESSES

Errors in file /u01/diag/rdbms/wilson/wilson/trace/wilson_lgwr_4888.trc:

ORA-00313: open failed for members of log group 2 of thread 1

Errors in file /u01/diag/rdbms/wilson/wilson/trace/wilson_lgwr_4888.trc:

ORA-00313: open failed for members of log group 2 of thread 1

Thread 1 opened at log sequence 80

Current log# 2 seq# 80 mem# 0: /u01/oradata/WILSON/onlinelog/o1_mf_2_7xt44w3k_.log

Current log# 2 seq# 80 mem# 1: /u01/flash_recovery_area/WILSON/onlinelog/o1_mf_2_7xt450rv_.log

啟動之後，檔案的狀態依舊為Invalid。

SQL> select group#,status from v$logfile;

GROUP# STATUS

---------- -------

3

2

1

2 INVALID

9 rows selected.

SQL> select group#, status from v$log;

GROUP# STATUS

---------- ----------------

1 INACTIVE

3 INACTIVE

2 CURRENT

那麼，我們就可以得出初步的猜想：Invalid狀態是記錄在控制檔案中的。

下面是筆者正常啟動的日誌片段。

Mon Sep 10 04:51:22 2012

ALTER DATABASE OPEN

Beginning crash recovery of 1 threads

Started redo scan

Completed redo scan

read 31 KB redo, 21 data blocks need recovery

Started redo application at

Thread 1: logseq 81, block 346

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

Mem# 0: /u01/oradata/WILSON/onlinelog/o1_mf_3_7xt456o0_.log

Mem# 1: /u01/flash_recovery_area/WILSON/onlinelog/o1_mf_3_7xt45bvp_.log

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

Mem# 0: /u01/oradata/WILSON/onlinelog/o1_mf_1_7xt44nq1_.log

Mem# 1: /u01/flash_recovery_area/WILSON/onlinelog/o1_mf_1_7xt44qt6_.log

Completed redo application of 0.01MB

Completed crash recovery at

Thread 1: logseq 82, block 25, scn 1625420

21 data blocks read, 21 data blocks written, 31 redo k-bytes read

LGWR: STARTING ARCH PROCESSES

Mon Sep 10 04:51:23 2012

ARC0 started with pid=20, OS id=5802

ARC0: Archival started

LGWR: STARTING ARCH PROCESSES COMPLETE

ARC0: STARTING ARCH PROCESSES

Thread 1 advanced to log sequence 83 (thread open)

Thread 1 opened at log sequence 83

Current log# 2 seq# 83 mem# 0: /u01/oradata/WILSON/onlinelog/o1_mf_2_7xt44w3k_.log

Current log# 2 seq# 83 mem# 1: /u01/flash_recovery_area/WILSON/onlinelog/o1_mf_2_7xt450rv_.log

Successful open of redo thread 1

Mon Sep 10 04:51:24 2012

ARC1 started with pid=21, OS id=5806

Mon Sep 10 04:51:24 2012

ARC2 started with pid=22, OS id=5810

Mon Sep 10 04:51:24 2012

ARC3 started with pid=23, OS id=5814

6、結論

本篇中，我們討論了Invalid日誌檔案的一些特徵和處理方法。在正常情況下，我們是不鼓勵系統出現Invalid日誌檔案的。這樣會給系統帶來很多潛在的問題。我們一般推薦一次性將所有成員建立完成，或者在新增日誌成員之後，手工switch log，消除Invalid現象。

談談Oracle日誌檔案的INVALID狀態（下）

相關文章