SQL Server ExpressでT-SQLのみでSELECTをブロックしているUPDATEをトレースしてみる

T-SQLでトレースしてみるの実践

SELECTがなかなか帰ってこない！！
どうやらブロックされているみたいだ
誰が？どのプロセスが？ってことをトレースしてみます

SQL Server の Express エディションだとトレースのツールが使えないのでT-SQLだけで頑張ってみます


# 実験概要

テーブルに対して１秒毎にSELECTしているプロセスがある
同じテーブルに対してインデックス指定でUPDATEするプロセスがある
UPDATEはトランザクションをかけて行う
UPDATEのトランザクションが終わるまではSELECTがブロックされる
・・という状況を作ります

ちなみにOracleではこれは起こりません。
トランザクションが COMMIT されるまでは、UPDATE前の情報で普通にSELECT可能ですが、SQL SERVERだとブロックされちゃうんですよね
欠陥ＤＢだと思うのだけれど。。。



# 実験用テーブル

こんな感じのテーブルを利用

```SQL:
SELECT *
  FROM TEST_TBL
```

|ID|TXT|
|:-:|:-:|
|1|TEST1|
|2|TEST2|
|3|TEST3|
|4|TEST4|
|5|TEST5|
|6|TEST6|
|7|TEST7|
|8|TEST8|
|9|TEST9|




#実験用スクリプト

## SELECT

１秒毎にテーブルをSELECTする VBScript のサンプルです

```SELECT-TEST.vbs
'//===================================================================
'// VBScript から ＤＢに接続してロック状態を再現する(SELECT)
Option Explicit
Randomize()


'//===================================================================
'// 初期設定
Dim server, db
server = "TEST-SERVER"                       '// 接続先サーバ
db = "TEST_DB"                               '// 接続先ＤＢ


'//===================================================================
'// 引数からログインユーザとパスワードを取得
Dim user, pass
If WScript.Arguments.count <> 2 Then
    WScript.Echo WScript.ScriptName & " DBユーザ  DBパスワード"
    WScript.Quit -1
Else
    user = WScript.Arguments(0)
    pass = WScript.Arguments(1)
End If


'//===================================================================
'// DB OPEN
WScript.Echo "DB OPEN - SERVER:" & server & "  DB:" & db 
WScript.Echo "DB USER: " & user
WScript.Echo "DB PASS: " & pass
Dim con
Set con = WScript.CreateObject("ADODB.Connection")
con.Open _
    "Provider=SQLOLEDB.1;"        & _
    "Data Source=" & server & ";" & _
    "Initial Catalog=" & db & ";" & _
    "PERSIST SECURITY INFO=TRUE;" & _
    "USER ID="  & user & ";"      & _
    "PASSWORD=" & pass & ";"      & _
    ""


'//===================================================================
'// 設定　タイムアウト30秒、ロック待ち10秒、カーソル設定
con.CommandTimeout = 30
con.Execute "SET LOCK_TIMEOUT 10000"
con.CursorLocation = 3 ' クライアントサイドカーソルに変更


'//===================================================================
'// SELECT - LOOP
Dim sql, rs, wk
do
    sql = _
        "SELECT * " & _
        "  FROM TEST_TBL " & _
        ""
    WScript.Echo VbCrLf & sql

    Set rs = con.Execute(sql) 
    Do Until rs.eof
        WScript.Echo Now() & " - ID: " & rs.Fields("ID") & "  TXT: " & rs.Fields("TXT")
        rs.MoveNext
    Loop
    rs.close
    Set rs = Nothing
    
    '//===================================================================
    '// 指定時間スリープ（ミリ秒指定：１０００＝１秒）
    WScript.Sleep 1234
loop


'//===================================================================
'// DB CLOSE - 処理終了
con.Close
Set con = Nothing

```

## UPDATE

トランザクションをかけてUPDATEを発行。
キー入力されるまでトランザクションを維持
トランザクションが維持されている間は。。SELECTがブロックされちゃう という VBScript のサンプルです

