本ブログでは、次の投稿で SQL Server へのクエリ実行時の「コマンド タイムアウト」(クエリ タイムアウト) について触れてみました。
そもそも「コマンド タイムアウト」とは何なのでしょうか？
上記の投稿では触れていなかった部分についてもまとめておきたいと思います。
Contents
コマンド タイムアウト は SQL Server の設定ではない
アプリケーションから、クエリの実行時間が一定時間続いた場合、次のような例外が発生することが「コマンド タイムアウト 」となります。
Execution Timeout Expired. The timeout period elapsed prior to completion of the operation or the server is not responding.
待ち操作がタイムアウトになりました。
コマンド タイムアウトですが発生させているのは、「SQL Server」ではなく、「アプリケーション」となります。
SQL Server でタイムアウト関連の設定の項目の一つとしては、「リモート クエリのタイムアウト」の設定があります。
この設定は、remote query timeout サーバー構成オプションの構成 となり、「リンクサーバー経由でのリモートクエリの実行によるタイムアウトの制御」となるため、一般的なクエリ実行には、関係ありません。
他にも「クエリの待機」の設定もあります。
この項目については、query wait サーバー構成オプションの構成 となり、「クエリ実行時間が長い場合のタイムアウト」とは異なる実行キューの制御となりますので、この項目を調整しても一般的な長時間のクエリ事項によるタイムアウトの制御はできません。
「コマンドのタイムアウトが発生したとアプリケーションが認識した場合、それは、アプリケーション側の制御によってタイムアウトを発生させた」ということであり、「SQL Server がクエリの実行が一定時間続いたので、強制的にクエリをタイムアウトさせた」とは異なるということを意識しておく必要があります。
コマンド タイムアウトが発生すると「Attention」の TDS のパケットが「アプリケーションから送信」される
次のようなスクリプトを実行して、SQL Server に対してクエリを実行してみます。
using namespace Microsoft.Data.SqlClient
Clear-Host
Add-Type -AssemblyName Microsoft.Data.SqlClient
$con = New-Object SqlConnection("Server=tcp:xxxxxx;User=xxxxxx;Password=xxxxxx;Database=tpch;Application Name=TestApp")
$con.Open()
$cmd = $con.CreateCommand()
$cmd.CommandText = "SELECT * FROM LINEITEM"
$cmd.CommandTimeout = 5
try {
$sw = [System.Diagnostics.Stopwatch]::StartNew()
$cmd.ExecuteNonQuery()
}
catch {
Write-Host $_.Exception
}
finally {
$sw.Stop()
Write-Host $sw.Elapsed
$con.Close()
$con.Dispose()
}
LINEITEM には数 GB のデータが格納されており、、今回使用している環境では ExecuteNonQuery は 5 秒以上かかります。
コマンドタイムアウトが 5 秒に設定されていますので、クエリ実行から 5 秒経過すると、次のような例外が発生し、コマンド (クエリ) がタイムアウトします。
この時のネットワークのパケットを確認します。
SQL Server の IP アドレスが、「192.168.0.202」、アプリケーションを実行している環境の IP アドレスが「192.168.0.2」となります。
192.168.0.2 から 192.168.0.202 に対して、Attention の TDS パケットが実行されていることが確認できます。
このパケットが「アプリケーションがコマンドタイムアウトの設定に達したため、SQL Server に対して、Attention メッセージを送信した状態」となります。
Attention の仕様については 2.2.1.7 Attention で解説されています。
アプリケーションはコマンドタイムアウトに指定されている時間に達すると、SQL Server に対して、Attension メッセージを送信します。
この Attention メッセージが SQL Server が認識し、SQL Server からの Attention の受信応答をアプリケーションが受け取ることで、クエリのキャンセルが完了します。
上記の画像では、アプリケーションが Attention のメッセージを送信した後も SQL Server からの Response が継続していることが確認できますが、これは、アプリケーションが SQL Server からの Attention の受信応答を待っているためで、アプリケーションが Attention を送信しても即時にクエリの実行がキャンセルされているわけではないということを示しています。
Attention メッセージの TDS はとてもシンプルなものとなります。
「どのような事象により Attention メッセージが送信されたか？」というような情報は持っていません。
SQL Server がコマンドタイムアウト時に受け取っているメッセージはこれだけになりますので、「SQL Sever に送信されたキャンセル要求のメッセージでは、どのような事象によりクエリがキャンセルされたか」を判断することができないということになります。
また、「何秒に達したので Attention メッセージを送信したのか？」についても SQL Server 側では判断できません。
コマンドタイムアウトの設定値は、アプリケーション側に依存しており、SQL Server のセッション情報でも保持していない情報となりますので「コマンドタイムアウトの設定」については、アプリケーション側に確認をする必要があります。
コマンド タイムアウトは「アプリケーションから Attention メッセージを送信して、コマンドをキャンセルする動作」となりますので、コマンドタイムアウトを発生させた主体は、アプリケーション側となります。
ただし「SQL Server の何らかの動作によってクエリの実行に時間がかかったためタイムアウトの秒数に達した」という可能性が高いため、SQL Server では「タイムアウトの情報」を調査するのではなく「実行に時間のかかったクエリ」の調査を行うことになります。
しかし、コマンドタイムアウトはアプリケーションが基点として発生しますので、「コマンドタイムアウトが発生した場合、どのようなクエリが実行され、クエリの実行に何秒かかったのでタイムアウトしたのか？」については、アプリケーション側でもログとして取得することが可能かは検討を行う必要があります。
(タイムアウトが発生すると DB 観点での調査が来るケースが多いのですが、アプリケーションでクエリを出力しておいてくれれば、調査がスムーズに進むケースが多いはずなのですよね…。)
ちなみに、非同期クエリでキャンセルを実行した場合も Attention メッセージでキャンセルが行われているようでした。
$cts = New-Object System.Threading.CancellationTokenSource
$task = $cmd.ExecuteNonQueryAsync($cts.Token)
$cts.Cancel()
アプリケーションからのクエリの実行から結果の取得にかかった時間が、コマンドタイムアウトに達すると、必ずタイムアウトが発生するのか？
先ほどは、時間のかかるクエリを ExecuteNonQuery を使用して実行しました。
それでは、データの取得を次のようにしてみるとどうでしょうか？
$reader = $cmd.ExecuteReader()
$dt = New-Object System.Data.DataTable
$dt.Load($reader)
DataReader で情報を取得している処理となり、完了まで 20 秒程度かかるクエリです。
CommandTImeout = 5 となっている状態で、この処理は完了するでしょうか？
今回の実行方法であれば、処理は正常に完了しました。
全てのパターンで、このような動作になるか保証はなく、アプリケーションで使用しているデータアクセスプロバイダーの実装に依存する形となるはずですが、今回のような ADO.NET の処理であれば、タイムアウトしないケースがあります。
DataReader でデータにアクセスをしていますが、今回はすべてのデータ読み取りでブロッキングは発生しておらず、各 Read の処理は 5 秒以下で完了しています。
そのため、「全てのデータを取得するためには 20 秒の処理時間が必要」となっていますが、各 Read についてコマンドタイムアウト以下の処理時間で完結しているためタイムアウトは発生しません。
それでは、SQL Server 側で次のクエリを実行した状態ではどうなるでしょうか？
BEGIN TRAN
SELECT * FROM LINEITEM WITH(XLOCK, HOLDLOCK) WHERE L_ORDERKEY = 302662
SELECT している途中のデータで排他ロックを取得した状態としており、Read Committed 分離レベルでデータを読み込んだ場合は、ロック競合によるブロッキングが発生します。
このような場合は、途中の Read 処理で 5 秒以上かかることになりますので、ロック競合が発生した Read のタイミングで Attention メッセージが送信され、コマンドタイムアウトとなります。
コマンドタイムアウトが発生した場合に SQL Server 観点ではどのような調査ができるか？
最初に書いておきますと、調査用の情報取得を仕掛けておかないと調査はできません。
何も調査用の情報を取得する仕組みを設定していない状態で、調査をしようとしても有効な情報は取得できない可能性がとても高いです。
ということで、日ごろから「問題が発生した場合に有益な情報を取得する仕組みづくり」については考慮しておく必要があります。
どのような仕組みで調査することができるかは、冒頭で紹介した投稿で紹介していますので、これらの情報を活用してみてはいかがでしょうか。
基本的には次のような情報を活用することになります。
方法 1 : パフォーマンスモニターの活用
SQL Server に対して送信された Attention メッセージの数であれば、パフォーマンスモニターの SQL Server: SQL Statistics オブジェクト の SQL Attention rate の情報を取得することで、メッセージの受信状況 ( = キャンセル要求のあったコマンドの発生状況) を確認することができます。
この情報から、コマンドタイムアウトが発生した時間帯を確認することができます。
方法 2 : 拡張イベントの活用
拡張イベントの Attention イベント クラス の情報を取得することでも Attention メッセージの発生状況を確認することができます。
パフォーマンスモニターでは、Attention メッセージの受信状況しか確認することはできませんでしたが、拡張イベントを使用することで「どのクエリの実行で Attention メッセージが送信されたのか？」についても確認することができます。
拡張イベントで情報を取得する場合には「イベントを相互に関連付ける方法を追跡する」の有効化も検討します。
Attention メッセージによってキャンセルされたクエリについては「sql_batch_completed」(実行方法によっては「rpc_completed」) の、「result」が「Abort」の情報として取得されます。
(sql_batch_completed をすべて取得するとノイズとなるデータが多いですので、フィルターで result = Abort を設定するようにしておくと、取得した情報の解析がしやすいです)
因果関係の追跡を有効化しておくことで attention と attention により Abort となった sql_batch_completed で同一の「attatch_activiti_id.guid」が付与されます。
これにより、attention が発生したバッチの情報が取得できるようになり、Attention が発生した理由の解析の一助となります。
クエリの実行時間 (duration) がコマンドタイムアウトに近い値となっている場合、SQL Server 観点でもコマンドタイムアウトが発生したのではないか？というような判断をすることもできます。
方法 3 : 待ち事象の取得
コマンド タイムアウトが発生したということは「何らかの要因により SQL Server からの情報取得に時間がかかった」可能性が考えられます。
SQL Server ではクエリの実行が何らかの要因により処理が進められていない場合には「待ち事象」が発生している状態となり、待ち事象を解析することで「クエリがどのような要因により実行効率が低下していたのか？」を確認することができます。
待ち事象の取得については、様々な方法がありますがクエリに特化した取得であれば、SQL Server 2017 以降であれば、クエリストアを活用することができます。
例としては PIVOT を使用した待ち事象の取得.sql のような方法があります。
これは SQL Server 2017 から取得できるようになった query_store_wait_stats を活用した方法となりますが、次のような情報を取得することができます。
クエリストアに格納されているクエリから「Aborted」(アプリケーション要求によってキャンセルされたクエリ) の情報を取得することができます。
Aborted になっているクエリの情報で、頻繁に発生していた待ち事象が、タイムアウトの原因となった可能性があるので、その待ち事象を減らすための対応を検討 / 実施することでタイムアウトが解消する可能性が考えられます。
上記の画像の場合は Lock が多いのでロック競合を減らすことでタイムアウトを緩和できる可能性があるということになります。
SQL Server 2017 以前のバージョンであれば、定期的に DMV の情報をダンプすることで代替することもできます。
サンプルについては EZMonitor (イージーモニター) として公開しています。
セッション単位の実行中のクエリの分析 については、dm_exec_session_wait_stats を使用しているため SQL Server 2016 以降でのみ実行可能ですが、OS タスクをベースとした待機状態の取得 については、SQL Server 2012 以降でも動作させることができるかと思います。
DMV を使用した情報取得については、瞬間的なものですので取得タイミングによっては必要となる情報が取得できていない可能性がありますが、分析を行うためには有益な情報となります。
実行されているクエリの情報を連続して時系列で並べることで、クエリ実行によって、どのような待機が発生していたのかを確認することができます。
クエリストアでは「ロックの待ちが多かった」という情報の取得となっていましたが、DMV で実行中のクエリの情報を取得することで、「どのようなロックがどのデータに対して発生していたか」というような情報を確認することができます。
ブロッキング対象のセッションについても確認できますので、ロック競合の原因となっていた情報を取得できる可能性もあります。
ロック競合については Blocked Process Report イベント クラス で取得することも検討した方が良いですが。
SQL Sever 観点で調査できるのはこのような内容ではないでしょうか。
今回はクエリの特定から SQL Server で実施するアプローチですが、クエリの特定については、アプリケーション側で Exception となったクエリの情報をロギングできた方が手っ取り早いと思いますが。
最後にも書きますが「コマンドタイムアウトはアプリケーションからの要求によって発生」し、「SQL Server はアプリケーションからのクエリのキャンセル要求に応じてクエリをキャンセルさせる」ことがコマンド タイムアウトという挙動となります。
コマンドタイムアウトを解決するためには、SQL Server 観点での調査だけでなく、アプリケーション側からもログを確認 (または、確認可能なログを出力する) し、アプリケーションとデータベースが協力して調査を行うことが、事象を解決するための最善の方法ではないでしょうか。