【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/
【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)'
検索結果から、デッドロック時のキーが確認できます。
同一テーブル内のインデックス間デッドロックの解決策
このようなインデックス間のデッドロックが発生する場合の解決策としては以下が考えられるかと。
(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
お手軽に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で開くことができます。
拡張イベントは表示列を追加することで確認したい列で集計やソートが可能であるため、待機イベントの待機時間の合計や、待機イベントのうち上位のイベントを確認することもできます。
ただし、待機時間の単位については以下の通り異なりますので要注意です。
拡張イベント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で参照できるよう各クエリに追加しました。
待機イベントやクエリの実行時間を確認したら、チューニングするために実行プランは確認する必要があるので。