先日投稿した SQL Server 2022 で Non-yielding Scheduler 発生時の出力内容が追加されていました は SQL Server 2022 向けの情報となり、投稿時点の最新バージョンの SQL Server を使用することで、ERRORLOG から g_copiedStackInfo のコンテキストを取得し、スケジューラーを解放しないスレッドのスタックを確認することができることを確認しました。
それ以外のバージョンでは、ダンプが出力されたタイミングでしか確認できないとなると、発生時の初回の情報しか確認でいないことになり、SQL Server のサービスを連続稼働している最中のエラーの原因特定が困難になってしまいます。
これを解消することができないか、考えていたところ「nonyield_copiedstack_ring_buffer_recorded」という拡張イベントを見つけることができました。
手元の環境では、SQL Server 2022 以外では、2019 CU16 / 17 で追加されていることは確認できたのですが、Some of the more obscure changes in SQL Server 2022, Part 1 では差分として上げられているので、使用できるバージョンに制限は出てきそうですが、2022 でなくても使用できる環境はあるようです。
このイベントの説明は次のようになっており、g_copiedStackInfo 相当の内容を SQL Server のリングバッファーに出力しているようです。
一時停止していないスタックがコピーされリング バッファーに記録されました
この拡張イベントを使用することで、サービス起動中の SQL Server で複数回 Non-yielding Scheduler が発生していた場合でもスタックの情報を確認することができそうです。
実際に、SQL Server 2019 CU17 でイベントを設定したものが以下になるのですが、サービスの再起動を行わなくても複数 Non-yielding Scheduler の情報を取得できていることが確認できます。
標準で取得されているイベントフィールドとして、「stack_frames」があるのですが、この情報を SQLCall StackResolver 等で解決することで、どのような処理で Non-yielding が発生したのかを確認することができます。(call_stack については Schedule Monitor がスレッドを検知したという情報となっており、実際の処理については Stack Frames に含まれています)
今回は、Windbg で強制的にスレッドを停止状態にしたので、通常は発生しないようなスタックとなるかもしれませんが、実際に拡張イベントを取得した Stack Frames を解決してみると次のような情報が確認できました。
左が停止したスレッドのコールスタック / 右が拡張イベントを解決したコールスタックとなるのですが、等価の情報が取得できていそうでした。
サービス起動中に 2 回目以降に発生した Non-yielding Scheduler の原因を調査したい場合、自動的に取得されるダンプがないため、稼働中のプロセスに接続または手動でダンプを取得し、g_copiedStackInfo の情報 (.cxr sqlmin!g_copiedStackInfo+0X20;kc) を取得する必要があるのかと思っていたのですが、拡張イベントで取得ができると、稼働中の環境でも取得がしやすそうかなと思いました。
実際に Non-yielding Scheduler が発生している状態と情報が取得できるタイミングではタイムラグがあるので、正確な情報が取得できるかは確約ができないのですが、このような情報取得方法も覚えておくとよさそうですね。