實戰課堂：為什麼更換存儲之後一切正常但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_dev1311of=/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_dev1311blocksize=8192

那麼顯然，這個問題跳出了傳統的故障原因。

我們再回顧一下錯誤信息，資料庫啟動失敗源自DBWR報錯，可以通過進程跟蹤來分析進程的工作狀態。

在此我們通過v$session，分析DBW0進程當前的等待事件，排查dbwr進程遲遲不向其他進程發送相關ipc message的原因：

SQL> select event from v$session where paddr in

(select addr from v$process where pid=);

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）*60ms = 900ms，即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.682626sec (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.695486sec (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=9000SCOPE=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性能為何出現衰減，導致啟動超時。這和存儲的規劃、磁碟劃分、緩存配置等有關，資料庫的案例到此就處理完成了。

資源下載

關注公眾號：數據和雲（OraNews）回復關鍵字獲取

2018DTCC, 資料庫大會PPT

2017DTC，2017 DTC 大會 PPT

DBALIFE，「DBA 的一天」海報

DBA04，DBA 手記4 電子書

122ARCH，Oracle 12.2體系結構圖

2017OOW，Oracle OpenWorld 資料

PRELECTION，大講堂講師課程資料

喜歡這篇文章嗎？立刻分享出去讓更多人知道吧！