アプリケーションから SQL Server / SQL Database にコマンド (クエリ) を実行する際には、「コマンドタイムアウト」(クエリタイムアウト) について考慮をしておく必要があります。
ADO.NET の SQL Server 向けのドライバーではデフォルトでは 30 秒に設定されています。
コマンドタイムアウトの時間に達すると「Timeout expired.? The timeout period elapsed prior to completion of the operation or the server is not responding.」「実行タイムアウトの期限が切れました。操作完了前にタイムアウト期間が過ぎたか、サーバーが応答していません。」のエラーが発生し、クエリの実行がキャンセルされます。
アプリケーション側で Exception をキャッチして、その時に実行されていたクエリなどをロギングするようになっていれば、「どのようなクエリによりタイムアウトが発生したか？」を確認することができますが、そのようなロギングの仕組みがない or 情報が不足している場合に、サーバー側観点だけでどのような情報取得の対応ができるか、考えてみました。
Contents
コマンドタイムアウトは「クライアント側の処理」により発生する
最初に「コマンドタイム後はなぜ発生するか？」を把握しておきます。
これについては クエリタイムアウト – その仕組み で解説されている内容となりますが、クエリアイムアウトを発生させているのはサーバー側の処理ではなく「クライアント側の処理」となります。
コマンドタイムアウトを5 秒とし、それ以上時間がかかるクエリを実行した際のネットワークのパケットが以下となります。
「192.168.x.x」の IP がクライアントとなり、「10.200.x.x」が SQL Server となります。
Time が 2 秒 (2.863781) のタイミングで、クライアントから SQL Server に対して、SQL batch (クエリの実行) のパケットが投げられていることが確認できます。
その 5 秒後 (7.867111) のタイミングで、クライアントから SQL Server に対して、Attention のパケットが投げられています。
SQL Server とクライアントのメッセージでは、TDS (Tabular Data Stream) が使用されることが多いですが、Attention については、次のように TDS で Attention メッセージ クライアントから送信されることになります。
この Attention のパケットがクエリのキャンセル要求となり、今回のケースであればコマンドタイムアウトにより Attention パケットが投げられたということになります。
つまり、コマンドのタイムアウトは「コマンドタイムアウトの時間に達したため、SQL Server がクエリをキャンセルする」ことで発生しているのではなく、「コマンドタイムアウトの時間に達したため、クライアントがクエリのキャンセルメッセージ (Attention) を送信し、その要求により SQL Server がクエリをキャンセルする」ことにより発生していることになります。
SSMS から実行したクエリがタイムアウトしないのは、SSMS というツールでは、コマンドタイムアウト (実行タイムアウト) が 0 (無制限) に設定されているのがデフォルトとなっているためです。
サーバー側でコマンドタイムアウトの発生状況を取得することはできるか？
コマンドタイムアウトは「クライアントの要求」により発生します。
それでは、次に、このクライアントの要求により発生したコマンドタイムアウトを SQL Server / SQL Database のサーバー側観点でデータベース管理者が把握することができるかを考えてみましょう。
コマンドタイムアウトはクライアントが Attention メッセージを送信しすることで発生します。
つまり、サーバー側ではこの Attention メッセージの受信状況が確認できれば、コマンドタイムアウトの発生状況を把握することができるということになります。
Attention メッセージは、クエリのキャンセル要求のためのメッセージですので、コマンドタイムアウト専用というわけではありません。
厳密なコマンドタイムアウトの発生回数を把握するためには使用することはできませんが、クエリのキャンセルを行うという行為自体は、コマンドタイムアウトで発生する機会の方が多いため、サーバーのおおよその傾向を取得することは可能です。
Attention の発生状況についてはパフォーマンスモニターの項目または、sys.dm_os_performance_counters の情報として取得することが可能です。
SQL Server: SQL Statistics の SQL Attention rate がサーバーが受信した Attention メッセージの数となります。
次の画像が、コマンドのタイムアウトを頻繁に発生させている状態で情報を取得したものとなるのですが、コマンドタイムアウトが発生したタイミングで値が上昇していることが確認できます。
この情報を使用することでサーバー観点でコマンドタイムアウトの発生状況 (厳密には Attention メッセージの受信状況) を確認することができます。
そのほかの方法としては、sys.dm_os_ring_buffers から取得するということもできそうです。
この情報はメモリ上の循環バッファ上のものですので、どの程度の期間の情報が取得されているかの保証はありませんが、直近の発生状況でしたら次のクエリで取得できる可能性があります。
DECLARE @round_start_time bigint = (SELECT MAX(round_start_time) FROM sys.dm_os_memory_cache_clock_hands)
SELECT
rb.ring_buffer_address,
rb.ring_buffer_type,
rb.timestamp,
DATEADD(ms, (rb.timestamp - @round_start_time), GETDATE()) AS record_time,
CAST(rb.record AS xml) AS record,
CAST(rb.record AS xml).value('(/Record/@id)[1]','int') AS id,
CAST(rb.record AS xml).value('(//Error)[1]','int') AS Error,
CAST(rb.record AS xml).value('(//Severity)[1]','int') AS Severity,
CAST(rb.record AS xml).value('(//State)[1]','int') AS State
FROM
sys.dm_os_ring_buffers AS rb
WHERE
ring_buffer_type = 'RING_BUFFER_EXCEPTION'
AND
CAST(rb.record AS xml).value('(//Error)[1]','int') = 3617
ORDER BY timestamp DESC
検証していた限りでは、Error Id 3617 は、コマンドタイムアウトが発生したタイミングで出力されているように見受けられました。
コマンドタイムアウトが発生したクエリをサーバーサイドで特定するにはどうするか？
コマンドタイムアウトが発生したクエリをサーバーサイドで特定 (取得 / ロギング) するための方法として、次のような 2 つの機能を活用することができます。
拡張イベント or SQL Server プロファイラの Attention イベントクラス
Attention イベントクラスの取得についてはデフォルトでは設定されていないため、この方法で情報を取得したい場合には、明示的に情報の取得の設定を行う必要があります。
次の画面は、拡張イベントの画面となりますが、取得可能なイベントに「attention」があります。
このイベントを取得し、取得項目として「sql_text」を含めておくことで「どのようなクエリの実行で Attention メッセージを受信したか？」をサーバーサイドで取得することができます。
実際には次のような情報を取得することができます。
クエリのテキストが取得できていますので、どのようなクエリで Attention メッセージが送信されたのかを把握することとができます。
クエリストア
もう一つの方法がクエリストアとなります。
SQL Server では、DB 単位で明示的に有効化する必要がありますが、SQL Database ではデフォルトで有効化されていますので、拡張イベントと比較して、情報の取得ができる環境はクエリストアの方が多いかもしれません。
クエリストアは実行されたクエリの情報が自動的に取得されますが「クエリの実行状態」についても情報が取得されています。
この実行状態には「正常終了」だけでなく「異常終了」も含まれており、Attention メッセージによりキャンセルされたクエリの情報についても取得が行われます。
例としては次のようなクエリとなります。
--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.runtime_stats_id, rs.plan_id, rs.runtime_stats_interval_id, rs.execution_type, rs.execution_type_desc, rs.first_execution_time, rs.last_execution_time, rs.count_executions, (rs.avg_duration / 1000.0) AS avg_duration_ms, (rs.last_duration / 1000.0) AS last_duration_ms, (rs.min_duration / 1000.0) AS min_duration_ms, (rs.max_duration / 1000.0) AS max_duration_ms, (rs.stdev_duration / 1000.0) AS stdev_duration_ms, (rs.avg_cpu_time / 1000.0) AS avg_cpu_time_ms, (rs.last_cpu_time / 1000.0) AS last_cpu_time_ms, (rs.min_cpu_time / 1000.0) AS min_cpu_time_ms, (rs.max_cpu_time / 1000.0) AS max_cpu_time_ms, rs.stdev_cpu_time, rs.avg_logical_io_reads, rs.last_logical_io_reads, rs.min_logical_io_reads, rs.max_logical_io_reads, rs.stdev_logical_io_reads, rs.avg_logical_io_writes, rs.last_logical_io_writes, rs.min_logical_io_writes, rs.max_logical_io_writes, rs.stdev_logical_io_writes, rs.avg_physical_io_reads, rs.last_physical_io_reads, rs.min_physical_io_reads, rs.max_physical_io_reads, rs.stdev_physical_io_reads, rs.avg_clr_time, rs.last_clr_time, rs.min_clr_time, rs.max_clr_time, rs.stdev_clr_time, rs.avg_dop, rs.last_dop, rs.min_dop, rs.max_dop, rs.stdev_dop, rs.avg_query_max_used_memory, rs.last_query_max_used_memory, rs.min_query_max_used_memory, rs.max_query_max_used_memory, rs.stdev_query_max_used_memory, rs.avg_rowcount, rs.last_rowcount, rs.min_rowcount, rs.max_rowcount, rs.stdev_rowcount, rs.avg_num_physical_io_reads, rs.last_num_physical_io_reads, rs.min_num_physical_io_reads, rs.max_num_physical_io_reads, rs.stdev_num_physical_io_reads, rs.avg_log_bytes_used, rs.last_log_bytes_used, rs.min_log_bytes_used, rs.max_log_bytes_used, rs.stdev_log_bytes_used, rs.avg_tempdb_space_used, rs.last_tempdb_space_used, rs.min_tempdb_space_used, rs.max_tempdb_space_used, rs.stdev_tempdb_space_used 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 <> 0 ORDER BY SWITCHOFFSET(rsi.start_time, DATEPART(tz, SYSDATETIMEOFFSET())) DESC
直近 1 時間の範囲の異常終了したクエリ取得を行うものとなりますが、これにより次のような情報を取得することができます。
「Aborted」となっており、平均的な実行時間が 6.5 秒となっていることが確認できます。
コマンドタイムアウトは 1 秒で実行したクエリではあるのですが、クエリがキャンセルされるにはは、クライアントの状態 / 実行方法 / サーバーの状態 / トランザクションの状態等に応じて多少のタイムラグが出ます。
今回の例ではコマンドタイムアウトと同一値ではありませんが、環境によってはクエリのタイムアウト時間の近似値となるケースもあり、この情報から、コマンドタイムアウトに達して Aborted となったという判断をすることもできます。
クエリの情報はキャッシュからも取得できますが、クエリキャッシュはメモリ上の情報であり、情報が取得できるのが確実ではないことと、キャッシュされるクエリは「クエリの実行が完了した場合にキャッシュされる」というような動作となっているため、実行が完了しなかったクエリについては情報を取得することができません。
キャッシュの情報で、「最大実行時間がコマンドタイムアウト時間に近い」ような場合は「タイムアウトが発生した可能性のあるクエリ」として判断することができるかもしれませんが、クエリストアの方が確実性が高いかと思います。
コマンドタイムアウトの発生時の詳細な情報については、アプリケーション側のロギングの仕組みや APM で取得ができていることが望ましいと思いますが、SQL Server / SQL Database 側のデータベース管理者の観点でもいくつかの情報確認を行うことができますので、「Attention メッセージを起点とした情報取得」については、方法を知っているというのは一つの武器になるのではないでしょうか。