【SQL Server】SSMS17.0「実際の実行プランの分析」機能について

SQL Server Management Studio(SSMS) 17.0で、保存済みの"実際の実行プラン"の分析が可能になったようなので使ってみました。

まだ現状では、「不正確な基数推定」というシナリオしか分析できませんが、あまりSQLServerに精通していない技術者でも、どのように改善すればよいか確認でき便利に感じました。

以下のような予測行数と実際の行数に乖離があるプランを確認してみます。

保存した実際の実行プランをSSMSで開き、右クリックを押下して、"実際の実行のプランの分析"を選択します。

予測行数と実際の行数に差分が存在する場合、どのノードでどの程度の差分が発生しているか確認できます。

また、上画像にある右ペインの「検索結果の詳細」から以下のような解決策を見ることができます。

基数推定のみではありますが、確認すべきポイントが明示的に表示されていて便利ですね。

最新版のSSMSは以下からダウンロードできます。
他にも便利な機能が拡充されてきていますので、使ってみるとよいかと。
SQL Server Management Studio (SSMS) のダウンロード | Microsoft Docs

【SQLServer】【java】jdbcからSQLを実行した場合のSQLステートメントと実行プラン

jdbcからSQLを実行した場合、SQLserver側でどのようなステートメント・実行プランとして現れるのかまとめてみました。

接続プロパティSelectMethodが未指定の場合、もしくはdirectの場合

まずはSelectMethodが未指定の場合で確かめてみます。
デフォルトがdirectであるため、directでも同様の動きとなるかと。

Statementクラスによる実行

import java.sql.Connection;
import java.sql.Driver;
import java.sql.ResultSet;
import java.sql.Statement;
import java.util.Properties;

public class SQLserver_Statement_test {
    public static void main(String[] args) {
        try{
            Driver d = (Driver)Class.forName(
            "com.microsoft.sqlserver.jdbc.SQLServerDriver").newInstance();
            String connUrl = "jdbc:sqlserver://YUUSUKE-VAIO\\INS_NISHI2016;" +
                    "database=Param_testDB;integratedSecurity=false;user=sa;password=system;";
            Connection conn = d.connect(connUrl, new Properties());
            
            Statement stmt = conn.createStatement();
            String SQL = "SELECT * FROM [dbo].[Param_test] " + 
                         "WHERE col2 = 500000 "+
                         "/*test_sql_Statement*/";            
            ResultSet rs = stmt.executeQuery(SQL);
            
            while(rs.next()){
            System.out.println(rs.getString("col1"));
            }
            rs.close();
            stmt.close();
            
        }
        catch(Exception e){
                e.printStackTrace();
                }
    }    
}

java.sql.statementによる実行の場合、SQLserver側では簡易パラメータ化されていなければAdhocクエリとなります。

PreparedStatementクラスによる実行

import java.sql.Connection;
import java.sql.Driver;
import java.sql.ResultSet;
import java.sql.PreparedStatement;
import java.util.Properties;

public class SQLserver_Prepared_Statement_test {
    public static void main(String[] args) {
        try{
            Driver d = (Driver)Class.forName(
            "com.microsoft.sqlserver.jdbc.SQLServerDriver").newInstance();
            String connUrl = "jdbc:sqlserver://YUUSUKE-VAIO\\INS_NISHI2016;" +
                             "database=Param_testDB;integratedSecurity=false;user=sa;password=system;";
            Connection conn = d.connect(connUrl, new Properties());
            
            String SQL = "SELECT * FROM [dbo].[Param_test] " + 
                         "WHERE col2 = ?"+
                         "/*test_sql_Prepared_Statement*/";
            PreparedStatement pstmt = conn.prepareStatement(SQL);
            pstmt.setInt(1, 500002);
            ResultSet rs = pstmt.executeQuery();
            
            while(rs.next()){
            System.out.println(rs.getString("col2"));
            }
            rs.close();
            pstmt.close();
            
        }
        catch(Exception e){
                e.printStackTrace();
                }
    }    
}

java.sql.Preparedstatementによる実行の場合、SQLserver側ではpreparedクエリとなります。
実行プランを作成する際には、バインド変数により実行プランを作成します。パラメータスニッフィングが有効であれば、プラン作成時のパラメータで最適化される実行プランが次回以降再利用されることになりますので、実行プラン作成時のパラメータには注意が必要です。
（例えば検索画面などで曖昧検索や未入力による全件検索が発生しうる場合など）