```UPDATE-TEST.vbs
'//===================================================================
'// VBScript から ＤＢに接続してロック状態を再現する
Option Explicit
Randomize()


'//===================================================================
'// 初期設定
Dim server, db
server = "TEST-SERVER"                       '// 接続先サーバ
db = "TEST_DB"                               '// 接続先ＤＢ


'//===================================================================
'// 引数からログインユーザとパスワードを取得
Dim user, pass
If WScript.Arguments.count <> 2 Then
    WScript.Echo WScript.ScriptName & " DBユーザ  DBパスワード"
    WScript.Quit -1
Else
    user = WScript.Arguments(0)
    pass = WScript.Arguments(1)
End If


'//===================================================================
'// DB OPEN
WScript.Echo "DB OPEN - SERVER:" & server & "  DB:" & db 
WScript.Echo "DB USER: " & user
WScript.Echo "DB PASS: " & pass
Dim con
Set con = WScript.CreateObject("ADODB.Connection")
con.Open _
    "Provider=SQLOLEDB.1;"        & _
    "Data Source=" & server & ";" & _
    "Initial Catalog=" & db & ";" & _
    "PERSIST SECURITY INFO=TRUE;" & _
    "USER ID="  & user & ";"      & _
    "PASSWORD=" & pass & ";"      & _
    ""


'//===================================================================
'// 設定　タイムアウト30秒、ロック待ち10秒、カーソル設定
con.CommandTimeout = 30
con.Execute "SET LOCK_TIMEOUT 10000"
con.CursorLocation = 3 ' クライアントサイドカーソルに変更


'//===================================================================
'// UPDATE - LOOP
Dim sql, rs, wk
do
    sql = _
        "UPDATE TEST_TBL " & _
        "   SET TXT = N'UPDATE' " & _
        " WHERE ID  = '" & Int(Rnd() * 9) + 1  & "' " & _
        ""
    
    WScript.Echo sql
    con.Execute("BEGIN TRANSACTION")
    con.Execute(sql) 
    
    WScript.Echo "UPDATE..."
    wk = WScript.StdIn.ReadLine
    con.Execute("ROLLBACK TRANSACTION")
    
    WScript.Echo "COMMIT"
    wk = WScript.StdIn.ReadLine
    If wk = "exit" Then Exit Do
    
loop


'//===================================================================
'// DB CLOSE - 処理終了
con.Close
Set con = Nothing
```


# ブロックのトレース取得

５秒以上ブロックされてたらトレース情報を保存するように指定です

```SQL
sp_configure 'show advanced options', 1 ;
GO
RECONFIGURE ;
GO
sp_configure 'blocked process threshold', 5 ;
GO
RECONFIGURE ;
GO

DECLARE @rc int
DECLARE @TraceID int
DECLARE @maxfilesize bigint
DECLARE @file nvarchar(4000)
SET @maxfilesize = 100
SET @file = N'C:\TEMP\Block'

EXEC @rc = sp_trace_create @TraceID output, 0, @file, @maxfilesize, NULL
IF (@rc != 0) GOTO error

DECLARE @on bit
SET @on = 1

--Blocked Process Report イベント クラスのデータ列
-- exec  sp_trace_setevent  @TraceID,  137,  27, @on  -- EventClass -- イベントの種類 = 137。
exec  sp_trace_setevent  @TraceID,  137,   1, @on  -- TextData -- トレースでキャプチャされたイベント クラスに依存するテキスト値。
exec  sp_trace_setevent  @TraceID,  137,   3, @on  -- DatabaseID -- ロックが取得されたデータベースの ID。ServerName?データ列がトレースにキャプチャされ、サーバーが使用できる場合、SQL Server Profiler にデータベースの名前が表示されます。データベースに対応する値は、DB_ID 関数を使用して特定します。
exec  sp_trace_setevent  @TraceID,  137,   4, @on  -- TransactionID -- トランザクションにシステムが割り当てた ID。
exec  sp_trace_setevent  @TraceID,  137,  13, @on  -- Duration -- プロセスがブロックされていた時間 (ミリ秒)。
exec  sp_trace_setevent  @TraceID,  137,  15, @on  -- EndTime -- イベントが終了した時刻。この列は、SQL:BatchStarting?や?SP:Starting?などの開始イベント クラスでは設定されません。
exec  sp_trace_setevent  @TraceID,  137,  22, @on  -- ObjectID -- ロックを取得したオブジェクトのシステム割り当て ID (使用可能かつ適用可能な場合)。
exec  sp_trace_setevent  @TraceID,  137,  24, @on  -- IndexID -- イベントの影響を受けるオブジェクトに付けられたインデックス用の ID。オブジェクトのインデックス ID を決定するには、sysindexes?システム テーブルの?indid?列を使用します。
exec  sp_trace_setevent  @TraceID,  137,  26, @on  -- ServerName -- トレースされている SQL Server のインスタンスの名前。
exec  sp_trace_setevent  @TraceID,  137,  32, @on  -- Mode -- イベントが受け取った状態またはイベントが要求している状態。
exec  sp_trace_setevent  @TraceID,  137,  41, @on  -- LoginSid -- ログイン ユーザーのセキュリティ ID 番号 (SID)。このイベントは必ずシステム スレッドから報告されます。IsSystem は 1、SID は sa です。
exec  sp_trace_setevent  @TraceID,  137,  51, @on  -- EventSequence -- 要求内の特定のイベントのシーケンス。
exec  sp_trace_setevent  @TraceID,  137,  60, @on  -- IsSystem -- イベントがシステム プロセスで発生したか、ユーザー プロセスで発生したかを示します。1 = システム、0 = ユーザーです。
exec  sp_trace_setevent  @TraceID,  137,  64, @on  -- SessionLoginName -- セッションを開始したユーザーのログイン名。たとえば、Login1 を使用して SQL Server に接続し、Login2 でステートメントを実行すると、SessionLoginNameには Login1 が表示され、LoginName?には Login2 が表示されます。この列には、SQL Server ログインと Windows ログインの両方が表示されます。

--フィルタ
--  sp_trace_setfilter 
--       [ @traceid = ] 
--     , [ @columnid = ] 
--     , [ @logical_operator = ] 0:AND  1:OR
--     , [ @comparison_operator = ] 0:=  1:<>  2:>  3:<  4:>=  5:<=  6:LIKE  7:NOT LIKE
--     , [ @value = ] value
--

-- 特定テーブルのみを対象 : ObjectID(22)
--DECLARE @objid int
--SELECT  @objid = obj.object_id  FROM  sys.objects as obj WHERE  obj.name like 'TEST_TBL'
--EXEC sp_trace_setfilter @TraceID,  22, 1, 0, @objid

-- 開始
EXEC sp_trace_setstatus @TraceID, 1

SELECT TraceID=@TraceID
GOTO finish

error: 
SELECT ErrorCode=@rc

finish:
GO




---開始
--EXEC sp_trace_setstatus 2, 1

---停止
--EXEC sp_trace_setstatus 2, 0

---削除
--EXEC sp_trace_setstatus 2, 2

---確認
--SELECT *  
--  FROM ::fn_trace_getinfo(default)  
--
--SELECT * 
--  FROM ::fn_trace_geteventinfo ( trace_id )  
--
--SELECT * 
--  FROM ::fn_trace_getfilterinfo ( trace_id )  


---トレースファイル読み込み
--SELECT *
--  FROM ::fn_trace_gettable ( N'C:\TEMP\Block.trc' , 0 )  

```


