淺談一次惱火的死鎖追蹤經(jīng)歷
最近，剛跳槽到一新公司，就遇到生產(chǎn)數(shù)據(jù)庫晚上突然出現(xiàn)大面積中斷，并持續(xù)近一小時，而發(fā)生事故時，我沒有在現(xiàn)場，錯過了直接獲取信息的機會；過后boss要求追查原因，于是艱難的排查過程開始了。
開始以為是數(shù)據(jù)庫某個JOB運行出現(xiàn)異常引起或者是因為程序里面哪個鳥人寫了垃圾語句造成了大面積的死鎖，于是將收集的trace信息拿到本地分析，從收集到的trace信息看，數(shù)據(jù)庫在19：49：28時出現(xiàn)了鎖，系統(tǒng)cancel了它，而且是連續(xù)三個，之后數(shù)據(jù)庫大部分連接都是Abort了。
初步估計應(yīng)該是死鎖了，首先想到的就是因為數(shù)據(jù)庫更新語句造成，于是查找Agent里面是否有對應(yīng)時間的JOB運行，結(jié)果沒有匹配的，然后分析trace文件里面是否有該時間段內(nèi)運行的長Update、Insert或者Delete語句，查了半天也沒發(fā)現(xiàn)，汗。。。，調(diào)查長查詢，還是沒有，狂汗。。。
Trace文件分析來分析去也沒辦法定位到具體語句（Trace 文件中只抓取了運行時間超過2秒或者讀大于10000的記錄），看來問題不是那么簡單了；光根據(jù)Trace文件信息想要找到兇手估計不可能了，于是把Windows日志和數(shù)據(jù)庫錯誤日志都查了一遍，也沒有發(fā)現(xiàn)任何異常，難道是無頭案。。。（沒查到任何信息，擔(dān)心飯碗不保了）
想來想去，也問了一些牛人，都沒有啥結(jié)果，看來通過手頭上現(xiàn)有的資料估計要找出問題是沒多少希望了，只能另辟蹊徑；既然可以肯定是因為死鎖造成的，那說明數(shù)據(jù)庫里面肯定存在資源的不一致訪問或者競爭，那就從死鎖下手，于是先清空掉當(dāng)前的數(shù)據(jù)庫錯誤日志文件，再打開1204和1222跟蹤標(biāo)志，等待魚兒上鉤。
- DBCC errorlog
- DBCC TRACEON (1204, 1222, -1);
- DBCC tracestatus
收集了幾天數(shù)據(jù)，準(zhǔn)備收網(wǎng)了，將ERROR.LOG從服務(wù)器拷貝到本地，用UE打開，認(rèn)真一行行看，找到如下信息：
- Deadlock encountered .... Printing deadlock information
果然是死鎖，總算找到真兇了，用UE查找一把，不查不知道，一查嚇一跳，一堆死鎖...
死鎖信息如下：
查看一下頁面信息：
- DBCC TRACEON (3604)
- DBCC PAGE('XXXX',1,22664690,3) WITH TABLERESULTS
- DBCC TRACEOFF (3604)
這些頁面信息都正常。
再根據(jù)信息，Input Buf 的信息，反過來查詢Trace文件（Input Buffer 只能存放255個字節(jié)，信息顯示不全，只能反過來找）：
- 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%'
發(fā)現(xiàn)，死鎖在表Rec_Main表上，一個是修改，一個是查詢，而這個表數(shù)據(jù)量達(dá)700多W，又一個汗.....
不過很奇怪的是，死鎖顯示的信息都是些簡單的修改（單條記錄修改）和查詢操作，不至于引起這么多死鎖呀，繼續(xù)頭大中...
繼續(xù)追查后發(fā)現(xiàn)，這兩個操作在數(shù)據(jù)庫中比較頻繁（一天的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)%'
一天的死鎖次數(shù)大概有20次左右，Update一次只有一條記錄，但是為啥會出現(xiàn)如此頻繁的死鎖呢？ 除了這個表本身的數(shù)據(jù)量大
以及查詢超級變態(tài)之外（后面發(fā)現(xiàn)是主因），還有沒有其他的原因呢？
最后，實在找不出問題所在，將問題反映到微軟，和微軟的人經(jīng)過幾天的溝通，最終給出的結(jié)果是數(shù)據(jù)庫的Bug（吐血，運氣真好呀），微軟回答如下：
問題分析：
========
您的數(shù)據(jù)庫版本是：Microsoft SQL Server 2005 - 9.00.4207.00 (Intel IA-64) Enterprise Edition，SP3 CU1
我檢查了您提供的死鎖相關(guān)信息后發(fā)現(xiàn)，如您所說，您的這個死鎖問題正是SQL2005的Bug所引起，詳細(xì)可以參考文檔：<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的版本，所以請選擇正確對應(yīng)的安裝文件
-------補充---
微軟雖然給出了一個可能的原因（還不知道靠不靠譜），但是基于目前系統(tǒng)的情況，boss不建議打補?。ㄒ舻蕉ㄆ诰S護(hù)的時候再做），于是要我提改進(jìn)方案，有了以上的追蹤信息，再來提改進(jìn)方案就不是什么難事了，于是mail給了boss：
根據(jù)這些信息，我們可以知道：
死鎖主要發(fā)生在表Rec_main上，這個表的數(shù)據(jù)量有700多萬；
主要是由一個Update和一個Select語句引起了死鎖，這兩條語句運行頻率比較高，并且查詢語句非常長（見附件，這樣的查詢不可能使用到索引）；
主要問題出在這個復(fù)雜的查詢和表的數(shù)據(jù)量上（還包括微軟說的bug）；
目前這種死鎖在我們數(shù)據(jù)庫里面還是頻繁的發(fā)生。
為處理這種情況，有以下建議：
業(yè)務(wù)上，是否能夠?qū)⒃摫淼男畔⒎珠_，減少數(shù)據(jù)量；
開發(fā)人員能否改進(jìn)這個查詢語句；
查詢是否可以考慮加上with（nolock），Update 語句可以加上 with（rowlock）；
其他（考慮分區(qū)表等）。
最終，將表中數(shù)據(jù)搬移掉一部分，修改了查詢的語句，同時加上了with（nolock），問題得到解決（至于微軟的方案，要見下回分解了）
原文鏈接：http://www.cnblogs.com/fygh/archive/2011/04/12/DeadLock.html
【編輯推薦】
