[SQL]紀錄 SQL Server 死結( Deadlock ) 的方法

利用 SQL Server Error Log , Extend Event 和 SQL Trace 來記錄

剛好有朋友的環境發生 Deadlock 的狀況 , 想要知道是怎麼來發生的 , 因此整理一下之前給他的資料 , 當成自己的紀錄


預備環境

為了能夠呈現 Deadlock 的狀況 , 我利用 AdventureWorks 的範例資料庫來做測試,並且準備以下兩段的 SQL 語法來做測試

第一組

PRINT @@SPID

BEGIN TRAN
	UPDATE [Production].[Product] SET Color = 'Silver' 
		WHERE [ProductID] = 1

	SELECT * FROM [Production].[Location]
		WHERE [LocationID] = 1 

ROLLBACK

第二組

PRINT @@SPID

BEGIN TRAN
	UPDATE [Production].[Location] SET ModifiedDate = CAST( GETDATE() AS DATE )
		WHERE [LocationID] = 1

	SELECT * FROM [Production].[Product]
		WHERE [ProductID] = 1 

ROLLBACK

基本上發生 Deadlock "通常" 是有幾個交易彼此在等待對方的資源 , 使得系統無法運行下去的狀況 , SQL Server 會每 5 秒鐘自動偵測是否有死結的狀況,因此會犧牲其中一個交易,打破互相等待的狀況,讓整體可以運作下去。

因此在上面兩組的指令,我們會故意一次只跑一半,讓兩個交易會造成死結的狀況,並且利用幾種方式來做紀錄。

首先如下圖所示,我們在這個交易內,先執行一半去做 Product 資料表的更新

圖1

接下來我們在第二組指令,也類似圖 1 的方式,先執行一半,但這次在這個交易我們是去更新另外一個資料表 Location 。

圖2

接下來我們繼續回到第一組指令,去執行下半段的部分,此時會發現因為目前要讀取的資料,剛好是前面的步驟所更新的資料,因此交易會因為 Lock 的原因,造成指令在等待前面的交易結束。

圖3

此時我們回到第二組的 SQL 指令去執行後半段,會發現執行之後,在等待一下子的時間後,就會出現錯誤訊息,告訴我們這個交易成為死結的犧牲者

圖4

此時我們回到原本第一組因為鎖定造成等待的指令,會因為第二組的交易已經被取消了,因此就可以正常讀取到資料了。

圖5

因此從上面簡單的示範過程中可以看到,當有死結發生的時候,因為 SQL Server 會自動介入處理,因此會犧牲掉一個交易,不讓整體因為交易間相互等待,導致系統無法正常運行。上述只是死結發生的一種狀況,相互競爭也有可能發生在自己一個交易內,只是我們先用一個比較簡單的方式來做展示。


一般來說,當 SQL Server 發生問題,我們通常都會很習慣的來查看 SQL Server 記錄檔 ( SQL Server Error Log ),因此在查看之前,我先透過 xp_logevent 來產生一個紀錄到記錄檔內。

EXEC xp_logevent 60000, '---------------------------------', informational; 

從圖片中可以看到記錄檔內有我們所加入的資訊,但順著這個資料的時間往前找,會發現在我們之前做測試的時候,雖然有發生 Deadlock 的狀況,但是在記錄檔內,如果我們沒有預先做相關處理,是沒有任何記錄在這裡是有被記錄下來的。

圖6

那我們要怎麼來做紀錄呢 ? 從很久之前很多朋友都會透過 SQL Profiler 或者是 SQL Trace 來做紀錄,這兩個本質上都是相似的東西,一般我們都會先利用 SQL Profiler 利用圖形化介面來做設定,當確認沒有問題之後,再將這些設定轉成 SQL Trace 的語法。因此在下面的範例當中,我們就先採用 SQL Profiler 的設定來做說明。

當我們開啟 SQL Profiler 之後,首先我們會建立一個追蹤,SQL Profiler 其實很貼心的預備好相關的範本,只要在選擇範本的地方,選擇「TSQL_Locks」的範本

圖7

可以從「事件選取範圍」中可以看到,透過這個範本已經將相關的 Deadlock 事件給選擇進來了。因此我們就可以按下執行,來看看當我們發生 Deadlock 的時候,可以看到甚麼樣的資訊。

