sql2000資料庫搶救記

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 損壞?

就再持續觀察了......................  -.-!!!!