standby open read only 出錯的處理過程

 

昨天一備份資料庫,在open? read? only的過程中出現故障，從而導致在standby上備份失敗。alert log 中資訊如下：

Errors in file /opt/oracle/admin/crmhz/udump/crmhz_ora_13914.trc:
ORA-00604: error occurred at recursive SQL level 1
ORA-16000: database open for read-only access
Error 604 happened during db open, shutting down database
USER: terminating instance due to error 604
Instance terminated by USER, pid = 13914
ORA-1092 signalled during: alter database open read only...
Tue Aug 10 09:31:51 2004

再查看trace file資訊

[root@crmsb bdump]# more?? /opt/oracle/admin/crmhz/udump/crmhz_ora_13914.trc
/opt/oracle/admin/crmhz/udump/crmhz_ora_13914.trc
Oracle9i Enterprise Edition Release 9.2.0.1.0 - Production
With the Partitioning, OLAP and Oracle Data Mining options
JServer Release 9.2.0.1.0 - Production
ORACLE_HOME = /opt/oracle/product/9.2.0
System name:??? Linux
Node name:????? crmsb
Release:??????? 2.4.9-e.3smp
Version:??????? #1 SMP Fri May 3 16:48:54 EDT 2002
Machine:??????? i686
Instance name: crmhz
Redo thread mounted by this instance: 1
Oracle process number: 11
Unix process pid: 13914, image: oracle@crmsb (TNS V1-V3)

*** SESSION ID:(10.3) 2004-08-10 09:30:37.408
*** 2004-08-10 09:30:37.408
Managed Recovery: Cancel posted.
ORA-00604: error occurred at recursive SQL level 1
ORA-16000: database open for read-only access

 

都沒有提供什麼有價值的資訊，很奇怪會出現604錯誤

於是決定trace? open過程

startup  nomount

alter database mount standby? database;

select  sid from v$mystat where rownum = 1;

select  sid,serial# from v$session where sid = ?;

exec  dbms_system.set_ev(sid,serial#,10046,12,'');

alter database  open  read  only;

這是資料庫crash ,找到trace file，發現末尾部分為

 

select grantee#,privilege#,nvl(col#,0),max(mod(nvl(option$,0),2))from objauth$ where obj#=:1 group by grantee#,privilege#,nvl(col#,0) order by grantee#
END OF STMT
PARSE #13:c=0,e=485,p=0,cr=0,cu=0,mis=1,r=0,dep=2,og=0,tim=1066522815818430
BINDS #13:
?bind 0: dty=2 mxl=22(22) mal=00 scl=00 pre=00 oacflg=08 oacfl2=1 size=24 offset=0
?? bfp=40647620 bln=22 avl=02 flg=05
?? value=72
EXEC #13:c=0,e=518,p=0,cr=0,cu=0,mis=0,r=0,dep=2,og=4,tim=1066522815819173
FETCH #13:c=0,e=58,p=0,cr=2,cu=0,mis=0,r=0,dep=2,og=4,tim=1066522815819296
=====================
PARSING IN CURSOR #12 len=34 dep=1 uid=0 oct=7 lid=0 tim=1066522815819480 hv=3008185193 ad='56fcbaac'
delete from idl_ub1$ where obj#=:1
END OF STMT
PARSE #12:c=10000,e=14804,p=6,cr=79,cu=0,mis=1,r=0,dep=1,og=0,tim=1066522815819472
BINDS #12:
?bind 0: dty=2 mxl=22(22) mal=00 scl=00 pre=00 oacflg=08 oacfl2=1 size=24 offset=0
?? bfp=40645a48 bln=22 avl=06 flg=05
?? value=4294951150
WAIT #12: nam='db file sequential read' ela= 41 p1=1 p2=22839 p3=1
WAIT #12: nam='db file sequential read' ela= 27 p1=1 p2=9 p3=1
EXEC #12:c=0,e=884,p=2,cr=4,cu=2,mis=0,r=0,dep=1,og=4,tim=1066522815820884
ERROR #12:err=16000 tim=1837753940
ORA-00604: error occurred at recursive SQL level 1
ORA-16000: database open for read-only access
EXEC #1:c=370000,e=375493,p=304,cr=5505,cu=4,mis=0,r=0,dep=0,og=4,tim=1066522815826303
ERROR #1:err=1092 tim=1837753940

很奇怪，正常standby資料庫open read  only的時候是沒有delete的，在這裡居然出現dml。於是一開始我嘗試去研究idl_ub1$是個什麼表，結果發現是儲存pl/sql代碼的，很奇怪，這個資料庫為什麼會出現個狀況，繼續在 $ORACLE_HOME/rdbms/admin 下 grep -ir idl_ub1$ * ，結果找到和一個x$ 表掛上關係做串連了，未果，又通過 delete from idl_ub1$ where obj#=:1 中綁定變數value=4294951150 去結合搜尋出來的view尋找，也沒什麼進展。實際上，根據 WAIT #12: nam='db file sequential read' ela= 27 p1=1 p2=9 p3=1 可以知道這個delete是訪問了file# =1 block#=9 的資料區塊，很顯然，這是系統復原段的塊頭，根據這裡我們可以知道，這是一個復原操作，也就是說，在主要資料庫中由於DDL 的失敗，使得系統復原段中記錄了該操作的回退資訊，但是資料庫又還沒有復原完成，到了standby中就出現這個狀況了。

為了嘗試解決這個問題，首先繼續應用幾個日誌，再open read only，結果失敗，也就是說該失敗的ddl在主要資料庫一直沒有復原，而資料庫中已經尋找不到任何異常進程或者事務、鎖，只能認為是系統出現異常。於是，今天在徵得相關負責人的同意的情況下，我們決定在下班後將主要資料庫重新啟動一次看看，這樣強迫系統復原失敗的ddl。下班重新啟動資料庫，切換日誌並歸檔，在standby上應用日誌到重起資料庫之後產生的歸檔日誌，再open  read only 成功，問題得到解決。