この記事は ZOZO Advent Calendar 2023 カレンダー Vol.3の 10日目の記事です。
本記事ではSQL Serverで発生するデッドロックの収集から調査までをサンプルDBで実際に発生させながら紹介します。
SQL Serverにおけるデッドロックについて
デッドロック（Deadlock）は、複数のプロセスやスレッドが互いに相手の動作を待ってしまい、最終的に進行が停滞してしまう状態を指します。
SQL Serverではデッドロックモニターという検出用バックグラウンドプロセスが動いていて、
検出され次第原因となっているプロセスがキルされます。(検出の間隔はデフォルト5秒)
自動でキルされることもあり、稀に発生するだけであれば大きな問題とはなりにくいです。
しかし、瞬間的に大量に更新されるケースなど、デッドロックが連なってしまってロック範囲が拡大してしまうなど、
大量の処理がブロックされてしまうとWorkerやConnectionの枯渇を引き起こし、大きな障害に繋がる可能性があります。
デッドロック収集用の拡張イベントの設定
SQL Server では拡張イベントを使用することで発生したデッドロックを記録することができます。
デフォルトで起動している system_health セッションでも確認できますが、
他のイベントも収集している都合上、時間経過で消えてしまう可能性があります。
新規セッションとして登録しておくことで長期間残すことが可能です。
SQL Server Management Stduio(SSMS) からの拡張イベント設定例
以下は設定例です。
-
新規セッションをクリック
-
セッション名の入力
-
xml_deadlock_reportをキャプチャ対象として選択
-
イベントファイルの保存先を設定する
-
OKボタンを押して作成する
▶︎マークがついていたら起動しています。
サンプルDBでデッドロックを意図的に発生させる
実際にデッドロックを発生させて上記で設定した拡張イベントに記録されることを確認します。
- 使用した環境
- SQL Server 2016
- データベースは AdventureWorks サンプル データベース を使用
具体的な手順は次の通りです。
- AdventureWorksのDBに接続してタブを開き、下記のクエリを実行する
BEGIN TRAN
SELECT TOP(1) *
FROM [AdventureWorks2016].[Production].[TransactionHistory] WITH(ROWLOCK, UPDLOCK)
WHERE
TransactionID = 100000
WAITFOR DELAY '00:00:10'
SELECT TOP(1) *
FROM [AdventureWorks2016].[Production].[TransactionHistory] WITH(ROWLOCK, UPDLOCK)
WHERE
TransactionID = 100001
ROLLBACK
1 を実行してから10秒以内に別のタブで、下記のクエリを実行する
BEGIN TRAN
SELECT TOP(1) *
FROM [AdventureWorks2016].[Production].[TransactionHistory] WITH(ROWLOCK, UPDLOCK)
WHERE
TransactionID = 100001
WAITFOR DELAY '00:00:10'
SELECT TOP(1) *
FROM [AdventureWorks2016].[Production].[TransactionHistory] WITH(ROWLOCK, UPDLOCK)
WHERE
TransactionID = 100000
ROLLBACK
下記のように片方のタブでデッドロックが発生する
記録されたデッドロックイベントを確認する
上記を発生させると拡張イベントにデッドロックのイベントが記録されます
ここのデッドロックタブをクリックするとデッドロックグラフが確認でき、値をダブルクリックするとXMLで表示することができます
デッドロックイベントの個別の保存方法
拡張イベントに記録された中で個別で抜き出して共有・保存したい時があります。
そういった場合、XML表示をしている状態で「ファイル」 → 「名前を付けて保存」を押下し、ファイルを「すべてのファイル」として拡張子xdlで保存することで Microsoft SQL Server Deadlock File として保存ができます。
- 保存されたファイル
- 開くとSSMSが起動し、デッドロックグラフの確認が可能
デッドロックの分析
デッドロックグラフの画面ではプロセスにカーソルを合わせることでinputbufに記録されているクエリ(デッドロック発生時にそのプロセスで実行されていたクエリ)を確認できます。
例えば上記のデッドロックグラフからは次のような情報を取得することができます。
- プロセスID51において
- PK_TransactionHistory_TransactionのキーロックAをUロックとして取得済みであること
- PK_TransactionHistory_TransactionのキーロックBをUロックとして取得するのを待っていること
- その時実行されていたクエリ
- プロセスID66において
- PK_TransactionHistory_TransactionのキーロックBをUロックとして取得済みであること
- PK_TransactionHistory_TransactionのキーロックAをUロックとして取得するのを待っていること
- その時実行されていたクエリ
競合が起きた行を特定する
上記ケースだと出力されたSQL文のWHERE句に直接値が入っているため競合が起きたのはどのレコードなのかが明確ですが、実際に運用環境などで発生した場合は不明な場合が多いです。
どのレコードを起点として発生したかは必須の情報ではないですが、特定イベントの時や特定データで発生しやすい場合など有用な情報となる可能性があります。
上記で示したキーロックA, キーロックBはXML側のprocess-listのwait_resourceと紐付けることができます。
wait_resourceの実オブジェクトの特定については以下の記事が大変参考になります。
今回のケースでは次のクエリを実行することで、実際にどのようなレコードか特定できます。
-- 1行目を適宜変更して実行
DECLARE @wait_resource NVARCHAR(64) = 'KEY: 5:72057594050314240 (8dec1ed25f57)';
DECLARE @wait_resource_table_name NVARCHAR(64);
DECLARE @db_id INT = CAST(SUBSTRING(@wait_resource, 6, 1) AS INT); -- db_id1桁のみ対応
DECLARE @hobt_id BIGINT = CAST(SUBSTRING(@wait_resource, 8, 17) AS BIGINT);
DECLARE @lock_res NVARCHAR(64) = SUBSTRING(@wait_resource, 26, 14);
DECLARE @schemaname NVARCHAR(64);
DECLARE @tablename NVARCHAR(64);
DECLARE @indexname NVARCHAR(128);
SELECT
@schemaname = OBJECT_SCHEMA_NAME(p.object_id, @db_id),
@tablename = OBJECT_NAME(p.object_id, @db_id),
@indexname = i.name
FROM
sys.allocation_units AS a WITH(NOLOCK)
INNER JOIN sys.partitions AS p WITH(NOLOCK)
ON p.hobt_id = a.container_id
INNER JOIN sys.indexes AS i WITH(NOLOCK)
ON i.object_id = p.object_id
AND i.index_id = p.index_id
WHERE
p.hobt_id = @hobt_id;
SELECT @tablename AS TableName, @indexname AS IndexName; -- 確認用
EXEC(
'SELECT TOP 1 ''' + @tablename + ''' AS wait_table_name, ''' + @indexname + ''' AS index_name, *
FROM ' + @schemaname + '.' + @tablename + ' with(NOLOCK)
WHERE %%lockres%% = ''' + @lock_res + ''''
);
- 実行結果
終わりに
上記を整理していき、実際の呼び出し元のコードと同一トランザクションで実行されているクエリなどとを照らし合わせていくことで下記のような整理ができていきます。
ここまで整理できると、データベースについて詳しくない方にも発生した事象の説明が伝わりやすくなり、また、改善案の提案・相談もしやすくなるように思います。