SQL Server の特定の待機を意図的に誘発させたり、特定のスレッドを一時的にフリーズさせて挙動を確認させる際に windbg を使用することがあるのですが、windbg で SQL Server を操作する際「WAITFOR DELAY」を題材にしてみると、操作方法を理解するのに役に立つ気がしたので、操作の流れをまとめておこうと思います。
本投稿は、windbg の導入の基本的な操作の把握や、SQL Server に関連するパブリックシンボルの設定については完了している前提となっており、それ以降の操作を記載しています。
WAITFOR DELAY のコールスタックを確認
WAITFOR DELAY の挙動に関与するために、windbg で WAITFOR DELAY に関連する処理が実行された際に、処理を停止させるブレークポイントを設定する必要があります。
そこで、SQL Call Stack Resolver を使用した SQL Server のコールスタックの分析 で紹介した、SQL Call Stack Resolver を使用して、WAITFOR DELAY が実行された際のコールスタックを取得します。
WAITFOR DELAY ですが、実行した際には「WAITFOR」という待機事象が発生します。
そこで、WAITFOR の待機事象が発生した際の拡張イベントを取得して、どのようなコールスタックの状態となっているかを確認します。
今回は次のような条件の拡張イベントを設定し、グローバルフィールドとして「callstack」を取得するようにしています。
「wait_type=WAITFOR」とすることで、「WAITFOR DELAY」が実行された際の待機事象を取得するようにしており、特定のクエリウィンドウのセッションから実行された WAITFOR DELAY の完了のタイミングでログが取得できるようにしています。
次のように WAITFOR DELAY を実行し、実行が完了すると、「wait_completed」のイベントが取得されます
これでコールスタックが取得できましたので、Call Stack Resolver でコールスタックを解決します。
ポイントとなるのが赤枠の箇所となります。
WAITFOR DELAY を実行すると「sqllang!CStmtWait::XretExecute」が呼び出され、実際の待機については「sqllang!SOS_Task::Sleep」で実行が行われているというコールスタックの流れとなります。
実際に待機が発生するのは、「sqllang!SOS_Task::Sleep」となりますので、windbg でこの関数の呼び出し時にブレークポイントを設定することで、WAITFOR DELAY の挙動に windbg 経由で関与することができます。
windbg で WAITFOR DELAY の処理に関与する
ブレークポイントを設定する関数の目途ができましたので、windbg で SQL Server のプロセスである sqlservr.exe に接続します。
デバッガーが SQL Server に接続できたら、ブレークポイントを設定しておきます。Sleep については引数違いで複数の関数がありますので bm でブレークポイントを設定しています。
bm sqllang!SOS_Task::Sleep
これで、WAITFOR DELAY が実行された際にブレークポイントで停止するように設定されているのですが、バックグラウンドタスクでも、Sleep の関数は呼ばれるので、自分が実行したクエリ以外でブレークポイントによる停止が発生する可能性があります。
そのため、想定していないブレークポイントが実行される場合は、自分が実行した WAITFOR DELAY のみで停止させるようにするために、ブレークポイントの設定を次のように設定することも検討します。
次のブレークポイントであれば 10 秒の待機を指定した場合のみデバッガに制御が戻ってくるはずです。
bm sqllang!SOS_Task::Sleep ".if (@rcx!=0x2710) { .printf \"skip breakpoints. sleep time [%d] ms \\n\",@rcx ;g } .else {k} "
10 秒以外の待機では次のように Print で情報が出力されるだけですが、10 秒の待機であれば、デバッガーに制御が戻ってきますので次のような WAITFOR DELAY を実行するとクエリの実行が途中で待機状態となり、デバッガーに制御が戻ります。
ブレークポイントで停止した際のコールスタックが表示されていますが「sqllang!SOS_Task::Sleep」で停止していますね。
この状態で「r」を実行するか Registers ウィンドウを表示してレジスタの情報を確認してます。
今回の SQL Server は x64 のプロセスですので、rcx が第一引数となっているかと思います。rcx の値を確認すると「0x2710」(10000) となっていることが確認できます。
「sqllang!SOS_Task::Sleep」第一次引数を確認すると「unsigned long」となっているので、ここには待機する時間をミリ秒で指定しているのだと思います。
10,000 ミリ秒 = 10 秒となりますので、rcx に 0x2710 が設定されていたと考えらえれます。
この状態で「g」で windbg から処理を進めると、処理を進めてから 10 秒後にクエリの実行が完了します。
それでは、WAITFOR DELAY に挙動に関与してみたいと思いますので、もう一度「WAITFOR DELAY ’00:00:10’」を実行して、ブレークポイントで停止させます。
ブレークポイントで停止したら「r rcx=ea60」で rcx の値を 60000 = 60 秒に変更して、実行を継続させます。先ほどはデバッガーから処理を継続してから 10 秒で処理が完了していましたが、今回は 60 秒経過後に処理が完了するようになります。
ブレークポイントで停止した際には、関数が実行される直前で停止しており、まだ関数自体は未実行の状態ですので、その状態でレジスタの値を変更して関数を実行したことで、「WAITFOR DELAY ’00:00:10’」が「WAITFOR DELAY ’00:01:00’」相当の挙動として実行されます。
SQL Server を windbg で操作する際には、どのような流れになるのか / どのような操作ができるのかを把握する際には、WAITFOR DELAY を使用してみるとシンプルで勉強になるのではないでしょうか。