SQL Server: ブロッキングが起きていないようで実は起きている状況について解説

背景

SQL Serverで現在実行中のクエリをリストアップする際はDMVのsys.dm_exec_requestsを使用するかと思います。
実行するクエリの例としては以下のようなものが考えられます。

set transaction isolation level read uncommitted
SELECT TOP 100
     der.session_id as spid
    ,der.blocking_session_id as blk_spid
    ,datediff(s, der.start_time, GETDATE()) as elapsed_sec
    ,DB_NAME(der.database_id) AS db_name
    ,des.host_name
    ,des.program_name
    ,der.status
    ,dest.text as command_text
    ,REPLACE(REPLACE(REPLACE(SUBSTRING(dest.text, 
    (der.statement_start_offset / 2) + 1, 
    ((CASE der.statement_end_offset
    WHEN -1 THEN DATALENGTH(dest.text)
    ELSE der.statement_end_offset
    END - der.statement_start_offset) / 2) + 1),CHAR(13), ' '), CHAR(10), ' '), CHAR(9), ' ') AS current_running_stmt
    ,datediff(s, der.start_time, GETDATE()) as time_sec
    ,wait_resource --ロックされているリソース名
    ,wait_type
    ,last_wait_type --最後または現在の待機の種類の名前
    ,der.wait_time  as wait_time_ms
    ,der.open_transaction_count
    ,der.command
    ,der.percent_complete
    ,der.cpu_time
    ,(case der.transaction_isolation_level
      when 0 then 'Unspecified'
      when 1 then 'ReadUncomitted'
      when 2 then 'ReadCommitted'
      when 3 then 'Repeatable'
      when 4 then 'Serializable'
      when 5 then 'Snapshot'
    else cast(der.transaction_isolation_level as varchar) end) as transaction_isolation_level
    ,der.granted_query_memory * 8 as granted_query_memory_kb --キロバイト単位
FROM
    sys.dm_exec_requests der
JOIN sys.dm_exec_sessions des ON des.session_id = der.session_id
OUTER APPLY sys.dm_exec_sql_text(sql_handle) AS dest
WHERE
    des.is_user_process = 1
and datediff(s, der.start_time, GETDATE()) >= 1
ORDER BY
    datediff(s, der.start_time, GETDATE()) DESC

このクエリを実行したときに、以下のような結果が取得できたとします。

wait_type / last_wait_typeともにCXPACKETなので、並列処理の完了を待っていることが分かります。
また、ブロッキングプロセスを示すblk_spid列（もともとは「blocking_session_id」）も0なので、一件するとシンプルに大量のデータを読み取るSELECT文において並列でデータを読み取っているんだな、と捉えてしまいがちです。

ただ、このような状況でもブロッキングが実は発生している、ということがあります。
今回はその事象について解説します。

状況のセットアップ

以下のクエリを実行して、1レコード更新した状態でトランザクションを開きっぱなしにしておきます。

begin tran
delete from Member where MemberID = 18629765

次に、別のクエリウインドウでselect文を実行します。

--1000万レコードのテーブルに対してcount(*)
select count(*) from Member

これで冒頭で示した、exec_requestsでみると並列実行しているようだが、実際はブロッキングによって処理がとまっている状況をつくることができました。

調査

今回は意図的に並列実行クエリがブロックされている状況を作り出しましたが、状況が分かっていない場合に、どのように原因を突き止めればいいでしょうか。その方法について考えてみます。

1. 拡張イベントを使う

拡張イベントで「blocked_process_report」イベントを収集対象にします。

以下のように、ブロッキングイベントが収集されます。

「blocked_process」フィールドをダブルクリックすると、詳細を確認できます。
ブロッカーが、トランザクションを開きっぱなしのDELETE文であることを突き止めることができました。

2. dm_os_waiting_tasksを使う

DMVを使うことでも原因を追うことができます。dm_os_waiting_tasksを使います。該当のsession_idを指定して絞り込みます。

select * from sys.dm_os_waiting_tasks where session_id = 103

↓のような結果となりました。

wait_typeに着目すると、1つのタスクだけがwait_type=LCK_M_Sと、ロック待ち（ブロッキング）となっていることが分かります。
それ以外のタスクについてはCXPACKET待ちとなっているので、ロック待ちのタスクが完了するのを待っている（つまり、ロック待ちタスク以外のタスクは全て実行が完了している）と分かります。

blocking_session_idに着目すると、session_id=104が原因でロック待ちとなっていることが分かります。
それ以外のタスクでblocking_session_id=103となっているのは、CXPACKET待ちなので自分自身にブロックされている、というイメージです。

あとは104のプロセスが何者かを解決します。

dbcc inputbuffer(104)

原因を突き止めることができました。

まとめ

ロックについて以下の2記事で解説してきましたが、その中で解説していなかった「一見ブロッキングされていなさそうだが、ブロッキングされている状況」について説明しました。
https://qiita.com/maaaaaaaa/items/38fd95b142b07acf7700
https://qiita.com/maaaaaaaa/items/28c8a1affe36a6bd811a