T-SQLでトレースしてみるの実践
SELECTがなかなか帰ってこない！！
どうやらブロックされているみたいだ
誰が？どのプロセスが？ってことをトレースしてみます
SQL Server の Express エディションだとトレースのツールが使えないのでT-SQLだけで頑張ってみます
実験概要
テーブルに対して１秒毎にSELECTしているプロセスがある
同じテーブルに対してインデックス指定でUPDATEするプロセスがある
UPDATEはトランザクションをかけて行う
UPDATEのトランザクションが終わるまではSELECTがブロックされる
・・という状況を作ります
ちなみにOracleではこれは起こりません。
トランザクションが COMMIT されるまでは、UPDATE前の情報で普通にSELECT可能ですが、SQL SERVERだとブロックされちゃうんですよね
欠陥ＤＢだと思うのだけれど。。。
実験用テーブル
こんな感じのテーブルを利用
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
ブロックのトレース取得
５秒以上ブロックされてたらトレース情報を保存するように指定です
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 で利用状況モニタを起動して、１秒毎に更新設定
状況のモニタリングをしておく
実験用スクリプトを実行
DOS窓（黒い画面）を２画面開いて実験用スクリプトを実行してみます
画面１：
画面２：
画面２でUPDATEを実行すると、画面１のSELECTが止まることが確認できる。。ハズ
同時に利用状況モニタを見てみると、LOCK されているのが確認できる。。ハズ
画面２のUPDATEスクリプトはキー入力するまでトランザクション維持なので、何度か繰り返してみるとよくわかると思う
あまり待たせるとSELECT側がタイムアウトしちゃいますヨ
トレースの確認
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
ブロックされている状況がトレースできているはず
７行目の TextData 欄を詳しく見てみると。。
（コピーして xmlの拡張子を付けて保存して開いてみると。。）
Blocked-Process とか Blocking-Process とかの情報が詳しく載ってます。
どんなSQL文でブロックされてたのかも一目瞭然
誰が？（TEST_USERが）とかどのプロセスが？（SPID=54が）とかが丸わかりです