T-SQLだけでSQL Traceしてトレースファイルの中身まで確認

SQL Server の Express エディションではトレース用のツールが利用できません。
でも、プログラムの発行しているSQLを調べたいとか、なんだかLockしているっぽい動作しているけど。。なんて時にどうしてもトレースを使って調べたくなることがあります。。よね

T-SQLだけで SQL Trace して保存したトレースファイルの中身までちゃんと確認するための手順です。

とりあえず、話を分かりやすくするために、特定のユーザが発行したSQLのみを対象に取得する手順にしときます

#トレース設定

”TEST_USER”という名前のユーザのみを対象
トレースファイルは C:\TEMP\trc.trc として保存します

USE [master]
GO

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

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

DECLARE @on bit
set @on = 1

--トレース対象イベントを設定
--RPC:Completed イベント クラス イベントの種類 = 10。
EXEC  sp_trace_setevent  @TraceID,  10,   1, @on  -- TextData -- リモート プロシージャ コールのテキスト。
EXEC  sp_trace_setevent  @TraceID,  10,  13, @on  -- Duration -- イベントにかかった時間 (マイクロ秒)。
EXEC  sp_trace_setevent  @TraceID,  10,  14, @on  -- StartTime -- イベントの開始時刻 (取得できた場合)。
EXEC  sp_trace_setevent  @TraceID,  10,  15, @on  -- EndTime -- リモート プロシージャ コールの終了時刻。
EXEC  sp_trace_setevent  @TraceID,  10,  31, @on  -- Error -- 特定のイベントのエラー番号。
EXEC  sp_trace_setevent  @TraceID,  10,  34, @on  -- ObjectName -- 参照されているオブジェクトの名前。
EXEC  sp_trace_setevent  @TraceID,  10,  51, @on  -- EventSequence -- 要求内の特定のイベントのシーケンス。
EXEC  sp_trace_setevent  @TraceID,  10,  66, @on  -- GroupID -- SQL トレース イベントが発生したワークロード グループの ID。

--SQL:BatchCompleted イベント クラスのデータ列  イベントの種類 = 12。
EXEC  sp_trace_setevent  @TraceID,  12,   1, @on  -- TextData -- バッチのテキスト。
EXEC  sp_trace_setevent  @TraceID,  12,  13, @on  -- Duration -- イベントにかかった時間 (マイクロ秒)。
EXEC  sp_trace_setevent  @TraceID,  12,  14, @on  -- StartTime -- イベントの開始時刻 (取得できた場合)。
EXEC  sp_trace_setevent  @TraceID,  12,  15, @on  -- EndTime -- イベントが終了した時刻。SQL:BatchStarting や SP:Starting などの開始イベント クラスについては、この列に値が格納されません。
EXEC  sp_trace_setevent  @TraceID,  12,  31, @on  -- Error -- イベントのエラー番号。
EXEC  sp_trace_setevent  @TraceID,  12,  51, @on  -- EventSequence -- 要求内の特定のイベントのシーケンス。
EXEC  sp_trace_setevent  @TraceID,  12,  66, @on  -- GroupID -- SQL トレース イベントが発生したワークロード グループの ID。

--フィルタ
--  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
--
-- ユーザの限定 : LoginName ::  0(AND) 11(LoginName) 0(=) N'TEST_USER'
EXEC sp_trace_setfilter @TraceID, 11, 0, 0, N'TEST_USER'

-- ユーザ操作のみの指定 ： IsSystem  :: 0(AND) 60(IsSystem) 0(=) 0
EXEC sp_trace_setfilter @TraceID, 60, 0, 0, 0

-- 不要分の削除 ： Text  :: 0(AND)  1(Text) 7(Not Like) N'SET %'
EXEC sp_trace_setfilter @TraceID,  1, 0, 7, N'SET %'
EXEC sp_trace_setfilter @TraceID,  1, 0, 7, N'%EXEC sp_MShelpcolumns %'
EXEC sp_trace_setfilter @TraceID,  1, 0, 7, N'%exec sp_unprepare%'
EXEC sp_trace_setfilter @TraceID,  1, 0, 7, N'%exec sp_executesql%'

