SQL Server 2016 / SQL Database v12 で使用できるクエリストアの機能では、正常終了したクエリだけでなく、異常終了したクエリについても情報が取得されています。
異常終了したクエリから、クエリタイムアウト (コマンドタイムアウト) したクエリの情報の取得について考えてみたいと思います。
クエリストアの情報については、かなり日本語化されたものが出てきていますので、クエリ ストアがデータを収集するしくみ を一読しておくとよいかと。
クエリストアにより取得された、実行統計の情報は sys.query_store_runtime_stats? に格納されており、実行タイプとしては以下のような 3 種類の情報が個別に格納されています。
Determines type of query execution:
0 ? Regular execution (successfully finished)
3 ? Client initiated aborted execution
4 – Exception aborted execution
クエリタイムアウト (コマンドタイムアウト) について、execution_type = 3 の情報として、格納されているようで、この情報を取得することで確認ができそうです。
今回は以下のような? TPC-H のクエリをインデックスをなにも設定していない状態で実行させているため、数十秒ではタイムアウトしてしまうような状態としています。
$sql = @" SELECT L_RETURNFLAG, L_LINESTATUS, SUM(L_QUANTITY) AS SUM_QTY, SUM(L_EXTENDEDPRICE) AS SUM_BASE_PRICE, SUM(L_EXTENDEDPRICE*(1-L_DISCOUNT)) AS SUM_DISC_PRICE, SUM(L_EXTENDEDPRICE*(1-L_DISCOUNT)*(1+L_TAX)) AS SUM_CHARGE, AVG(L_QUANTITY) AS AVG_QTY, AVG(L_EXTENDEDPRICE) AS AVG_PRICE, AVG(L_DISCOUNT) AS AVG_DISC, COUNT(*) AS COUNT_ORDER FROM LINEITEM WHERE L_SHIPDATE <= dateadd(dd, -90, cast('1998-12-01' as datetime)) GROUP BY L_RETURNFLAG, L_LINESTATUS ORDER BY L_RETURNFLAG,L_LINESTATUS GO "@ 1..10 | %{Invoke-Sqlcmd -ServerInstance . -Query $sql -Database "tpch" -QueryTimeout 10}
直近一時間で、クエリタイムアウトの発生したクエリの取得であれば、以下のような形でしょうか。
--sp_query_store_flush_db SELECT SWITCHOFFSET(rsi.start_time, DATEPART(tz, SYSDATETIMEOFFSET())) AS start_time, SWITCHOFFSET(rsi.end_time, DATEPART(tz, SYSDATETIMEOFFSET())) AS end_time, SWITCHOFFSET(rs.first_execution_time, DATEPART(tz, SYSDATETIMEOFFSET())) AS first_execution_time_local, SWITCHOFFSET(rs.last_execution_time, DATEPART(tz, SYSDATETIMEOFFSET())) AS last_execution_time_local, st.query_sql_text, sq.query_hash, rs.* FROM sys.query_store_runtime_stats rs INNER JOIN sys.query_store_runtime_stats_interval rsi ON rs.runtime_stats_interval_id = rsi.runtime_stats_interval_id INNER JOIN sys.query_store_plan sp ON sp.plan_id = rs.plan_id INNER JOIN sys.query_store_query sq ON sp.query_id = sq.query_id INNER JOIN sys.query_store_query_text st ON st.query_text_id = sq.query_text_id WHERE rs.last_execution_time >= DATEADD(hh,-1,CAST(SYSDATETIMEOFFSET() AS datetimeoffset)) AND rs.execution_type = 3 AND rs.avg_duration >= 9000000 ORDER BY SWITCHOFFSET(rsi.start_time, DATEPART(tz, SYSDATETIMEOFFSET())) DESC
今回はクエリのタイムアウトを 10 秒 / 20 秒に設定した 2 パターンで実行していますので、実行時間が 9 秒以上で異常終了したクエリを取得しています。
(10 秒以上でもよいとは思いますが、1 秒程度の余裕を持たせて情報を取得しています。ADO.NET ですとデフォルトは 30 秒かと思いますが。)
実際に取得した情報が以下になります。
今回は 10 秒 / 20 秒でクエリタイムアウトを設定して実行していますので「avg_duration」や「last_duration」等が 10 秒 / 20 秒になっていることが確認できるかと思います。
(duration はマイクロ秒で格納されています。)
1,2 行目が 20 秒、3~5 行目が 10 秒のクエリタイムアウトを設定して実行したものになりますが、タイムアウトの時間によって実行時間が変わっていることが確認できますね。
この情報の中で、3 行目については、他の行と違うトレンドとなっていることが確認できるかと思います。
3 行目以外は、CPU 使用時間が、35 秒 / 72 秒程度になっていることが確認できます。
今回の環境は、4 コアの環境となっておりクエリで使用された並列度についてもクエリストアの情報から確認することができます。
CPU 使用時間を DOP で割ると 8.75 秒 / 18 秒となりますので、処理時間内で CPU についてはかなり使用されていた状態となります。
また、物理 / 論理 IO の発生状況も取得することができ、今回はかなりの I/O が発生していますので、2,3 行目以外は処理が行われていた状態で発生したタイムアウトの可能性が高いと考えられます。
これらの情報から大量のデータの操作を使用として、処理性能とタイムアウトの時間のバランスが悪くクエリがタイムアウトした可能性があると考えられます。
このケースについてはクエリの実行効率を上昇させるための手段を検討する必要が出てきます。
それでは、3 行目のような状態はどのようなケースになるかというと、ロック競合によりブロッキングが発生しており、処理が進まなかった場合の例となります。
3 行目の情報が出力される際には、TPC-H のクエリの実行前に以下のようなクエリを実行していました。
BEGIN TRAN SELECT TOP 1 * FROM LINEITEM WITH(XLOCK, HOLDLOCK)
LINEITEM に対して、排他ロックを保持したままの状態にするクエリですが、このクエリが実行されていたため、TPC-H のクエリではロックを取得することができず、ロック競合によるブロッキングが発生し、CPU や I/O は発生しておらず、クエリタイムアウトが発生したものと考えられます。
クエリストアには正常完了時の情報も、もちろん取得されており、クエリのハッシュによる検索ということもできますので、先ほどのクエリを以下のように変更することで直近 5 時間で実行された特定のクエリの状態というのを確認することができます。
SELECT SWITCHOFFSET(rsi.start_time, DATEPART(tz, SYSDATETIMEOFFSET())) AS start_time, SWITCHOFFSET(rsi.end_time, DATEPART(tz, SYSDATETIMEOFFSET())) AS end_time, SWITCHOFFSET(rs.first_execution_time, DATEPART(tz, SYSDATETIMEOFFSET())) AS first_execution_time_local, SWITCHOFFSET(rs.last_execution_time, DATEPART(tz, SYSDATETIMEOFFSET())) AS last_execution_time_local, st.query_sql_text, sq.query_hash, rs.* FROM sys.query_store_runtime_stats rs INNER JOIN sys.query_store_runtime_stats_interval rsi ON rs.runtime_stats_interval_id = rsi.runtime_stats_interval_id INNER JOIN sys.query_store_plan sp ON sp.plan_id = rs.plan_id INNER JOIN sys.query_store_query sq ON sp.query_id = sq.query_id INNER JOIN sys.query_store_query_text st ON st.query_text_id = sq.query_text_id WHERE rs.last_execution_time >= DATEADD(hh,-5,CAST(SYSDATETIMEOFFSET() AS datetimeoffset)) AND sq.query_hash = 0xB4A24E1213D92EE3 AND rs.avg_duration >= 9000000 ORDER BY SWITCHOFFSET(rsi.start_time, DATEPART(tz, SYSDATETIMEOFFSET())) DESC
5,6 行目のデータについては、クエリタイムアウトを無制限にした状態で実行したものとなりますので実行の状態は「Regular」(成功) となっています。
このような情報の取得を行うと、「成功時」と「失敗時」の情報の比較ができますので、成功した場合と失敗した場合で、使用しているリソースの状態の違いを比較することもができます。
クエリストアはデフォルトでは 1 時間単位で情報の集約が行われています。
このような比較を実施する場合、収集間隔を短くして、平均的な実行時間の精度をあげるという考慮も必要になる可能性がありますが、最初の一歩としては、一時間間隔の情報でもよいかと思います。
(今回は、検証用に複数行のデータを短時間で取得したかったので、10 分間隔としています。)
クエリストアで取得されている情報を、現場で有益な情報としてどのように利用するかは奥が深いですね。