これは以前もまとめておりますので、詳細は以下を参照ください。
【SQL server】パラメータスニッフィングによる実行プランのパフォーマンス低下 - 小物SEのメモ帳

実際にSQLserver側でステートメントを確認してみると、バインド変数のままステートメントが実行されていることがわかるかと思います。
ただし接続プロパティSendStringParametersAsUnicodeを指定していない場合、デフォルトでは文字列パラメータはNVARCHARとして実行されるため、VARCHARが存在する場合暗黙型変換が発生します。
この場合、同プロパティをfalseとして、NVARCHAR型のカラムにはNプレフィックスを付与するなどする必要があります。
Microsoftのblogにも記載があり、ありがちなミスであるため、データ型が正しいか確認しておくべきでしょう。
DO’s&DONT’s #2: 絶対にやらなければいけないこと – データ型を一致させる – Microsoft SQL Server Japan Support Team Blog

接続プロパティSelectMethodがcursorの場合

次にSelectMethodがcursorの場合で確かめてみます。

このときSQLserver側ではサーバサイドのカーソルが要求されることになります。
カーソル処理は、パフォーマンスがよくないことがありますので、使う際はよく検討しましょう。
まとめてデータを取得可能であればカーソルを使用しない方が処理効率はよいかと。

Statementクラスによる実行

import java.sql.Connection;
import java.sql.Driver;
import java.sql.ResultSet;
import java.sql.Statement;
import java.util.Properties;

public class SQLserver_Statement_cursor_test {
   public static void main(String[] args) {
        try{
            Driver d = (Driver)Class.forName(
            "com.microsoft.sqlserver.jdbc.SQLServerDriver").newInstance();
            String connUrl = "jdbc:sqlserver://YUUSUKE-VAIO\\INS_NISHI2016;" +
                    "database=Param_testDB;integratedSecurity=false;user=sa;password=system;SelectMethod=cursor";
            Connection conn = d.connect(connUrl, new Properties());
            
            Statement stmt = conn.createStatement();
            String SQL = "SELECT * FROM [dbo].[Param_test] " + 
                         "WHERE col2 = 500001 "+
                         "/*test_sql_Statement_cursor*/";            
            ResultSet rs = stmt.executeQuery(SQL);
            
            while(rs.next()){
            System.out.println(rs.getString("col1"));
            }
            rs.close();
            stmt.close();
            
        }
        catch(Exception e){
                e.printStackTrace();
                }
    }    
}

基本的には接続プロパティSelectMethodが未指定の場合と同様ですが、次レコードを参照するためのカーソル処理”FETCH API_CURSOR…”がステートメントに、実行プランに”FETCH CURSOR”が追加されています。

なぜかこの場合プランがうまく表示できませんでした…
XML表示で確認すると内部まで確認できます。

PreparedStatementクラスによる実行

import java.sql.Connection;
import java.sql.Driver;
import java.sql.ResultSet;
import java.sql.PreparedStatement;
import java.util.Properties;

public class SQLserver_Prepared_Statement_cursor_test {
    public static void main(String[] args) {    
       try{
            Driver d = (Driver)Class.forName(
            "com.microsoft.sqlserver.jdbc.SQLServerDriver").newInstance();
            String connUrl = "jdbc:sqlserver://YUUSUKE-VAIO\\INS_NISHI2016;" +
                             "database=Param_testDB;integratedSecurity=false;user=sa;password=system;SelectMethod=cursor";
            Connection conn = d.connect(connUrl, new Properties());
            
            String SQL = "SELECT * FROM [dbo].[Param_test] " + 
                         "WHERE col2 = ? " +
                         "/*test_sql_Prepared_Statement_cursor*/";
            PreparedStatement pstmt = conn.prepareStatement(SQL);
            pstmt.setInt(1, 500003);
            ResultSet rs = pstmt.executeQuery();
            
            while(rs.next()){
            System.out.println(rs.getString("col2"));
            }
            rs.close();
            pstmt.close();
            
        }
        catch(Exception e){
                e.printStackTrace();
                }
    }    
}

こちらも基本的には接続プロパティSelectMethodが未指定の場合と同様で、次レコードを参照しFETCHしていく処理が追加されています。

ただし次のようなカーソルの処理対象データが外部結合等で大きくなる場合、中間データがtempdbのCWT_PrimaryKeyに保存されることがあるため、多数のカーソル処理が集中するとtempdbへのIOが集中しボトルネックとなることがあります。