圖8

我們一樣就利用一開始所建立的腳本,按照次序再重新執行一次,故意造成死結的狀況發生。果然在 SQL Profiler 之中,就會產生一個 Deadlock graph 的事件,並且在這個事件中,SQL Profiler 會將所記錄下來的資訊,用圖形的方式來作呈現,從下面的圖我們就可以看到,這兩個 Session 58 和 Session 59 發生死結的狀況,因此 Session 59 是死結的犧牲者,SQL Server 自動將 Session 59 給中斷,讓 Session 58 因為可以取得資源,因此就可以繼續的往下去執行了。

圖9

雖然從前面的步驟中看起來,採用 SQL Profiler 或者是 SQL Trace ,微軟已經不建議我們再繼續使用這樣的方式,那現在到底要用甚麼樣的方式來做紀錄呢 ? 官方是建議採用擴充事件 ( Extended Event ) 來做紀錄,現在當我們要使用的時候, 其實他在設定上也是非常的方便。

我們可以在 SSMS 上面,選擇 管理 → 擴充事件 → 工作階段 的節點,然後透過滑鼠右鍵選擇「新增工作階段精靈」,透過精靈式的一步一步完成相關設定。 

圖10
圖11

這個我們設定一個工作階段的名稱

圖12

可以看到類似 SQL Profiler ,在工作階段也有相關的範本可以選擇使用,這裡我們也是選擇「TSQL_Locks」的範本,這樣我們可以簡化不少相關設定。但如果後續您熟悉了相關設定和使用,也是可以不採用範本,自己去挑選符合您所要的相關事件和欄位。

圖13

在這個步驟中,我們可以看到右邊「選取的事件」中,已經自動加入 Deadlock 所需要紀錄的資訊了。

圖14
圖15
圖16

這裡為了後續方便查詢和使用,因此這裡我們特別建立一個目錄用來存放擴充事件中所記錄下來的資訊

圖17
圖18
圖19

當我們完成相關設定之後,再來重新執行一開始會造成死結的命令,此時透過擴充事件中所得到的資訊,我們可以看到有個「xml_deadlock_report」的事件被記錄下來了。而在這個事件中,我們不僅可以透過相關的 XML 資訊了解發生 Deadlock 的原因,他還會多增加一個死結的頁簽。

圖20

而透過該死結頁簽所提供的資訊,可以看到跟 SQL Profiler 中所看到的相似的說明。

圖21

因此從上述的展示中,相信大家會發現,其實擴充事件使用起來跟 SQL Profiler 差異並不太大,而且還可以有更多的功能並且獲取更多的資訊,因此即使微軟接下來可能會淘汰 SQL Profiler 或 SQL Trace,要轉換成使用 Extended Event 應該也不會太麻煩。


然而除了上述兩種方法,另外還有一種就是透過開啟追蹤旗標 ( Trace Flag ),將資訊給紀錄在 SQL Server 記錄檔內,因此如果您有需要開啟的話,那麼可以在 SSMS 裡面,去使用以下的語法來做開啟。

DBCC TRACEON (1204, -1)
DBCC TRACEON (1222, -1)

當我們開啟之後,如果有發生死結的狀況,那麼死結的資訊就會被記錄在記錄檔內了。

圖22

只是就我個人來說,比較不喜歡用這樣的方式,因此當你採用這樣的設定時候,雖然可以把死結的資訊記錄下來,但是要是當這個 SQL Server 的 Instance 要是重新啟動,那麼這樣的設定就失效了。雖然有人提到可以將這樣的設定,可以透過SQL Server 組態管理員中,開啟 SQL Server 服務的設定,在「啟動參數」內加入兩組的設定 -T1222 和 -T1204 ,這樣啟動 SQL Server 之後,就會開啟將死結的狀況給存入到記錄檔內。

圖23

這樣看起來也是有達到效果,但是每次要設定或者是更改,就需要把 SQL Server 服務給重新啟動,對於線上正在運作的 SQL Server,就不是那麼恰當了。


因此透過這篇文章,主要是整理三種不同紀錄死結的方式,從長久來看,應該會選擇擴充事件會是比較合適的方法,但也不是說其他狀況不行,可能大家在使用上,要多了解要運用的場景,了解這三種使用方式的限制,再來選擇一種合適自己的方法囉。