小物SEのメモ帳

IT関係の試したことや調べたことの備忘録

【SQL Server】クエリ実行時の待機イベントを確認する

SQL Server

クエリチューニングを実施する際に実行プランやIO、実行時間を確認することが多いかと思いますが、実行時間のうち待機イベントと待機時間を確認する方法の説明です。

以下を使用してCPU時間と実行時間を確認することが多いのではないでしょうか。

SET STATISTICS TIME ON
-- 実行時間を計測するクエリ
SET STATISTICS TIME OFF

f:id:utiowa:20170611152311p:plain

お手軽にCPU時間と実行時間を確認することができますが、実行時間のうちCPU以外の待機はどのようであったか把握できません。

拡張イベントwait_comletedを使う

SQLServer2014以降から、待機イベントにかかった時間としてwait_completedが追加されており、待機イベントが終了した時にイベント名と経過時間を記録してくれます。
ただし、各イベントの待機時間の取得している単位以下は丸められてしまっているので、待機事象のミリ秒以下まで正確に把握したい場合があれば、wait_completedではなくwait_infoやwait_info_externalの開始時間と終了時間の差分を算出して合計すべきかもしれません。
しかしクエリチューニングをするうえでは細かい数字の積み上げよりも、どの待機イベントで大きく待ちが発生しているか把握する方が大事であるため、気にする必要はないかと。

事前準備

以降で監視するクエリのセッションIDに対し拡張イベントを作成します。
そのため事前にセッションIDを調べておく必要があります。

SELECT @@SPID

もしくはSSMS上のタブからも確認可能です。
f:id:utiowa:20170611160328p:plain

拡張イベントを作成する

事前準備で確認した監視したいセッションIDを指定して拡張イベントを作成します。
以下クエリのxxxは、監視したいセッションIDに置換してください。
また、結果を保存するファイルパスも適宜読み替えてください。

/***************************************/
-- (1)調査対象のセッションIDを確認して
-- 以下xxxをセッションIDに置換してから実行
-- 
-- (2)拡張イベントファイルの保存先も
-- 変更してから実行（36行目）
/***************************************/
CREATE EVENT SESSION [exec_query_wait] ON SERVER 
ADD EVENT sqlos.wait_completed(SET collect_wait_resource=(1)
    ACTION(sqlserver.sql_text)
    WHERE ([package0].[equal_uint64]([sqlserver].[session_id],(xxx)) AND [duration]>(0))),
ADD EVENT sqlserver.query_post_compilation_showplan(
    ACTION(sqlserver.sql_text)
    WHERE ([sqlserver].[session_id]=(xxx))),
ADD EVENT sqlserver.query_post_execution_showplan(
    ACTION(sqlserver.sql_text)
    WHERE ([sqlserver].[session_id]=(xxx))),
ADD EVENT sqlserver.sp_statement_completed(
    ACTION(sqlserver.sql_text)
    WHERE ([sqlserver].[session_id]=(xxx))),
ADD EVENT sqlserver.sp_statement_starting(
    ACTION(sqlserver.sql_text)
    WHERE ([sqlserver].[session_id]=(xxx))),
ADD EVENT sqlserver.sql_batch_completed(
    ACTION(sqlserver.sql_text)
    WHERE ([sqlserver].[session_id]=(xxx))),
ADD EVENT sqlserver.sql_batch_starting(
    ACTION(sqlserver.sql_text)
    WHERE ([sqlserver].[session_id]=(xxx))),
ADD EVENT sqlserver.sql_statement_completed(
    ACTION(sqlserver.sql_text)
    WHERE ([sqlserver].[session_id]=(xxx))),
ADD EVENT sqlserver.sql_statement_starting(SET collect_statement=(1)
    ACTION(sqlserver.sql_text)
    WHERE ([sqlserver].[session_id]=(xxx))) 
ADD TARGET package0.event_file(SET filename=N'C:\Program Files\Microsoft SQL Server\MSSQL13.INS_NISHI2016\MSSQL\Log\wait_event.xel')
WITH (MAX_MEMORY=4096 KB,EVENT_RETENTION_MODE=ALLOW_SINGLE_EVENT_LOSS,MAX_DISPATCH_LATENCY=30 SECONDS,MAX_EVENT_SIZE=0 KB,MEMORY_PARTITION_MODE=NONE,TRACK_CAUSALITY=OFF,STARTUP_STATE=OFF)
GO

ALTER EVENT SESSION [exec_query_wait] ON SERVER STATE = START
GO

-- ===============================
-- 別セッション(session_ID = xxx)でクエリ実行
-- ===============================

上記で指定したセッションIDにて確認したいクエリの実行が完了し、拡張イベントによるトレースが完了したら拡張イベントによる監視終了と、拡張イベントを削除します。

