2012/5/7下午二點多,正準備混一下後就要休假去醫院作檢查. 結果收到人客打來的電話說,無法ETL資料了. 看了一下他寄來的LOG,發現代誌金是大條, 二顆SAN DISK磁碟竟然不見了?
因為醫生不好排,所以我就先到醫院檢查,然後請同事幫忙去跟OP了解一下看看SAN是否有問題.
一個半小時後作完檢查,到客戶site,問了一下同事,同事說,OP重開機就看到那二顆磁碟了.當下以為沒事了.
結果等我到機房一看後,才發現DB變成了灰色有疑問的狀態.
查看了SQL SERVER 的ERRORLOG截錄如下
2012-05-07 15:00:25.55 spid14 分析資料庫 'myDB' (10) 已經完成 100% (大約還有 0 秒)
2012-05-07 15:00:25.56 spid14 資料庫 'myDB' (10) 的復原已經完成 0% (大約還需要 102 秒) (階段 2/3)。
2012-05-07 15:00:25.64 spid14 錯誤: 823，重要性: 24，狀態: 2
2012-05-07 15:00:25.64 spid14 I/O error (torn page) detected during read at offset 0x000003b8608000 in file 'G:\myDB_FILE\XX_NDF.NDF'.。
2012-05-07 15:00:25.66 spid14 錯誤: 3313，重要性: 21，狀態: 2
2012-05-07 15:00:25.66 spid14 在資料庫 'myDB' 上重做記錄動作時發生錯誤。錯誤位於記錄檔資料錄識別碼 (813332:24625:7)。。
2012-05-07 15:00:25.66 spid14 錯誤: 3313，重要性: 21，狀態: 2
2012-05-07 15:00:25.66 spid14 Error while redoing logged operation in database 'myDB'. Error at log record ID (813332:24625:7).。
2012-05-07 15:00:25.77 spid14 錯誤: 3414，重要性: 21，狀態: 1
2012-05-07 15:00:25.77 spid14 資料庫 'myDB' (資料庫識別碼 10) 無法復原。請洽技術支援。。
2012-05-07 15:00:25.77 spid14 錯誤: 3414，重要性: 21，狀態: 1
2012-05-07 15:00:25.77 spid14 Database 'myDB' (database ID 10) could not recover. Contact Technical Support.。
再往前查看重開機前的ERRORLOG,截錄如下
2012-05-07 12:16:52.09 spid1 SQL Server
has encountered 1 occurrence(s) of IO requests taking longer than 15
seconds to complete on file [G:\DB_FILE\XX_NDF.NDF] in database
[myDB] (10). The OS file handle is 0x00000620. The offset of the latest
long IO is: 0x0000034c742000
2012-05-07 12:16:52.09 spid1 SQL Server has encountered 1
occurrence(s) of IO requests taking longer than 15 seconds to complete
on file [G:\DB_FILE\YY_NDF.NDF] in database [myDB] (10). The OS
file handle is 0x0000061C. The offset of the latest long IO is:
0x0000038eab8000
2012-05-07 12:22:31.59 spid2 LogWriter: 發生作業系統錯誤 2(系統找不到指定的檔案。)。
2012-05-07 12:22:31.59 spid2 Write error during log flush. Shutting down server
2012-05-07 12:22:31.60 spid88 SQL Server has encountered 161
occurrence(s) of IO requests taking longer than 15 seconds to complete
on file [G:\DB_FILE\YY_NDF.NDF] in database [myDB] (10). The OS
file handle is 0x0000061C. The offset of the latest long IO is:
0x0000039d402000
2012-05-07 12:22:31.60 spid88 錯誤: 823，重要性: 24，狀態: 2。
2012-05-07 12:23:26.48 spid6 I/O error
21(裝置未就緒。) detected during write at offset 0x000003cfd8c000 in file
'F:\DB_FILE\ZZ_NDF.NDF'.。
2012-05-07 12:23:27.37 spid56 錯誤: 9001，重要性: 21，狀態: 1
2012-05-07 12:23:27.37 spid56 資料庫 'tempdb' 的記錄檔無法使用。。
2012-05-07 12:23:27.37 spid56 錯誤: 9001，重要性: 21，狀態: 1
2012-05-07 12:23:27.37 spid56 The log for database 'tempdb' is not available.。
初判看來SAN DISK的問題.因為有問題的主要資料表檔案及tempdb都是放在SAN DISK上的
第一件事,當然就是關鍵字GOOGLE 查看可能的解決方法.一番查看後,先做了第一次修復嚐試
參考
Chenghsiu's Blog的這篇文章
Use Master
Go
sp_configure 'allow updates', 1
reconfigure with override
Go
--異動為緊急模式
update sysdatabases set status = 32768 where name = 'myDB'
Go
--單一使用者模式
sp_dboption 'myDB', 'single user', 'true'
Go
--檢查有沒問題
DBCC CHECKDB('myDB')
--如果DBCC CHECKDB無問題 RESET DB 狀態
update sysdatabases set status=0 where name='myDB'
Go
--動為多人模式
sp_dboption 'myDB' ,'dbo use only','false'
Go
--重新整理DB應該會正常了
sp_configure 'allow updates', 0
reconfigure with override
Go
當天做了將近5個小時檢查,
我也沒仔細推敲什麼叫"沒問題"
dbcc checkdb後的結果節錄如下
資料表錯誤 : 資料庫 'myDB'，索引 'xx_tab.xx_idx' (識別碼 1604473786) (索引識別碼 2)。下列索引鍵含有不必要的或無效的鍵值:
伺服器: 訊息 8956，層級 16，狀態 1，行 1
值 (xx_ym = 10104 and xx_og = '1111' ) 的索引資料列 (6:802286:114) 指向 (RID = (3:1964420:1)) 所識別的資料列。
伺服器: 訊息 8986，層級 16，狀態 1，行 1
物件識別碼 1604473786 的錯誤太多 (201)。若要查看所有的錯誤訊息，請使用 'WITH ALL_ERRORMSGS' 來重新執行陳述式。
物件 'xx_tab' 在 1936564 個分頁上有 18529648 列。
CHECKDB 在資料表 'xx_tab' (物件識別碼1604473786) 上發現了 0 個配置錯誤和 37223 個一致性錯誤。
.........
CHECKDB 在資料庫 'myDB' 上發現了 0 個配置錯誤和 71632 個一致性錯誤。
repair_fast 是 DBCC CHECKDB (myDB) 所發現的錯誤的最小修復層級。
DBCC 的執行已經完成。如果 DBCC 印出錯誤訊息，請聯絡您的系統管理員。
做完後,DB總算可正常讀取,測試幾個重要資料表的讀取後,發現在讀取資料表xx_tab時,先列出幾列資料後,然後就就出現823的錯誤了, 如下
伺服器: 訊息 823，層級 24，狀態 2，行 1
I/O error (torn page) detected during read at offset 0x0000038121a000 in file 'G:\DB_FILE\XX_NDF.NDF'.
連線中斷
於是使用以下語法檢查
sp_DBOPTION 'myDB', 'single user','true'
dbcc checktable ('xx_tab')
得到以下 訊息
資料表錯誤 : 物件識別碼 1604473786，索引識別碼 0，分頁 (3:1964027)。測試 (IS_ON (BUF_IOERR, bp->bstat) && bp->berrcode) 失敗。值為 2057 和 -1。
伺服器: 訊息 8928，層級 16，狀態 1，行 1
物件識別碼 1604473786，索引識別碼 0: 分頁 (3:1964029) 無法處理。請查看其他的錯誤以取得相關細節。
伺服器: 訊息 8939，層級 16，狀態 1，行 1
資料表錯誤 : 物件識別碼 1604473786，索引識別碼 0，分頁 (3:1964029)。測試 (IS_ON (BUF_IOERR, bp->bstat) && bp->berrcode) 失敗。值為 2057 和 -1。
物件 'xx_tab' 在 1937026 個分頁上有 18540732 列。
CHECKTABLE 在資料表 'xx_tab' (物件識別碼1604473786) 上發現了 0 個配置錯誤和 33 個一致性錯誤。
repair_allow_data_loss 是 DBCC CHECKTABLE (myDB.dbo.xx_tab ) 所發現的錯誤的最小修復層級。
再試著 dbcc checktable ('xx_tab', repair_allow_data_loss)
出現了一個錯誤.(忘了複制下來) 結果也無法修復.
於是再試著dbcc checkfilegroup ('G:\DB_DILE\xx_ndf.bdf ') 是出現以下的錯誤
伺服器: 訊息 8939，層級 16，狀態 1，行 1
資料表錯誤 : 物件識別碼 1604473786，索引識別碼 0，分頁 (5:1991209)。測試 (m_freeCnt == freeCnt) 失敗。值為 1567 和 8074。
伺服器: 訊息 8939，層級 16，狀態 1，行 1
資料表錯誤 : 物件識別碼 1604473786，索引識別碼 0，分頁 (5:1991209)。測試 (emptySlotCnt == 0) 失敗。值為 11 和 0。
伺服器: 訊息 8981，層級 16，狀態 1，行 1
資料表錯誤 : 物件識別碼 1604473786，索引識別碼 21。(6:826686) 的下一個指標參考至分頁 (6:91078)，但找不到 (6:91078) 及其父系。可能是鏈結發生問題。
看來是跟索引有關,因為重要table的索引檔也是建立在一個獨立FILEGROUP上,於是想說,那就針對xx_tab的二個索引砍掉重建好了.順利砍掉了index後,執行重建指令,結果又出現了錯誤
伺服器: 訊息 823，層級 24，狀態 2，行 1
I/O error (torn page) detected during read at offset 0x0000038121a000 in file 'G:\DB_FILE\XX_NDF.NDF'.
連線中斷
然後,我建了一個相同結構相同名稱的空DB,把相關的FILEGROUP也建立起來後,detach這個DB,再將原本的mdf,ndf 給覆製蓋過去,重新attach db時,出現了錯誤
錯誤 5173: 不得和不同的資料庫結合檔案。
殘念啊....折騰了幾個小時,在一番紅了眼昏了頭的測試下,DB又被我搞到進入有疑問的狀態了.
最後,做了決定, 把系統資料庫及myDB資料都回復到最後備份正常的那個時段.
由於人客的備份環境 是採用FalconStor CDP,每小時都有快照備份,所以很快地就把系統資料庫備份檔案(mdf、ldf)都複製還原到原來的路徑下 (當然也是要花了二個小時把資料搬回去),然後san disk下的ndf檔也有每小時的快照給還原回去.
重啟sql server 後, ERRORLOG就只看以下的錯誤而以了,已經沒有823的錯了.
錯誤: 3313，重要性: 21，狀態: 2
在資料庫 'myDB' 上重做記錄動作時發生錯誤。錯誤位於記錄檔資料錄識別碼 (813332:24625:7)。。
錯誤: 3313，重要性: 21，狀態: 2
Error while redoing logged operation in database
'myDB'. Error at log record ID (813332:24625:7).。
最後又參考了這篇文章重建了log 後,就把db整個給搶救回來了.
USE MASTER
GO
sp_CONFIGURE 'allow updates', 1
RECONFIGURE WITH OVERRIDE
GO
--Change database mode to emergency mode. Following statement will return the current status of the database
SELECT * FROM sysdatabases WHERE name = 'myDB'
--Following statement will update only one row in database
BEGIN TRAN
UPDATE sysdatabases SET status = 32768 WHERE name = 'myDB'
COMMIT TRAN
--restart sql server
DBCC TRACEON (3604)
DBCC REBUILD_LOG(myDB,'C:\Program Files\Microsoft SQL Server\MSSQL\Data\my_log.LDF')
GO
-- Reset the database status using following command.
sp_RESETSTATUS 'myDB'
GO
BEGIN TRAN
UPDATE sysdatabases SET status = 0 WHERE name = 'myDB'
COMMIT TRAN
--Turn off the update to system tables of Master database running following script.
USE MASTER
GO
sp_CONFIGURE 'allow updates',0
RECONFIGURE WITH OVERRIDE
GO
個人這麼搞下來的結果...推測應是SAN DISK 的問題居多.
因為還原後的檔案(其實是個快照的virtual image), 讀取某個資料表(資料在Primary GROUP,但index放在INDEX GROUP)時,有以下的錯誤
OLE DB Provider for SQL Server <80004005.:無法透過 RID 從分頁中取出資料列，因為所要求的 RID 其編號大於分頁上最後一個 RID 的編號。
Rid pageid is <1:1511677> and row num is 0x9Page pointer = 0x8d876000, PageId = ,1:1511677>, flags = 0x8000, objectid = 1475444976, indexid = 0, DBID 10。
結果這將這個table的index 重建在Primary GROUP後就沒有問題了.
接下來,就要好好理清楚是不是SAN DISK的問題了, 得要再花時間反覆測試了. 好累!
============================================================
2012/05/10 ...快樂總沒有痛苦的時間來得長....
今天中午人客又回報
伺服器: 訊息 9001，層級 21，狀態 1，行 22
資料庫 'tempdb' 的記錄檔無法使用。
連線中斷
真是無頭緒的訊息,儲存空間灰常足夠,查看errorlog
2012-05-09 10:51:59.59 spid60 SQL Server has encountered 1145 occurrence(s) of IO requests taking longer than 15 seconds to complete on file [G:\TempFile\tempdb.mdf] in database [tempdb] (2). The OS file handle is 0x00000578. The offset of the latest long IO is: 0x0000007d042000
......
2012-05-10 11:10:32.26 spid101 I/O error 21(裝置未就緒。) detected during read at offset 0x0000000001e000 in file 'G:\TempFile\tempdb.mdf'.
又是類似的問題...連備用的virtaul image都有問題...到底是哪兒出錯呢? 整組壞掉...?
線上緊急進行下列處理,把tempdb由 virtual image 移到RAID HD上.
因為有使用者在線上也來不急一一通知離線,就算通知有人也會死賴不走..
於是要先改掉使用者的密碼, 確保重開服務後進入單一模式時唯一連線不會被搶走.
--先進入dos command使用isql 更改密碼
sp_password 'mypwd','1234','myuser'
--依序停用服務
net stop reportserver
net stop MSSQLServerOLAPService
net stop SQLServerAgent
net stop mssqlserver
--重開服務進入單一模式
net start mssqlserver /f /T3608
--使用isql command更改tempDB位置
use tempdb
go
--確認目前tempDB位置
sp_helpgile
go
--移動tempdb位置
use master
go
ALTER DATABASE tempdb
MODIFY FILE (NAME = tempdev, FILENAME = 'd:\temp\tempdb.mdf');
go
ALTER DATABASE tempdb
MODIFY FILE (NAME = templog, FILENAME = 'd:\temp\templog.ldf');
go
--最後,再重開服務
net start mssqlserver
net start SQLServerAgent
net start MSSQLServerOLAPService
net start reportserver
持續觀察中...................... -.-!!!
==================================================
2012/05/15
自從將tempDB做了轉移後,系統幾天下來似乎都恢復正常.
所以今天花了一些時間,把virtual image上的資料以Export/import的方式重新轉入到新的file group及file上.
這幾天也爬了文,查看是否有人有相同的問題, 但似乎是查無結果.
到底是因為tempdb的大量I/O造成index及data filegroup的問題,還是因為san disk的磁區損壞造成tempDB,index及data 損壞?
就再持續觀察了...................... -.-!!!!
