為什么更換存儲之后一切正常但RAC集群啟動不了?
這是一次來自生產實踐的真實案例,某客戶核心生產庫由于進行新老存儲替換變更操作后,Oracle RAC 兩個節點均無法打開,數據庫遭遇嚴重故障。
先來看看告警日志中記錄的錯誤信息,我們注意到數據庫能夠正常Mount,但是在Open階段遇到錯誤,提示某個數據文件不能被鎖定:
- ALTER DATABASE MOUNT
- This instance was first to mount
- Fri Dec 16 03:20:34 2016
- Successful mount of redo thread 2, with mount id 3052566649
- Fri Dec 16 03:20:40 2016
- Database mounted in Shared Mode (CLUSTER_DATABASE=TRUE)
- Lost write protection disabled
- Completed: ALTER DATABASE MOUNT
- ALTER DATABASE OPEN
- This instance was first to open
- Fri Dec 16 03:00:53 2016
- Errors in file /diag/ojtdb/ojtdb2/trace/ojtdb2_ora_1569.trc:
- ORA-01157: cannot identify/lock data file 1311 - see DBWR trace file
- ORA-01110: data file 1311: '/dev/vx/rdsk/ora_ojt10/ora_dev1311'
- ORA-1157 signalled during: ALTER DATABASE OPEN
通常遇到這個錯誤,最常見的原因是存儲未正常掛載,或者數據文件損壞丟失。
通過dd檢測發現I/O讀正常,dbv檢測數據文件也正常,這說明存儲和數據文件的基本表現都屬正常,而且不存在權限問題:
- oracle$ time dd if=/dev/vx/rdsk/ora_ojt10/ora_dev1311 of=/dev/null bs=1024k count=1000
- 1000+0 records in
- 1000+0 records out
- real 0m1.654s
- user 0m0.006s
- sys 0m0.316s
- oracle$ dbv file=/dev/vx/rdsk/ora_ojt10/ora_dev1311 blocksize=8192
那么顯然,這個問題跳出了傳統的故障原因。
我們再回顧一下錯誤信息,數據庫啟動失敗源自DBWR報錯,可以通過進程跟蹤來分析進程的工作狀態。
在此我們通過v$session,分析DBW0進程當前的等待事件,排查dbwr進程遲遲不向其他進程發送相關ipc message的原因:
- SQL> select event from v$session where paddr in
- (select addr from v$process where pid=<13>);
- EVENT
- ------------------------
- Disk file operations I/O
DBWR 始終在執行磁盤 I/O 操作,Disk file operations I/O等待事件的官方解釋如下:
This event is used to wait for disk file operations (for example, open, close, seek, and resize). It is also used for miscellaneous I/O operations such as block dumps and password file accesses.
此事件用于等待磁盤文件操作(例如,打開,關閉,搜索和調整大小)。 它也用于一些其他I / O操作,例如塊轉儲和密碼文件訪問。
這個等待事件的三個參數p1,p2,p3 含義如下:
持續觀察DBWR該事件的參數值,發現 p1=2,意思是 file open,在進行文件打開操作;p3=2,意思是操作數據文件。
而 p2 一直在遞增變化,其含義是文件號,不斷順序的打開不同的數據文件。
說明DBW0正在逐個檢查并打開數據文件,查詢得知該庫數據文件有1560個,在逐個檢查進行到900秒后,后臺alert日志中出現了如下錯誤,這一次出現問題的是另外一個文件:
- ORA-01157: cannot identify/lock data file 1401 - see DBWR trace file
- ORA-01110: data file 1401: '/dev/vx/rdsk/ora_ojt10/ora_dev1401'
- ORA-1157 signalled during: ALTER DATABASE OPEN
在啟動過程中,我們發現從mount到open階段,報出 ORA-01157 和 ORA-01110 花費的時間很長,需要十幾分鐘,然后報錯,使得啟動過程強制終止;
最終是后臺dbw進程在輸出日志,為了進一步分析該過程中具體流程,于是開啟10046事件跟蹤dbw0進程:
- *** 2016-12-16 12:03:30.798--這里時間是12點03,開始執行open操作
- WAIT #0: nam='SQL*Net message from client' ela= 7344875 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=8068132685065
- XCTEND rlbk=0, rd_only=1, tim=8068132685665
- =====================
- PARSING IN CURSOR #18446744071440810672 len=19 dep=0 uid=0 oct=35 lid=0 tim=8068132686043 hv=1907384048 ad='176ffabd68' sqlid='a01hp0psv0rrh'
- alter database open
- *** 2016-12-16 12:18:49.122
- WAIT #18446744071440810672: nam='rdbms ipc reply' ela= 2010056 from_process=23 timeout=2 p3=0 obj#=-1 tim=8069051099141
- *** 2016-12-16 12:18:51.038--之前都是空閑等待,從這個時間點開始,當前進程等待超時 ,發送超時消息給dbw0進程。而這個時間點18分。
- WAIT #18446744071440810672: nam='ksdxexeotherwait' ela= 1915544 p1=0 p2=0 p3=0 obj#=-1 tim=8069053014980
- WAIT #18446744071440810672: nam='control file sequential read' ela= 818 file#=0 block#=1 blocks=1 obj#=-1 tim=8069053016115
- WAIT #18446744071440810672: nam='control file sequential read' ela= 496 file#=0 block#=39 blocks=1 obj#=-1 tim=8069053016665
- WAIT #18446744071440810672: nam='control file sequential read' ela= 393 file#=0 block#=41 blocks=1 obj#=-1 tim=8069053017100
- WAIT #18446744071440810672: nam='control file sequential read' ela= 8212 file#=0 block#=2300 blocks=1 obj#=-1 tim=8069053025356
- WAIT #18446744071440810672: nam='CSS initialization' ela= 20622 p1=0 p2=0 p3=0 obj#=-1 tim=8069053046642
- WAIT #18446744071440810672: nam='CSS operation: action' ela= 2656 function_id=65 p2=0 p3=0 obj#=-1 tim=8069053049357
從dbw0進程的跟蹤日志來看,發現進程等待超時,然后發送超時消息給dbw0進程。從12:03分發起open操作,到12:18分出現超時消息,(18-3)*60 s = 900 s,即900秒后,后臺發送超時消息給dbw0進程,而這個時間點正是后臺報錯而啟動終止的時間。
這個信息給出了很好的分析線索,隨即繼續分析跟蹤文件,詳細分析每一次I/O的狀態:
- waited for 'Disk file operations I/O', seq_num: 617
- p1: 'FileOperation'=0x2
- p2: 'fileno'=0x1a9
- p3: 'filetype'=0x2
- time_waited: 0.696732 sec (sample interval: 0 sec)
- [1 sample, 07:57:37]
- waited for 'Disk file operations I/O', seq_num: 614
- p1: 'FileOperation'=0x2
- p2: 'fileno'=0x1a7
- p3: 'filetype'=0x2
- time_waited: 0.699569 sec (sample interval: 0 sec)
- [1 sample, 07:57:36]
- waited for 'Disk file operations I/O', seq_num: 613
- p1: 'FileOperation'=0x2
- p2: 'fileno'=0x1a6
- p3: 'filetype'=0x2
- time_waited: 0.682626 sec (sample interval: 0 sec)
- [1 sample, 07:57:35]
- waited for 'Disk file operations I/O', seq_num: 611
- p1: 'FileOperation'=0x2
- p2: 'fileno'=0x1a4
- p3: 'filetype'=0x2
- time_waited: 0.695486 sec (sample interval: 0 sec)
- [1 sample, 07:57:34]
- waited for 'Disk file operations I/O', seq_num: 610
- p1: 'FileOperation'=0x2
- p2: 'fileno'=0x1a3
- p3: 'filetype'=0x2
- time_waited: 0.700244 sec (sample interval: 0 sec)
- [1 sample, 07:57:33]
- waited for 'Disk file operations I/O', seq_num: 608
- p1: 'FileOperation'=0x2
- p2: 'fileno'=0x1a1
- p3: 'filetype'=0x2
- time_waited: 0.682131 sec (sample interval: 0 sec)
- ---------------------------------------------------
- Sampled Session History Summary:
- longest_non_idle_wait: 'Disk file operations I/O'
- [1 sample, 07:57:51 ]
- time_waited: 0.910736 sec (sample interval: 0 sec)
注意以上日志,可以發現平均打開一個數據文件的Disk file operations I/O操作大概需要0.7s左右,該庫共有 1560個 數據文件,照此計算,打開所有數據文件大約需要1092秒,這個時間超出了之前得出的從發起open到報錯終止的900秒的。
那么我們接下來要想辦法,讓數據庫在報錯之前等待更久。
怎么辦呢?讓我們思考1秒鐘。。。
數據庫中有一個隱藏參數 _controlfile_enqueue_timeout 默認為900s,該參數的意思是在數據庫的 Open 階段,鎖定控制文件讀取相關的數據文件并打開的允許超時時間,如果超過了900s閾值則認為數據庫超時,會拋出異常,中斷操作。
在此之前,我們估算了打開所有數據文件需要至少1092秒,這里在參數文件將該參數修改為9000s后,重新執行啟動流程,最終成功打開了數據庫的第二節點。
- Fri Dec 16 12:52:22 2016
- ALTER SYSTEM SET _controlfile_enqueue_timeout=9000 SCOPE=SPFILE;
- Fri Dec 16 12:52:22 2016
- Shutting down instance (abort)
- License high water mark = 5
- USER (ospid: 18936): terminating the instance
- Instance terminated by USER, pid = 18936
- Fri Dec 16 12:52:30 2016
- Instance shutdown complete
- Fri Dec 16 12:52:34 2016
- Starting ORACLE instance (normal)
- Fri Dec 16 12:52:47 2016
- …
- Fri Dec 16 12:56:39 2016
- Database mounted in Shared Mode (CLUSTER_DATABASE=TRUE)
- Lost write protection disabled
- Completed: ALTER DATABASE MOUNT
- Fri Dec 16 12:57:19 2016
- alter database open
- Fri Dec 16 13:15:42 2016
- GTX0 started with pid=92, OS id=26326
- replication_dependency_tracking turned off (no async multimaster replication found)
- Starting background process QMNC
- Fri Dec 16 13:15:43 2016
- QMNC started with pid=93, OS id=26332
- Completed: alter database open
從日志中,也清晰的看到,從12:57發起 alter database open 到***完成open,耗時18分鐘后,數據庫成功open,數據庫恢復正常。
這個案例給我們的警示是:
在可能的情況下,任何變更都應該進行 1:1 真實測試,***可能發現隱患;
事關存儲的變更,必須做好存儲的讀寫I/O基準測試;
這個案例的后續是,分析新存儲的I/O性能為何出現衰減,導致啟動超時。這和存儲的規劃、磁盤劃分、緩存配置等有關,數據庫的案例到此就處理完成了。