# モニタリング開始

SQL ServerのManagement Studio で利用状況モニタを起動して、１秒毎に更新設定
状況のモニタリングをしておく

![20161215-00.png](https://qiita-image-store.s3.amazonaws.com/0/153259/590ff108-5c4f-0acd-c6df-6140ee0c6fef.png)


# 実験用スクリプトを実行
DOS窓（黒い画面）を２画面開いて実験用スクリプトを実行してみます

画面１：
![20161215-02.png](https://qiita-image-store.s3.amazonaws.com/0/153259/b30efbaa-48a5-ca7e-6e62-f65034c17b07.png)

画面２：
![20161215-03.png](https://qiita-image-store.s3.amazonaws.com/0/153259/3f78c636-9821-c01e-5167-a244e305b43c.png)


画面２でUPDATEを実行すると、画面１のSELECTが止まることが確認できる。。ハズ

同時に利用状況モニタを見てみると、LOCK されているのが確認できる。。ハズ
![20161215-04.png](https://qiita-image-store.s3.amazonaws.com/0/153259/84f4fb43-0f36-0bc9-c473-baa626b2d181.png)


画面２のUPDATEスクリプトはキー入力するまでトランザクション維持なので、何度か繰り返してみるとよくわかると思う
あまり待たせるとSELECT側がタイムアウトしちゃいますヨ



#トレースの確認



```SQL:ShowBlockTrace.sql
SELECT EventClass
     , StartTime
     , EndTime
     , Duration
     , Mode
     , CASE Mode
           WHEN  0 THEN 'NULL'
           WHEN  1 THEN 'Sch-S'
           WHEN  2 THEN 'Sch-M'
           WHEN  3 THEN 'S'
           WHEN  4 THEN 'U'
           WHEN  5 THEN 'X'
           WHEN  6 THEN 'IS'
           WHEN  7 THEN 'IU'
           WHEN  8 THEN 'IX'
           WHEN  9 THEN 'SIU'
           WHEN 10 THEN 'SIX'
           WHEN 11 THEN 'UIX'
           WHEN 12 THEN 'BU'
           WHEN 13 THEN 'RangeS-S'
           WHEN 14 THEN 'RangeS-U'
           WHEN 15 THEN 'RangeI-N'
           WHEN 16 THEN 'RangeI-S'
           WHEN 17 THEN 'RangeI-U'
           WHEN 18 THEN 'RangeI-X'
           WHEN 19 THEN 'RangeX-S'
           WHEN 20 THEN 'RangeX-U'
           WHEN 21 THEN 'RangeX-X'
       End AS 'ModeCase'
     , DatabaseID
     , ObjectID
     , OBJECT_NAME( ObjectID, DatabaseID ) AS 'ObjectName'
     , TextData
  FROM ::fn_trace_gettable ( N'C:\TEMP\Block.trc' , 0 )  
GO
```

![20161215-05.png](https://qiita-image-store.s3.amazonaws.com/0/153259/ae3d8c96-73e0-5dc5-4ff0-5544bcf16448.png)


ブロックされている状況がトレースできているはず
７行目の TextData 欄を詳しく見てみると。。
（コピーして xmlの拡張子を付けて保存して開いてみると。。）
![20161215-06.png](https://qiita-image-store.s3.amazonaws.com/0/153259/7ff934e9-a565-b6bf-2265-02c4e3cb4ba3.png)

Blocked-Process とか Blocking-Process とかの情報が詳しく載ってます。
どんなSQL文でブロックされてたのかも一目瞭然
誰が？（TEST_USERが）とかどのプロセスが？（SPID=54が）とかが丸わかりです