import java.sql.Connection;
import java.sql.Driver;
import java.sql.PreparedStatement;
import java.sql.ResultSet;
import java.util.Properties;

public class SQLserver_Prepared_Statement_cursors_test {
    public static void main(String[] args) {    
       try{
            Driver d = (Driver)Class.forName(
            "com.microsoft.sqlserver.jdbc.SQLServerDriver").newInstance();
            String connUrl = "jdbc:sqlserver://YUUSUKE-VAIO\\INS_NISHI2016;" +
                             "database=Param_testDB;integratedSecurity=false;user=sa;password=system;SelectMethod=cursor";
            Connection conn = d.connect(connUrl, new Properties());
            
            String SQL = "SELECT [param].[col1] FROM [dbo].[Param_test] AS [param] " + 
                         "LEFT OUTER JOIN  [Param_testDB].[dbo].[Parallel_test] AS [parallel] " +
                         "        ON  [param].[col2] = [parallel].[col2] " +
                         "WHERE [param].[col2] BETWEEN ? " +
                         "                         AND ? " + 
                         "ORDER BY 1 " +
                         "/*test_sql_Prepared_Statement_cursor*/";
            PreparedStatement pstmt = conn.prepareStatement(SQL);
            pstmt.setInt(1, 500000);
            pstmt.setInt(2, 500003);
            
            ResultSet rs = pstmt.executeQuery();
            
            while(rs.next()){
            System.out.println(rs.getString("col1"));
            }
            rs.close();
            pstmt.close();
            
        }
        catch(Exception e){
                e.printStackTrace();
                }
    }    
}

このあたりは静的カーソルについて前回まとめておりますので、そちらをご確認いただければ。
【SQL Server】tempdbのCWT_PrimaryKeyとは - 小物SEのメモ帳

java.sql.CallableStatementによるストアドの実行

java.sql.CallableStatementによる実行は、IN/OUTパラメータを伴うストアドプロシージャの呼び出しに使います。

USE [Param_testDB]
GO
DROP PROCEDURE IF EXISTS [dbo].[usp_stored_procedure_test]
GO

CREATE PROCEDURE [dbo].[usp_stored_procedure_test]
	@input_param INT,
	@output_param INT OUT
AS
BEGIN
	SET NOCOUNT ON;
	SELECT @output_param = col2 
	FROM [dbo].[Param_test] 
    WHERE col2 = @input_param
RETURN
END  
GO

import java.sql.Connection;
import java.sql.Driver;
import java.sql.CallableStatement;
import java.sql.Types;
import java.util.Properties;

public class SQLserver_Callable_Statement_test {
   public static void main(String[] args) {
        try{
            Driver d = (Driver)Class.forName(
            "com.microsoft.sqlserver.jdbc.SQLServerDriver").newInstance();
            String connUrl = "jdbc:sqlserver://YUUSUKE-VAIO\\INS_NISHI2016;" +
                    "database=Param_testDB;integratedSecurity=false;user=sa;password=system";
            Connection conn = d.connect(connUrl, new Properties());
            
            String SQL = "{call dbo.usp_stored_procedure_test(?,?)}";
            
            CallableStatement cstmt = conn.prepareCall(SQL);
            cstmt.setInt(1,500004);
            cstmt.registerOutParameter(2, Types.INTEGER);
            cstmt.execute();
            
            System.out.println(cstmt.getInt(2));
            cstmt.close();
            
        }
        catch(Exception e){
                e.printStackTrace();
                }
    }    
}

SQLserver側からすると保存されているストアドプロシージャが呼び出されて実行されています。
SQLテキストとしては"CREATE PROCEDURE…"から始まっていることも特徴となるかと。

ストアドプロシージャとなるため、実行プランとしてはPreparedStatementと同様に実行プラン作成時のバインド変数には注意が必要です。
ちなみにストアドプロシージャのjavaからの実行時のそのほかのパターンは以下の通りです。

パターン	実行方法
IN/OUTパラメータが必要ないストアドプロシージャ	java.sql.statement
INパラメータが必要なストアドプロシージャ	java.sql.Preparedstatement
OUTパラメータが必要なストアドプロシージャ	java.sql.CallableStatement

詳しくはMicrosoftのドキュメントをみていただければと思います。
https://docs.microsoft.com/en-us/sql/connect/jdbc/using-statements-with-stored-procedures

また、今回使ったSQLステートメントと実行プランの確認に使ったクエリも以下に残しておきます。
例によって使いまわしですが。

