SQL Serverにおけるデッドロックイベントの収集および調査について

:::note info
この記事は [ZOZO Advent Calendar 2023](https://qiita.com/advent-calendar/2023/zozo)  カレンダー Vol.3の 10日目の記事です。
:::
本記事ではSQL Serverで発生するデッドロックの収集から調査までをサンプルDBで実際に発生させながら紹介します。

# SQL Serverにおけるデッドロックについて

デッドロック（Deadlock）は、複数のプロセスやスレッドが互いに相手の動作を待ってしまい、最終的に進行が停滞してしまう状態を指します。
SQL Serverではデッドロックモニターという検出用バックグラウンドプロセスが動いていて、
検出され次第原因となっているプロセスがキルされます。(検出の間隔はデフォルト5秒)

自動でキルされることもあり、稀に発生するだけであれば大きな問題とはなりにくいです。
しかし、瞬間的に大量に更新されるケースなど、デッドロックが連なってしまってロック範囲が拡大してしまうなど、
大量の処理がブロックされてしまうとWorkerやConnectionの枯渇を引き起こし、大きな障害に繋がる可能性があります。

# デッドロック収集用の拡張イベントの設定

SQL Server では拡張イベントを使用することで発生したデッドロックを記録することができます。
デフォルトで起動している [system_health セッション](https://learn.microsoft.com/ja-jp/sql/relational-databases/extended-events/use-the-system-health-session?view=sql-server-ver16)でも確認できますが、
他のイベントも収集している都合上、時間経過で消えてしまう可能性があります。

新規セッションとして登録しておくことで長期間残すことが可能です。

## SQL Server Management Stduio(SSMS) からの拡張イベント設定例

以下は設定例です。

1. 新規セッションをクリック
![image.png](https://qiita-image-store.s3.ap-northeast-1.amazonaws.com/0/299916/a3b91cab-d34f-0165-9ddd-cc675f809088.png)

2. セッション名の入力
![image.png](https://qiita-image-store.s3.ap-northeast-1.amazonaws.com/0/299916/1cc5b3a0-ce4c-e0ca-36d6-12e611bdd5d7.png)

3. xml_deadlock_reportをキャプチャ対象として選択
![image.png](https://qiita-image-store.s3.ap-northeast-1.amazonaws.com/0/299916/d40bb37a-97e1-f387-5ddb-95ce7cfef3b2.png)

4. イベントファイルの保存先を設定する
![image.png](https://qiita-image-store.s3.ap-northeast-1.amazonaws.com/0/299916/5fc222a5-f957-6d2b-5547-75e345966c64.png)

5. OKボタンを押して作成する
![image.png](https://qiita-image-store.s3.ap-northeast-1.amazonaws.com/0/299916/7a97065b-d1c5-60eb-26c7-766f0e6c7432.png)
▶︎マークがついていたら起動しています。

# サンプルDBでデッドロックを意図的に発生させる

実際にデッドロックを発生させて上記で設定した拡張イベントに記録されることを確認します。

- 使用した環境
  - SQL Server 2016
  - データベースは [AdventureWorks サンプル データベース](https://learn.microsoft.com/ja-jp/sql/samples/adventureworks-install-configure?view=sql-server-ver16&tabs=ssms) を使用

具体的な手順は次の通りです。
1. AdventureWorksのDBに接続してタブを開き、下記のクエリを実行する
```sql:行ロックによるデッドロック:タブ1
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秒以内に別のタブで、下記のクエリを実行する
```sql:行ロックによるデッドロック:タブ2
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
```
下記のように片方のタブでデッドロックが発生する
![image.png](https://qiita-image-store.s3.ap-northeast-1.amazonaws.com/0/299916/945a87ae-1b12-53ef-59cd-9de86d11dc6e.png)

# 記録されたデッドロックイベントを確認する

上記を発生させると拡張イベントにデッドロックのイベントが記録されます
![image.png](https://qiita-image-store.s3.ap-northeast-1.amazonaws.com/0/299916/8d893902-6b8e-9b3d-a976-dd1728aab7bd.png)

ここのデッドロックタブをクリックするとデッドロックグラフが確認でき、値をダブルクリックするとXMLで表示することができます
![image.png](https://qiita-image-store.s3.ap-northeast-1.amazonaws.com/0/299916/021f1584-49a8-c003-6d96-33f9ae9b6223.png)

## デッドロックイベントの個別の保存方法

拡張イベントに記録された中で個別で抜き出して共有・保存したい時があります。
そういった場合、XML表示をしている状態で「ファイル」 → 「名前を付けて保存」を押下し、ファイルを「すべてのファイル」として拡張子`xdl`で保存することで `Microsoft SQL Server Deadlock File` として保存ができます。
![image.png](https://qiita-image-store.s3.ap-northeast-1.amazonaws.com/0/299916/31fd4c01-441c-c2ca-f0cb-e042ba865ff6.png)

- 保存されたファイル
    - ![image.png](https://qiita-image-store.s3.ap-northeast-1.amazonaws.com/0/299916/50380989-b85a-7b22-ca40-97185f646f97.png)
- 開くとSSMSが起動し、デッドロックグラフの確認が可能
    - ![image.png](https://qiita-image-store.s3.ap-northeast-1.amazonaws.com/0/299916/370d0b23-bfa5-ea66-cbb4-a3abc03ac625.png)

# デッドロックの分析
デッドロックグラフの画面ではプロセスにカーソルを合わせることでinputbufに記録されているクエリ(デッドロック発生時にそのプロセスで実行されていたクエリ)を確認できます。
![image.png](https://qiita-image-store.s3.ap-northeast-1.amazonaws.com/0/299916/205a0fab-4d4f-652f-0c49-abc3db30c05f.png)

例えば上記のデッドロックグラフからは次のような情報を取得することができます。
- プロセス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と紐付けることができます。
![image.png](https://qiita-image-store.s3.ap-northeast-1.amazonaws.com/0/299916/c812b916-6a43-61fb-b7ab-bf66237d2677.png)

wait_resourceの実オブジェクトの特定については以下の記事が大変参考になります。
- [SQL Server の Wait Resource から実オブジェクトを判断する at SE の雑記](https://blog.engineer-memo.com/2019/10/06/sql-server-%E3%81%AE-wait-resource-%E3%81%8B%E3%82%89%E5%AE%9F%E3%82%AA%E3%83%96%E3%82%B8%E3%82%A7%E3%82%AF%E3%83%88%E3%82%92%E5%88%A4%E6%96%AD%E3%81%99%E3%82%8B/)

今回のケースでは次のクエリを実行することで、実際にどのようなレコードか特定できます。
```sql:keyロックの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 + ''''
);

```
- 実行結果
![image.png](https://qiita-image-store.s3.ap-northeast-1.amazonaws.com/0/299916/24bb24ff-80dc-2608-b3f2-f825cc02fea7.png)


# 終わりに

上記を整理していき、実際の呼び出し元のコードと同一トランザクションで実行されているクエリなどとを照らし合わせていくことで下記のような整理ができていきます。
![image.png](https://qiita-image-store.s3.ap-northeast-1.amazonaws.com/0/299916/4a7a98c2-d373-a98a-d766-f8f8e3eb4f90.png)

ここまで整理できると、データベースについて詳しくない方にも発生した事象の説明が伝わりやすくなり、また、改善案の提案・相談もしやすくなるように思います。