ALTER EVENT SESSION [exec_query_wait] ON SERVER STATE = STOP
GO
DROP EVENT SESSION [exec_query_wait] ON SERVER
GO


結果をSQLで確認する場合は、例えば次のようなSQLで集計するとよいでしょう。
以下SQLでは待機イベントの待機時間の合計とクエリの構文解析・コンパイル時間、クエリ実行時のCPU時間と実行時間を出力しています。
sys.fn_xe_file_target_read_fileのファイルパスは、確認したい結果を保存したパスに適宜読み替えてください。

-- SQL Server2016なら
DROP TABLE IF EXISTS tempdb..#wait_analyze 
GO

-- SQL Server2014まで
/*
IF OBJECT_ID(N'tempdb..#wait_analyze', N'U') IS NOT NULL
	DROP TABLE #wait_analyze
GO
*/

CREATE TABLE #wait_analyze (event_data XML)
GO

INSERT INTO #wait_analyze (event_data)
SELECT CAST(event_data AS XML) AS wait_events
FROM sys.fn_xe_file_target_read_file(	  N'C:\Program Files\Microsoft SQL Server\MSSQL13.INS_NISHI2016\MSSQL\Log\wait_event*.xel'
														, NULL
														, NULL
														, NULL
														)
GO

SELECT
	 [waits].[sql_text]
	,[waits].[wait_type]
	,COUNT([waits].[wait_type]) AS wait_count
	,SUM([waits].[duration_ms]) AS total_wait_time_ms
	,SUM([waits].[signal_duration_ms]) AS total_signal_wait_time_ms
	,SUM([waits].[duration_ms]) - SUM([waits].[signal_duration_ms]) AS total_resource_wait_time_ms
FROM (
	SELECT 
		 event_data.value ('(/event/@timestamp)[1]', 'DATETIME') AS [date]
		,event_data.value ('(/event/@name)[1]' , 'VARCHAR(255)') AS [name]
		,event_data.value ('(/event/data[@name = ''wait_type'']/text)[1]', 'VARCHAR(255)') AS [wait_type]
		,event_data.value ('(/event/data[@name = ''duration'']/value)[1]', 'BIGINT') AS [duration_ms]
		,event_data.value ('(/event/data[@name = ''signal_duration'']/value)[1]', 'BIGINT') AS [signal_duration_ms]
		,event_data.value ('(/event/action[@name = ''sql_text'']/value)[1]', 'VARCHAR(MAX)') AS [sql_text]  
	FROM #wait_analyze
	WHERE event_data.value ('(/event/@name)[1]' , 'VARCHAR(255)') = 'wait_completed'
	) AS waits
GROUP BY [waits].[sql_text],[waits].[wait_type]
ORDER BY total_wait_time_ms DESC
GO

SELECT 
	 [waits].[sql_text] AS [sql_text]
	,[waits].[name] AS [event_name]
	,SUM([waits].[cpu_time_μs])/1000 AS [total_cpu_time_ms]
	,SUM([waits].[duration_μs])/1000 AS [total_elapsed_time_ms]
FROM (
	SELECT 
		 event_data.value ('(/event/@timestamp)[1]', 'DATETIME') AS [date]
		,event_data.value ('(/event/@name)[1]' , 'VARCHAR(255)') AS [name]
		,event_data.value ('(/event/data[@name = ''cpu_time'']/value)[1]', 'BIGINT') AS [cpu_time_μs]
		,event_data.value ('(/event/data[@name = ''duration'']/value)[1]', 'BIGINT') AS [duration_μs]
		,event_data.value ('(/event/action[@name = ''sql_text'']/value)[1]', 'VARCHAR(MAX)') AS [sql_text]  
		,event_data.value ('(/event/data[@name = ''statement'']/value)[1]', 'VARCHAR(MAX)') AS [statement]
	FROM #wait_analyze
	WHERE 
		event_data.value ('(/event/@name)[1]' , 'VARCHAR(255)') IN (
									'query_post_compilation_showplan'
									,'sql_statement_completed'
									,'sp_statement_completed'
									,'sql_batch_completed'
									,'query_post_execution_showplan'
									)
	) AS waits
GROUP BY [waits].[sql_text], [waits].[name]
GO


SELECT 
	 event_data.value ('(/event/@timestamp)[1]', 'DATETIME') AS [date]
	,event_data.value ('(/event/@name)[1]' , 'VARCHAR(255)') AS [name]
	,event_data.value ('(/event/data[@name = ''cpu_time'']/value)[1]', 'BIGINT') AS [cpu_time_μs]
	,event_data.value ('(/event/data[@name = ''duration'']/value)[1]', 'BIGINT') AS [duration_μs]
	,event_data.value ('(/event/action[@name = ''sql_text'']/value)[1]', 'VARCHAR(MAX)') AS [sql_text]  
	,[temp_xml].[xml_plan].query('.') AS [query_plan]