USE master
GO

SET NOCOUNT ON
GO

/*********************************************/
-- sort
-- 0 : Total CPU Usage TOP100
-- 1 : Average CPU Usage TOP100
-- 2 : Total Elapsed Time TOP100
-- 3 : Average Elapsed Time TOP100
-- 4 : Total IO Page TOP100
-- 5 : Average IO Page TOP100
/*********************************************/
DECLARE @sort INT

SET @sort = 0

SELECT TOP 100 CASE 
		WHEN @sort = 0
			THEN rank() OVER (
					ORDER BY total_worker_time DESC
						,sql_handle
						,statement_start_offset
					)
		WHEN @sort = 1
			THEN rank() OVER (
					ORDER BY (total_worker_time + 0.0) / (execution_count * 1000) DESC
						,sql_handle
						,statement_start_offset
					)
		WHEN @sort = 2
			THEN rank() OVER (
					ORDER BY total_elapsed_time DESC
						,sql_handle
						,statement_start_offset
					)
		WHEN @sort = 3
			THEN rank() OVER (
					ORDER BY (total_elapsed_time + 0.0) / (execution_count * 1000) DESC
						,sql_handle
						,statement_start_offset
					)
		WHEN @sort = 4
			THEN rank() OVER (
					ORDER BY (total_logical_reads + total_logical_writes) DESC
						,sql_handle
						,statement_start_offset
					)
		WHEN @sort = 5
			THEN rank() OVER (
					ORDER BY (total_logical_reads + total_logical_writes) / (execution_count + 0.0) DESC
						,sql_handle
						,statement_start_offset
					)
		END AS [row_no]
	,db_name(st.dbid) AS [database_name]
	,creation_time
	,last_execution_time
	,(total_worker_time + 0.0) / 1000 AS [total_worker_time(ms)]
	,(total_worker_time + 0.0) / (execution_count * 1000) AS [AvgCPUTime(ms)]
	,(total_elapsed_time + 0.0) / 1000 AS [total_elapsed_time(ms)]
	,(total_elapsed_time + 0.0) / (execution_count * 1000) AS [AvgElapsedTime(ms)]
	,total_logical_reads AS [LogicalReads(page)]
	,total_logical_writes AS [logicalWrites(page)]
	,total_logical_reads + total_logical_writes AS [AggIO(page)]
	,(total_logical_reads + total_logical_writes) / (execution_count + 0.0) AS [AvgIO(page)]
	,execution_count
	,total_rows
	,st.TEXT AS [batch_query_text]
	,CASE 
		WHEN sql_handle IS NULL
			THEN ' '
		ELSE (
				SUBSTRING(st.TEXT, (qs.statement_start_offset + 2) / 2, (
						CASE 
							WHEN qs.statement_end_offset = - 1
								THEN LEN(CONVERT(NVARCHAR(MAX), st.TEXT)) * 2
							ELSE qs.statement_end_offset
							END - qs.statement_start_offset
						) / 2)
				)
		END AS [statement_query_text]
	,plan_generation_num
	,[cp].objtype
	,qp.query_plan
FROM sys.dm_exec_query_stats AS [qs]
CROSS APPLY sys.dm_exec_sql_text(sql_handle) AS [st]
CROSS APPLY sys.dm_exec_query_plan(plan_handle) AS [qp]
INNER JOIN  sys.dm_exec_cached_plans AS [cp]
			ON [cp].[plan_handle] = [qs].[plan_handle]
WHERE total_worker_time > 0
ORDER BY CASE 
		WHEN @sort = 0
			THEN total_worker_time
		WHEN @sort = 1
			THEN (total_worker_time + 0.0) / (execution_count * 1000)
		WHEN @sort = 2
			THEN total_elapsed_time
		WHEN @sort = 3
			THEN (total_elapsed_time + 0.0) / (execution_count * 1000)
		WHEN @sort = 4
			THEN (total_logical_reads + total_logical_writes)
		WHEN @sort = 5
			THEN (total_logical_reads + total_logical_writes) / (execution_count + 0.0)
		END DESC
OPTION (RECOMPILE)

【SQL Server】tempdbのCWT_PrimaryKeyとは

実行プランでCWT_PrimaryKeyというテーブルを参照していることがありますが、どのようなものか気になり調べてみました。

これは静的カーソルの結果セットを保存するtempdbのワークテーブルのようです。

