小物SEのメモ帳

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

【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クエリとなります。
f:id:utiowa:20170726023442p:plain
f:id:utiowa:20170726023503p:plain

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のメモ帳

f:id:utiowa:20170726023548p:plain
f:id:utiowa:20170726023606p:plain

実際に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”が追加されています。
f:id:utiowa:20170726023752p:plain
f:id:utiowa:20170726023838p:plain
f:id:utiowa:20170726023910p:plain

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

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していく処理が追加されています。
f:id:utiowa:20170726024112p:plain
f:id:utiowa:20170726024122p:plain
f:id:utiowa:20170726024140p:plain


ただし次のようなカーソルの処理対象データが外部結合等で大きくなる場合、中間データが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();
                }
    }    
}

f:id:utiowa:20170726024220p:plain
f:id:utiowa:20170726024259p:plain


このあたりは静的カーソルについて前回まとめておりますので、そちらをご確認いただければ。
【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();
                }
    }    
}

f:id:utiowa:20170726024514p:plain
f:id:utiowa:20170726024525p:plain

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

作成したテストデータは次のようなものです。
f:id:utiowa:20170721025251p:plain

静的カーソルの確認

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

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

f:id:utiowa:20170721025344p:plain

実行プランに表示されている内容から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

f:id:utiowa:20170717000242p:plain

【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

f:id:utiowa:20170709224810p:plain

また、DBCC INPUTBUFFER同様に個別のセッションに対しても実行できます。
f:id:utiowa:20170709224722p:plain
f:id:utiowa:20170709224711p:plain

現在実行中のクエリのパフォーマンス状況を調べる場合にも、どの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]

適当なテストデータを投入しておきます。
f:id:utiowa:20170702152418p:plain

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

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

f:id:utiowa:20170702152834p:plain

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



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

f:id:utiowa:20170702153143p:plain

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

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


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

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)


実際にインデックス間でデッドロックが発生した場合のデッドロックグラフを確認してみると、お互いのインデックスのロック解放待ち状態となっていることが確認できるかと思います。
f:id:utiowa:20170702153909p:plain
#デッドロックグラフはデフォルトで取得されている拡張イベント「system_health」から確認できます。

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

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


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

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

「選択した列」に「xml_report」を追加します。
f:id:utiowa:20170702154307p:plain

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

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

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

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

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

f:id:utiowa:20170702154812p:plain

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

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

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

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

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

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

【SQL Server】処理の進捗がわかるライブクエリ統計

SQLServer2014以降で使用することができるライブクエリ統計の機能がクエリのパフォーマンスチューニングに役立ちそうだったため使い方を記します。
ライブクエリ統計を使うことで実行に長時間かかるクエリが、どの処理で時間を要しているのかわかるため、改善すべき処理が把握でき便利かと思います。
(多少なりとも負荷がかかる設定のため、商用環境以外での使用となるかと思いますが)

事前準備

使用するためには事前に以下の設定が必要です。

セッションのみの監視をする場合

これから監視するクエリのセッションで事前にSET STATISTICS XML ON;もしくはSET STATISTICS PROFILE ON;を実行

インスタンス全体のクエリを監視する場合

拡張イベントでquery_post_execution_showplanを有効にする


SQLServer 2016 SP1以降の場合、軽量版統計インフラストラクチャを有効にすることでも確認可能となります。

トレースフラグ7412を使用
DBCC TRACEON(7412, -1)
インスタンス全体のクエリを監視する場合

拡張イベントでquery_thread_profileを有効にする

実際に試してみる

ためしに時間のかかる適当なクエリを実行してライブクエリ統計を確認してみます。

WITH CTE AS (
SELECT 
		EMP.EMPLOYEE_ID,
		EMP.FIRST_NAME,
		EMP.LAST_NAME,
		EMP.SALARY,
		JOBS.MIN_SALARY,
		JOBS.MAX_SALARY,
		HIST.EMPLOYEE_ID AS [HIST_EMP_ID]
	FROM	dbo.EMPLOYEES AS [EMP]
	INNER JOIN dbo.JOBS AS [JOBS]
	ON EMP.JOB_ID = JOBS.JOB_ID
	LEFT OUTER JOIN  JOB_HISTORY AS [HIST]
	ON EMP.EMPLOYEE_ID = HIST.EMPLOYEE_ID
)
SELECT 
	*
FROM	 CTE AS [CTE_A]
	,CTE AS [CTE_B]
;
利用状況モニターを使用してインスタンス全体のクエリから対象のクエリを確認する場合

利用状況モニターを開いて、「アクティブなコストの高いクエリ」を押下して、確認するクエリを選択し右クリック、「ライブ実行プランの表示」を選択します。
f:id:utiowa:20170604201923p:plain

セッションから対象のクエリのみを確認する場合

SSMSの上部メニューから「ライブクエリ統計を含む」アイコンをクリックします。
f:id:utiowa:20170604201936p:plain


確認結果は以下のようになります。
f:id:utiowa:20170604202018p:plain

処理中である箇所や、各処理に要した時間や処理行数がリアルタイムで確認することが可能になりますので、処理の完了を待たずにボトルネックが把握できるため長時間が予想されるクエリのチューニング時に活用してみては。



参考情報:
ライブ クエリ統計