FROM #wait_analyze AS [wait_analyze]
OUTER APPLY [wait_analyze].event_data.nodes(N'/event/data[@name="showplan_xml"]/value/*') AS  temp_xml(xml_plan)
WHERE 
	event_data.value ('(/event/@name)[1]' , 'VARCHAR(255)') IN (
									 'query_post_compilation_showplan'
									,'query_post_execution_showplan'
								    )
GO

f:id:utiowa:20170611154351p:plain


GUIにて確認する際には、出力したファイルをダブルクリックすればSSMSで開くことができます。
拡張イベントは表示列を追加することで確認したい列で集計やソートが可能であるため、待機イベントの待機時間の合計や、待機イベントのうち上位のイベントを確認することもできます。
f:id:utiowa:20170611153630p:plain
f:id:utiowa:20170611153636p:plain


ただし、待機時間の単位については以下の通り異なりますので要注意です。

単位
イベント 単位 説明
sql_statement_completedイベントのduration列 ステートメントの実行時間 マイクロ秒
query_post_compilation_showplanイベントのduration列 構文解析とコンパイルの実行時間 マイクロ秒
wait_info,wait_completedイベントのduration列 待機事象の経過時間 ミリ秒

拡張イベントwait_infoを使う

SQLServer2012で同じことをする場合は、wait_completedではなくwait_infoを使うことになるかと思います。
基本的な流れは上記同様です。

/***************************************/
-- wait_completed用の拡張イベント
-- (1)調査対象のセッションIDを確認して
-- 以下xxxをセッションIDに置換してから実行
-- 
-- (2)拡張イベントファイルの保存先も
-- 変更してから実行（37行目）
/***************************************/
CREATE EVENT SESSION [exec_query_wait] ON SERVER 
ADD EVENT sqlos.wait_info(
    ACTION(sqlserver.sql_text)
    WHERE ([package0].[equal_uint64]([sqlserver].[session_id],(xxx)) AND [duration]>(0))),
ADD EVENT sqlserver.query_post_compilation_showplan(
    ACTION(sqlserver.sql_text)
    WHERE ([sqlserver].[session_id]=(xxx))),
ADD EVENT sqlserver.query_post_execution_showplan(
    ACTION(sqlserver.sql_text)
    WHERE ([sqlserver].[session_id]=(xxx))),
ADD EVENT sqlserver.sp_statement_completed(
    ACTION(sqlserver.sql_text)
    WHERE ([sqlserver].[session_id]=(xxx))),
ADD EVENT sqlserver.sp_statement_starting(
    ACTION(sqlserver.sql_text)
    WHERE ([sqlserver].[session_id]=(xxx))),
ADD EVENT sqlserver.sql_batch_completed(
    ACTION(sqlserver.sql_text)
    WHERE ([sqlserver].[session_id]=(xxx))),
ADD EVENT sqlserver.sql_batch_starting(
    ACTION(sqlserver.sql_text)
    WHERE ([sqlserver].[session_id]=(xxx))),
ADD EVENT sqlserver.sql_statement_completed(
    ACTION(sqlserver.sql_text)
    WHERE ([sqlserver].[session_id]=(xxx))),
ADD EVENT sqlserver.sql_statement_starting(SET collect_statement=(1)
    ACTION(sqlserver.sql_text)
    WHERE ([sqlserver].[session_id]=(xxx))) 
ADD TARGET package0.event_file(SET filename=N'C:\Program Files\Microsoft SQL Server\MSSQL13.INS_NISHI2016\MSSQL\Log\wait_event.xel')
WITH (MAX_MEMORY=4096 KB,EVENT_RETENTION_MODE=ALLOW_SINGLE_EVENT_LOSS,MAX_DISPATCH_LATENCY=30 SECONDS,MAX_EVENT_SIZE=0 KB,MEMORY_PARTITION_MODE=NONE,TRACK_CAUSALITY=OFF,STARTUP_STATE=OFF)
GO

ALTER EVENT SESSION [exec_query_wait] ON SERVER STATE = START
GO

-- ===============================
-- 別セッション(session_ID = xxx)でクエリ実行
-- ===============================

別セッションで監視するクエリが完了したら拡張イベントのセッションを停止します。

ALTER EVENT SESSION [exec_query_wait] ON SERVER STATE = STOP
GO
DROP EVENT SESSION [exec_query_wait] ON SERVER
GO

集計は以下クエリ。

/*******************************************************/
-- 拡張イベントwait_infoの集計用
/*******************************************************/
-- SQL Server2016なら
/*
DROP TABLE IF EXISTS tempdb..#wait_analyze 
GO
*/

-- SQL Server2014まで
IF OBJECT_ID(N'tempdb..#wait_analyze', N'U') IS NOT NULL
	DROP TABLE #wait_analyze
GO