静的カーソルは、カーソルを開いた時点の結果をtempdbへ一旦退避し、後続処理ではそれをFETCHして参照することで、カーソル処理中の処理対象への変更有無に関わらず、開いた時点の情報で処理をすることができます。

このときの静的カーソルの結果セットの格納先がtempdbのCWT_PrimaryKeyとなります。

テスト用データ作成

テスト用にテーブルとレコードを作成します。

CREATE DATABASE Cursor_testDB
GO
USE Cursor_testDB
GO

DROP TABLE IF EXISTS dbo.Cursor_test
GO

CREATE TABLE dbo.Cursor_test(
   [id] INT
  ,[column1] VARCHAR(50)
  ,[column2] VARCHAR(50)
  ,CONSTRAINT [PK_column] PRIMARY KEY CLUSTERED ([id])
  )
GO

DECLARE  @Id INT
        ,@Col1 VARCHAR(50)
        ,@Col2 VARCHAR(50)
SET  @id = 1

WHILE (@id < 10000)
  BEGIN
    SET  @Col1 = 'Column' + CONVERT(VARCHAR, @id)
    SET  @Col2 = 'Column' + CONVERT(VARCHAR, 100000-@id)
    INSERT INTO dbo.Cursor_test(id, column1, column2) VALUES (@id, @Col1, @Col2)
    SET @id = @id + 1
  END
GO

作成したテストデータは次のようなものです。

静的カーソルの確認

静的カーソルでクエリを実行してみます。

DECLARE  @Id INT
        ,@Col1 VARCHAR(50)
        ,@Col2 VARCHAR(50)

DECLARE Static_Cursor CURSOR LOCAL FORWARD_ONLY STATIC READ_ONLY 
  FOR SELECT id,column1,column2
      FROM dbo.Cursor_test
      WHERE id > 9990
      ORDER BY id DESC

OPEN Static_Cursor

FETCH NEXT FROM Static_Cursor INTO @Id,@Col1,@Col2
  WHILE @@FETCH_STATUS = 0
    BEGIN
      PRINT @id
      PRINT @Col1
      PRINT @Col2
      FETCH NEXT FROM Static_Cursor INTO @Id,@Col1,@Col2
    END
  CLOSE Static_Cursor
DEALLOCATE Static_Cursor
GO

実行プランに表示されている内容からtempdbのCWT_PrimaryKeyというワークテーブルに対して読み取り結果を格納し、その後のFETCH処理はtempdbのCWT_PrimaryKeyからクラスター化インデックスを用いて順次取得していることがわかるかと思います。

複数のクエリで静的カーソルを多用すると一度処理対象となる結果セットはtempdbへ格納され、そこから読出しされるため、tempdbへのIO処理が集中しボトルネックとなることがあります。
また、静的カーソルの対象が多い場合はtempdbへ格納する容量もその分増えることになりますのでどちらも注意が必要かと思います。

【参考情報】
静的カーソル
https://technet.microsoft.com/ja-jp/library/ms191286(v=sql.105).aspx

サーバーカーソル動作とクエリパフォーマンスとの関連性について
https://blogs.msdn.microsoft.com/jpsql/2014/04/29/36899/

DECLARE CURSOR (Transact-SQL)

【SQL Server】T-SQLのtry catch について

ストアドプロシージャを書く際にエラー処理を書くかと思いますが、例外をスローするためのサンプルを掲載します。

Googleで検索するとやたらRAISERRORを使ったサンプルが検索にヒットしますが、SQLserver2012以降を使っている場合なら単純にTHROWすればよいかと。

サンプルとしてEMPLOYEESテーブルを更新するストアドを作成します。

/*********************************************/
-- try catchのサンプル
/*********************************************/
  USE sales
  GO

  DROP PROCEDURE IF EXISTS dbo.usp_throw_test;
  GO

  CREATE PROCEDURE dbo.usp_throw_test
    @Employee_id INT,
    @Salary INT
  AS
  BEGIN
  SET NOCOUNT ON;
    BEGIN TRY
      BEGIN TRAN;
        SELECT *
        FROM [dbo].[EMPLOYEES] WITH (UPDLOCK)
        WHERE  EMPLOYEE_ID = @Employee_id

        UPDATE [dbo].[EMPLOYEES]
        SET SALARY = @Salary
        WHERE  EMPLOYEE_ID = @Employee_id

      COMMIT TRAN;
    END TRY
    BEGIN CATCH
      IF @@TRANCOUNT > 0
      ROLLBACK TRAN;
      THROW;
    END CATCH
  END
  GO

