一次死鎖追蹤經歷

作者: 飛洋過海來源: 博客園發布時間: 2011-04-19 10:52 閱讀: 3684 次推薦: 9 原文鏈接 [收藏]

摘要：最近，剛跳槽到一新公司，就遇到生產數據庫晚上突然出現大面積中斷，并持續近一小時，而發生事故時，我沒有在現場，錯過了直接獲取信息的機會；過后boss要求追查原因，于是艱難的排查過程開始了。

　　最近，剛跳槽到一新公司，就遇到生產數據庫晚上突然出現大面積中斷，并持續近一小時，而發生事故時，我沒有在現場，錯過了直接獲取信息的機會；過后boss要求追查原因，于是艱難的排查過程開始了。

　　開始以為是數據庫某個JOB運行出現異常引起或者是因為程序里面哪個鳥人寫了垃圾語句造成了大面積的死鎖，于是將收集的trace信息拿到本地分析，從收集到的trace信息看，數據庫在19：49：28時出現了鎖，系統cancel了它，而且是連續三個，之后數據庫大部分連接都是Abort了。　　初步估計應該是死鎖了，首先想到的就是因為數據庫更新語句造成，于是查找Agent里面是否有對應時間的JOB運行，結果沒有匹配的，然后分析trace文件里面是否有該時間段內運行的長Update、Insert或者Delete語句，查了半天也沒發現，汗。。。，調查長查詢，還是沒有，狂汗。。。

　　Trace文件分析來分析去也沒辦法定位到具體語句（Trace 文件中只抓取了運行時間超過2秒或者讀大于10000的記錄），看來問題不是那么簡單了；光根據Trace文件信息想要找到兇手估計不可能了，于是把Windows日志和數據庫錯誤日志都查了一遍，也沒有發現任何異常，難道是無頭案。。。（沒查到任何信息，擔心飯碗不保了）

　　想來想去，也問了一些牛人，都沒有啥結果，看來通過手頭上現有的資料估計要找出問題是沒多少希望了，只能另辟蹊徑；既然可以肯定是因為死鎖造成的，那說明數據庫里面肯定存在資源的不一致訪問或者競爭，那就從死鎖下手，于是先清空掉當前的數據庫錯誤日志文件，再打開1204和1222跟蹤標志，等待魚兒上鉤。

DBCC errorlog DBCC TRACEON (1204, 1222, -1); DBCC tracestatus

　　收集了幾天數據，準備收網了，將ERROR.LOG從服務器拷貝到本地，用UE打開，認真一行行看，找到如下信息： Deadlock encountered .... Printing deadlock information果然是死鎖，總算找到真兇了，用UE查找一把，不查不知道，一查嚇一跳，一堆死鎖... 　　死鎖信息如下：

　　查看一下頁面信息：

DBCC TRACEON (3604)
DBCC PAGE('XXXX',1,22664690,3) WITH TABLERESULTSDBCC TRACEOFF (3604)

　　這些頁面信息都正常。

　　再根據信息，Input Buf 的信息，反過來查詢Trace文件（Input Buffer 只能存放255個字節，信息顯示不全，只能反過來找）：

select top 10 * from fn_trace_gettable('F:\perfmon\Trace_xxxx_20110406A.trc',default)
where TextData
like '%@SMESSAGE varchar(8000),@SINMATERECID varchar(8000),@SREFRECID varchar(8000)%'

select top 10 * from fn_trace_gettable('F:\perfmon\Trace_xxxx_20110406A.trc',default)
where TextData like '%@P0_ varchar(7),@P1_ datetime,@P2_ datetime,@P3_ varchar(7),@P4_ datetime%'

　　發現，死鎖在表Rec_Main表上，一個是修改，一個是查詢，而這個表數據量達700多W，又一個汗.....

　　不過很奇怪的是，死鎖顯示的信息都是些簡單的修改（單條記錄修改）和查詢操作，不至于引起這么多死鎖呀，繼續頭大中...

　　繼續追查后發現，這兩個操作在數據庫中比較頻繁（一天的trace記錄）：

select COUNT(0) from fn_trace_gettable('F:\perfmon\Trace_xxxx_20110406A.trc',default)
where TextData like '%@P0_ varchar(7),@P1_ datetime,@P2_ datetime,@P3_ varchar(7),@P4_ datetime%'

select COUNT(0) from fn_trace_gettable('F:\perfmon\Trace_xxxx_20110406A.trc',default)
where TextData like '%@SMESSAGE varchar(8000),@SINMATERECID varchar(18),@SREFRECID varchar(8000)%'

　　一天的死鎖次數大概有20次左右，Update一次只有一條記錄，但是為啥會出現如此頻繁的死鎖呢？除了這個表本身的數據量大以及查詢超級變態之外（后面發現是主因），還有沒有其他的原因呢？

　　最后，實在找不出問題所在，將問題反映到微軟，和微軟的人經過幾天的溝通，最終給出的結果是數據庫的Bug（吐血，運氣真好呀），微軟回答如下：問題分析：========您的數據庫版本是：Microsoft SQL Server 2005 - 9.00.4207.00 (Intel IA-64) Enterprise Edition，SP3 CU1我檢查了您提供的死鎖相關信息后發現，如您所說，您的這個死鎖問題正是SQL2005的Bug所引起，詳細可以參考文檔：http://support.microsoft.com/kb/975090

　　處理方法：============您可以單獨安裝SP3 CU6，也可以直接安裝SP4來解決您的這個問題SP3 CU6下載地址：http://support.microsoft.com/kb/974648 SP4下載地址：http://www.microsoft.com/downloads/en/details.aspx?FamilyID=b953e84f-9307-405e-bceb-47bd345baece 您的SQL Server是IA64的版本，所以請選擇正確對應的安裝文件

　　補充

　　微軟雖然給出了一個可能的原因（還不知道靠不靠譜），但是基于目前系統的情況，boss不建議打補丁（要留到定期維護的時候再做），于是要我提改進方案，有了以上的追蹤信息，再來提改進方案就不是什么難事了，于是mail給了boss，根據這些信息，我們可以知道：