CREATE TABLE #wait_analyze (event_data XML)
GO

INSERT INTO #wait_analyze (event_data)
SELECT CAST(event_data AS XML) AS wait_events
FROM sys.fn_xe_file_target_read_file(	  N'C:\Program Files\Microsoft SQL Server\MSSQL13.INS_NISHI2016\MSSQL\Log\wait_event*.xel'
														, NULL
														, NULL
														, NULL
														)
GO

SELECT 
	 [waits].[sql_text]
	,[waits].[wait_type]
	,COUNT([waits].[wait_type]) AS wait_count
	,SUM([waits].[duration_ms]) AS total_wait_time_ms
	,SUM([waits].[signal_duration_ms]) AS total_signal_wait_time_ms
	,SUM([waits].[duration_ms]) - SUM([waits].[signal_duration_ms]) AS total_resource_wait_time_ms
FROM (
	SELECT 
		 event_data.value ('(/event/@timestamp)[1]', 'DATETIME') AS [date]
		,event_data.value ('(/event/data[@name = ''wait_type'']/text)[1]', 'VARCHAR(255)') AS [wait_type]
		,event_data.value ('(/event/data[@name = ''duration'']/value)[1]', 'BIGINT') AS [duration_ms]
		,event_data.value ('(/event/data[@name = ''signal_duration'']/value)[1]', 'BIGINT') AS [signal_duration_ms]
		,event_data.value ('(/event/action[@name = ''sql_text'']/value)[1]', 'VARCHAR(MAX)') AS [sql_text]  
	FROM #wait_analyze
	WHERE event_data.value ('(/event/@name)[1]' , 'VARCHAR(255)') = 'wait_info'
	) AS waits
GROUP BY [waits].[sql_text],[waits].[wait_type]
ORDER BY total_wait_time_ms DESC
GO

SELECT 
	 [waits].[sql_text] AS [sql_text]
	,[waits].[name] AS [event_name]
	,SUM([waits].[cpu_time_μs])/1000 AS [total_cpu_time_ms]
	,SUM([waits].[duration_μs])/1000 AS [total_elapsed_time_ms]
FROM (
	SELECT 
		 event_data.value ('(/event/@timestamp)[1]', 'DATETIME') AS [date]
		,event_data.value ('(/event/@name)[1]' , 'VARCHAR(255)') AS [name]
		,event_data.value ('(/event/data[@name = ''cpu_time'']/value)[1]', 'BIGINT') AS [cpu_time_μs]
		,event_data.value ('(/event/data[@name = ''duration'']/value)[1]', 'BIGINT') AS [duration_μs]
		,event_data.value ('(/event/action[@name = ''sql_text'']/value)[1]', 'VARCHAR(MAX)') AS [sql_text]  
		,event_data.value ('(/event/data[@name = ''statement'']/value)[1]', 'VARCHAR(MAX)') AS [statement]
	FROM #wait_analyze
	WHERE 
		event_data.value ('(/event/@name)[1]' , 'VARCHAR(255)') IN (
									'query_post_compilation_showplan'
									,'sql_statement_completed'
									,'sp_statement_completed'
									,'sql_batch_completed'
									,'query_post_execution_showplan'
									)
	) AS waits
GROUP BY [waits].[sql_text], [waits].[name]
GO


SELECT 
	 event_data.value ('(/event/@timestamp)[1]', 'DATETIME') AS [date]
	,event_data.value ('(/event/@name)[1]' , 'VARCHAR(255)') AS [name]
	,event_data.value ('(/event/data[@name = ''cpu_time'']/value)[1]', 'BIGINT') AS [cpu_time_μs]
	,event_data.value ('(/event/data[@name = ''duration'']/value)[1]', 'BIGINT') AS [duration_μs]
	,event_data.value ('(/event/action[@name = ''sql_text'']/value)[1]', 'VARCHAR(MAX)') AS [sql_text]  
	,[temp_xml].[xml_plan].query('.') AS [query_plan]
FROM #wait_analyze AS [wait_analyze]
OUTER APPLY [wait_analyze].event_data.nodes(N'/event/data[@name="showplan_xml"]/value/*') AS  temp_xml(xml_plan)
WHERE 
	event_data.value ('(/event/@name)[1]' , 'VARCHAR(255)') IN (
									 'query_post_compilation_showplan'
									,'query_post_execution_showplan'
								    )
GO

以上、クエリの待機イベントの確認方法でした。
拡張イベントをSSMS上で確認するときはGUI操作による列追加やフィルタ等が毎回必要となりめんどくさいので、一度上記のようなSQLを作っておくと便利でしょう。

【2017/06/18追記】
拡張イベントで取得した実行プランをSQLで参照できるよう各クエリに追加しました。
待機イベントやクエリの実行時間を確認したら、チューニングするために実行プランは確認する必要があるので。