テーブルにはCHECK制約としてsalary>0という条件を制約とします。

	ALTER TABLE [dbo].[EMPLOYEES]  WITH NOCHECK 
	ADD  CONSTRAINT [EMP_SALARY_MIN] CHECK  (([salary]>(0)))
	GO

	ALTER TABLE [dbo].[EMPLOYEES] CHECK CONSTRAINT [EMP_SALARY_MIN]
	GO

エラーを発生させると例外がスローされます。

EXEC dbo.usp_throw_test
  @Employee_id = 103,
  @Salary =  -15000

【SQL Server2016】dm_exec_input_bufferについて

SQL server2016以降で使用できるdm_exec_input_bufferについて。

これまではDBCC INPUTBUFFERコマンドを使用して各セッションで実行された最後のSQL文の確認等を行っていたかと思いますが、DBCCコマンドゆえに他の動的管理ビューとのJOINができず、複数セッションを確認する際には面倒でした。

SQL server2016からdm_exec_input_bufferが追加されたことにより、他の動的管理ビューとあわせて確認することが可能になり便利になりました。

SELECT * 
FROM		sys.dm_exec_sessions AS [sessions]
CROSS APPLY	sys.dm_exec_input_buffer([sessions].[session_id], NULL) AS [inp_buf]
WHERE [sessions].[session_id] > 50

また、DBCC INPUTBUFFER同様に個別のセッションに対しても実行できます。

現在実行中のクエリのパフォーマンス状況を調べる場合にも、どのSQLが遅いのか知りたいことがあるのでその際にも活用できるかと。
このくらいなら事前に準備がなくともサクッと書いて実行できるので便利ですね。

SELECT 
	*
FROM		sys.dm_exec_requests AS [req]
INNER JOIN	sys.dm_exec_sessions AS [sessions]
	ON	[sessions].[session_id] = [req].[session_id]
CROSS APPLY	sys.dm_exec_input_buffer([sessions].[session_id], NULL) AS [inp_buf]
WHERE [sessions].[session_id] > 50

また、以下のように準備しておけば、アクティブなユーザセッションが実行（実行中のクエリ含む）したクエリを調べる際にも使えますね。

SELECT        		[sessions].[session_id]
                ,	[sessions].[status]
                ,	[sessions].[cpu_time] AS [cpu_time(ms)]
                ,	[sessions].[memory_usage]*8 AS [memory_usage(kb)]
                ,	[sessions].[total_scheduled_time] AS [total_scheduled_time(ms)]
                ,	[sessions].[total_elapsed_time] As [total_elapsed_time(ms)]
		,	[sessions].[logical_reads]*8 AS [logical_reads_in_session(kb)]
		,	[req].[logical_reads]*8 AS [logical_reads_in_request(kb)]
		,	[req].[granted_query_memory]*8 AS [granted_query_memory_in_request(kb)]
                ,	[sessions].[login_time]
                ,	[sessions].[last_request_end_time]
                ,	[req].[start_time]
                ,	[req].[command]
                ,	[sessions].[host_name]
                ,	[sessions].[login_name]
                ,	[sessions].[nt_domain]
                ,	[sessions].[nt_user_name]
                ,	[sessions].[program_name]
		,	[sessions].[client_interface_name]
		,	[con].[client_net_address]
                ,	[con].[client_tcp_port]
                ,	[req].[percent_complete]
                ,	[req].[estimated_completion_time]
		,	[inp_buf].[event_type]
		,	[inp_buf].[event_info]
		,	[exec_text].[text] AS [most_recent_sql]
                ,	CASE 
				WHEN [req].sql_handle IS NOT NULL THEN (
					SELECT TOP 1 
						SUBSTRING(t2.text, ([req].[statement_start_offset] + 2) / 2, 
							( 
							(CASE 
								WHEN	[req].[statement_end_offset] = -1 THEN ((LEN(CONVERT(NVARCHAR(MAX),[t2].[text]))) * 2) 
								ELSE		[req].[statement_end_offset]
							END) - [req].[statement_start_offset]
							) / 2
						) 
					FROM sys.dm_exec_sql_text([req].[sql_handle]) AS [t2] 
					)
				ELSE ''
			END  AS [running_sql_text] 
		,	[sql_plan].[query_plan] AS [sql_plan]
FROM sys.dm_exec_sessions AS [sessions]
LEFT OUTER JOIN sys.dm_exec_connections AS [con]  
	　　 ON ( [sessions].[session_id] = [con].[session_id] )