-- トレース開始
EXEC sp_trace_setstatus @TraceID, 1

select TraceID=@TraceID
goto finish

error: 
select ErrorCode=@rc

finish:
go

TraceID
2

うまく実行できたらトレースIDが表示されます
ここでは、IDは２番が採番されたようです

#トレース状況の確認

SELECT *  
  FROM ::fn_trace_getinfo(default)  

traceid	property	value
1	1	2
1	2	c:\Program Files\Microsoft SQL Server\MSSQL10_50.MSSQLSERVER\MSSQL\Log\log_48.trc
1	3	20
1	4	NULL
1	5	1
2	1	0
2	2	C:\TEMP\trc.trc
2	3	100
2	4	NULL
2	5	1

トレースID １ はデフォルトで動いていたようです
トレースID ２ のプロパティ５ が ”１”なので、実行中です
https://msdn.microsoft.com/ja-jp/library/ms173875.aspx

#ユーザ作業
きちんとトレース取れているか、SQLを発行してみます

###テーブル作成

USE [TEST_DB]
GO
CREATE TABLE TEST_TBL
(
  ID   INT       NOT NULL  IDENTITY(1, 1),
  TXT  NCHAR(10)     NULL
) ON [PRIMARY]

###データ投入（INSERT)

INSERT INTO TEST_TBL (TXT) VALUES (N'TEST1')

###表示（SELECT)

SELECT *  FROM TEST_TBL

トレース表示

とりあえず、最低限だけSELECTします
他にもいろんな情報あるので、SELECT ＊ で見てみるとよいかも

SELECT SPID, EventClass, StartTime, EndTime, Duration, TextData
  FROM ::fn_trace_gettable ( N'C:\TEMP\trc.trc' , 0 )  

SPID	EventClass	StartTime	EndTime	Duration	TextData
NULL	65528	NULL	NULL	NULL	NULL
NULL	65534	2016-12-13 11:13:18.690	NULL	NULL	NULL
60	12	2016-12-13 11:13:26.497	2016-12-13 11:13:26.497	244	USE [TEST_DB]
60	12	2016-12-13 11:13:26.497	2016-12-13 11:13:26.503	8345	CREATE TABLE TEST_TBL ( ID INT NOT NULL IDENTITY(1, 1), TXT NCHAR(10) NULL ) ON [PRIMARY]
60	12	2016-12-13 11:13:29.970	2016-12-13 11:13:29.973	2792	INSERT INTO TEST_TBL (TXT) VALUES (N'TEST1')
60	12	2016-12-13 11:13:32.583	2016-12-13 11:13:32.583	769	SELECT * FROM TEST_TBL

発行したSQLがきちんと取れているようです。

トレースはシステムに付加をかけ続けるため、必要がなくなったらちゃんと停止して削除しておくことをおすすめします。

#トレース停止＆削除

実行にはトレースIDが必要なので、発行時のやつを覚えておくか、確認してから指定してください

---停止
EXEC sp_trace_setstatus 2, 0   -- 2 がトレースID　、　0 は停止命令

---削除
EXEC sp_trace_setstatus 2, 2   -- 最初の 2 がトレースID　、　2 は削除命令

今回はイベントID１０(RPC:Completed)と１２(SQL:BatchCompleted)を取りましたが、トレースしたいイベント（ロックイベントなどなど）についてはMicrosoftのサイトを参照
必要なやつを見つけてくださいです。
https://msdn.microsoft.com/ja-jp/library/ms175481(v=sql.105).aspx

また、トレースで不要なデータがいっぱい出てきちゃったりすると見るのもうんざりしちゃうので、うまくフィルタを設定して（sp_trace_setfilter）目的のデータを探しやすくしとくのが良いと思います。