LEFT OUTER JOIN sys.dm_exec_requests [req]  
	     ON ( 	 [req].[session_id] = [con].[session_id] 
		AND	 [req].[connection_id] = [con].[connection_id] )
CROSS APPLY	sys.dm_exec_input_buffer([sessions].[session_id], NULL) AS [inp_buf]
OUTER APPLY	sys.dm_exec_sql_text([con].[most_recent_sql_handle]) AS [exec_text]
OUTER APPLY	sys.dm_exec_query_plan([req].plan_handle) AS [sql_plan]
WHERE	[sessions].[is_user_process] = 1
ORDER BY [sessions].[session_id]

【SQL server】インデックス間のデッドロック

一つのテーブルにクラスタ化インデックスと非クラスタ化インデックスが貼られている場合に、同一テーブル内のインデックス間で発生するデッドロックについて検証してみました。

テストデータとテーブルを準備

以下のようなテーブルにテストデータを用意します。

CREATE TABLE [test].[Deadlock](
	[col1] [int] NOT NULL,
	[col2] [int] NOT NULL,
	[col3] [int] NOT NULL,
	[col4] [int] NOT NULL,
	[col5] [int] NOT NULL
) ON [PRIMARY]

適当なテストデータを投入しておきます。

デッドロックさせるインデックスとして以下インデックスを準備します。

CREATE CLUSTERED INDEX [Cix_col1] ON [test].[Deadlock]
(
	[col1] ASC
)
GO


CREATE NONCLUSTERED INDEX [NixIn_col2] ON [test].[Deadlock]
(
	[col2] ASC
)
INCLUDE ( [col4])
GO

デッドロック用のクエリを実行

UPDATE側のクエリでは、クラスタ化インデックスを使って更新するクエリを実行します。
その際、更新対象の項目は付加列インデックスで使用している列を更新します。

/*************************************/
-- UPDATE側
/*************************************/
USE sales
GO

DECLARE @counter INT = 0
DECLARE @j INT 

WHILE @counter < 1000000
BEGIN
	BEGIN TRAN;
		SET @j = CONVERT(INT, RAND() * 100)
		UPDATE [test].[Deadlock]
		SET [col4] = @j
		WHERE [col1] = 1
	COMMIT TRAN;
	SET @counter += 1
END

このUPDATE側のクエリでは次の実行プランからもわかる通り、クラスタ化インデックスを排他ロックにて参照し、付加列インデックスを更新します。

SELECT側のクエリでは、非クラスタ化インデックスを使用してkey lookupでクラスタ化インデックスへの参照が発生するようなクエリを実行します。

/*************************************/
-- SELECT側
/*************************************/
USE sales
GO

DECLARE @counter INT = 0
DECLARE @dummy INT

WHILE @counter < 1000000
BEGIN
	SELECT
		@dummy = [col3]
	FROM [test].[Deadlock]
	WHERE [col2] = 1
	SET @counter += 1		
END

こちらのSELECT側のクエリでは、WHERE句の条件に合致する行を非クラスタ化インデックスを使用して共有ロックにて行を特定し、key lookupを使用してクラスタ化インデックスから列の参照していることがわかるかと思います。

#key lookupを使ってしまうパターンなどインデックスの仕組みについては以下をご参照ください。
memorandom-nishi.hatenablog.jp

デッドロック発生時のロック状況を確認してみると、UPDATE側は排他ロック、SELECT側は共有ロックを取る際にデッドロックが発生していることがわかります。

USE sales
GO

SELECT 
		[locks].[request_session_id]									AS	[spid],
		ISNULL(DB_NAME([resource_database_id]), '')							AS	[db_name],
		CASE	
			WHEN	[resource_type] = 'OBJECT'			THEN	OBJECT_NAME([resource_associated_entity_id], [resource_database_id])
			WHEN	[resource_associated_entity_id] =	0	THEN	''
			ELSE	OBJECT_NAME([p].[object_id])
		END												AS [entity_name],
		[ind].[index_id]										AS [index_id],
		[ind].[name]											AS [index_name],
		ISNULL([locks].[resource_type], '')								AS [resource_type],
		[locks].resource_description									AS [resource_description],
		[locks].request_type										AS [request_type],
		[locks].request_mode										AS [request_mode],
		[requests].[command]										AS [command],
		[locks].[request_status]									AS [request_status],
		ISNULL([wait].[wait_duration_ms], 0)								AS [wait_duration_ms],
		ISNULL([wait].[wait_type], N'')									AS [wait_type],
		ISNULL(CONVERT (varchar,[wait].[blocking_session_id]), '')					AS [blocking_session_id],
		ISNULL([wait].[resource_description], N'')							AS [resource_description],
		ISNULL(REPLACE(REPLACE([query_text].[text],CHAR(13), ''), CHAR(10), ' '), N'')			AS [query_text],
		[plan].[query_plan]										AS [query_plan]
FROM			[sys].[dm_tran_locks]									AS [locks] WITH (NOLOCK)
	LEFT JOIN	[sys].[partitions]									AS [p] WITH (NOLOCK)
		ON	[p].[partition_id]		= [locks].[resource_associated_entity_id]
	LEFT JOIN	[sys].[dm_os_waiting_tasks]								AS [wait] WITH (NOLOCK)
		ON	[locks].[lock_owner_address]	= [wait].[resource_address]
		AND	[locks].[request_session_id]	= [wait].[session_id]
	LEFT JOIN	[sys].[indexes]										AS [ind] WITH (NOLOCK)
		ON	[p].[object_id]			= [ind].[object_id]
		AND	[p].[index_id]			= [ind].[index_id]
	LEFT JOIN	[sys].[dm_exec_requests]								AS [requests] WITH (NOLOCK)
		ON	[locks].[request_session_id]	= [requests].[session_id]
		AND	[wait].[session_id]		= [requests].[session_id]
    OUTER APPLY	[sys].[dm_exec_sql_text]([requests].[sql_handle])						AS [query_text] 
	OUTER APPLY [sys].[dm_exec_query_plan]([requests].[plan_handle]) 					AS [plan] 
WHERE	resource_database_id = DB_ID()
AND	resource_type <> 'DATABASE'
ORDER BY spid
OPTION (RECOMPILE)

実際にインデックス間でデッドロックが発生した場合のデッドロックグラフを確認してみると、お互いのインデックスのロック解放待ち状態となっていることが確認できるかと思います。

#デッドロックグラフはデフォルトで取得されている拡張イベント「system_health」から確認できます。

＜UPDATE側＞
UPDATE側クエリがクラスタ化インデックスの排他ロックを獲得
UPDATE側クエリが非クラスタ化インデックスの排他ロック獲得待ち

＜SELECT側＞
SELECT側クエリが非クラスタ化インデックスの共有ロックを獲得
SELECT側クエリがクラスタ化インデックスの共有ロック獲得待ち

また、今回はキーロックのデッドロック時の情報としてwaitresourceの値からどのデータでデッドロックが発生してしまったか確認することができます。

拡張イベントのsystem_healthのSSMSにて開き、カラムの上で右クリック、「列の選択」を選択します。

「選択した列」に「xml_report」を追加します。

xml_reportを列として追加できたら、name列が「xml_deadlock_report」であるレコードのxml_report列をダブルクリックします。

デッドロック情報がxml形式で確認できるため、xmlの「waitresource」のカッコ()の値を確認します。

カッコ()の値を使って、以下クエリで検索します。

/**************************************/
--デッドロックしたレコードの確認
/**************************************/
USE sales
GO

SELECT * 
FROM  [test].[Deadlock]
WHERE %%lockres%% = '(de42f79bc795)'

検索結果から、デッドロック時のキーが確認できます。

同一テーブル内のインデックス間デッドロックの解決策

このようなインデックス間のデッドロックが発生する場合の解決策としては以下が考えられるかと。
（１）別のインデックス使用して、非クラスタ化インデックス使用時にkey lookupが発生しないようにする
（２）トランザクション分離レベルをREAD COMMITED SNAPSHOTにする

ただし（２）は、参照時に直接共有ロックをかけないものの、その分tempdbにおける負荷が高くなることはデメリットとなることは考慮すべきかと思います。

ロックやトランザクション分離レベルについてはこちらを参照いただければ。
memorandom-nishi.hatenablog.jp
memorandom-nishi.hatenablog.jp

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

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

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

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

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

拡張イベントwait_comletedを使う

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

事前準備

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

SELECT @@SPID

もしくはSSMS上のタブからも確認可能です。

拡張イベントを作成する

事前準備で確認した監視したいセッション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

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

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

単位

イベント	単位	説明
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で参照できるよう各クエリに追加しました。
待機イベントやクエリの実行時間を確認したら、チューニングするために実行プランは確認する必要があるので。