SQL Server の待機事象を一歩踏み込んで確認するための手法 (コールスタックの解析) at SE の雑記

SQL Server では、「待機事象 (Wait Stats)」の情報を確認することで、インスタンスで同時実行性を低下させる問題が発生しているかの確認をするという分析手法があります。

SQL Server でクエリ実行の処理 (タスク) を実行する際には、タスクは次の状態を遷移しながら処理が行われます。

この 3 種類の状態の中で「待機状態」に入っている時間が少なければ、他の処理により同実行性を低下させることなく、処理を実行することができていることになります。

Contents

1 待機状態の確認方法
2 待機事象の一歩踏み込んだ確認方法
3 まとめ

待機状態の確認方法

一般的な待機情報の確認方法としては次のような DMV を使用するものがあります。

sys.dm_os_wait_stats

インスタンス全体の待機事象を確認するのであれば、sys.dm_os_wait_stats から確認することができます。
この DMV から、インスタンスが最後に起動してからの待機事象の累計値を確認することができます。

手動で累計値をクリアすることもできます。

基本的には、二点で取得して差分を算出すれば、累計値をクリアしなくてもデータの加工は可能なのですが、長時間、稼働しているシステムでは、「最大値」(max_wait_time) が、を考慮した分析を行う必要があるケースがあります。

「最大値の値にどのタイミングで達したか？」を判断するために、max_wait_time の値を使用するのですが、最大値だけは差分では抽出できませんので、特定のタイミングで DBCC SQLPERF を実行することで、最大値を初期化し、どのタイミングで最大値が更新されるかを確認するという手法ですね。

sys.dm_exec_session_wait_stats

SQL Server 2016 以降では、sys.dm_exec_session_wait_stats という DMV が追加されています。
これは、sys.dm_os_wait_stats のアクティブなセッション版の情報となり、セッション単位で待機事象の情報を確認することができます。

コネクションの破棄や、コネクションプールによる接続の再利用時 (sp_resetconnection) で情報がリセットされ、現在、アクティブなセッションについての待機事象の情報となりますので、ピンポイントで情報を取得するのは難しいかもしれませんが、実行中のクエリの情報などはこの DMV から取得することもできます。

sys.query_store_wait_stats

クエリストア自体は SQL Server 2016 で追加された機能ですが、SQL Server 2017 では、sys.query_store_wait_stats というシステムビューが追加され、クエリストアに待機事象の情報が取得されるようになりました。

SSMS でクエリストアの情報を確認する際には「クエリ待機統計」という項目がありますので、クエリ経由ではなく GUI 経由でも取得することができます。

クエリストアの情報として格納さている待機事象は、sys.dm_os_wait_stats / sys.dm_exec_session_wait_stats と異なり、関連する待機事象をカテゴライズして集計を行っています。

そのため、他の DMV と比較すると詳細は取得することはできないのですが、クエリストアの特徴である「設定を行うだけで過去の情報までさかのぼってクエリ単位で情報を確認できる」という特徴を待機事象でも使用することができるようになりますので、クエリの実行効率の低下が発生した場合に、有効に活用することができます。

実行プランから取得

スキーマの定義を見ていると、SQL Server 2016 SP1 辺りからのようですが、今の SQL Server では、実行プラン内にも待機事象の情報が出力されるようになっています。

実際にクエリを実行し、待機事象からクエリのボトルネックとなっている個所を確認するということもできるのようになっています。

待機事象の一歩踏み込んだ確認方法

ここまでで記載した内容は待機事象を確認するための First Step であり、待機事象を確認する際の基本的な情報です。

待機事象 (Wait / Latch) について調査をしていると、sqlskills.com の次の情報にたどり着くことが多いのではないでしょうか。

Paul Randal が主体となって情報を公開されているのだと思いますが、公開されている情報の中では、どのような理由により該当の待機事象が発生しており、該当の待機事象が発生した際のコールスタックについても公開がされています。

この情報が一歩踏み込んだ待機事象の確認方法となります。

これらの情報ですが、特殊なソフトウェアを用いなくても取得できるようになっており、情報の取得方法については、How to determine what causes a particular wait type の記事で公開をしてくださっています。

情報の取得は、拡張イベントの「wait_info」のイベントを取得し、取得する項目として「call_stack」を取得することで、コールスタックの解析を行っています。

環境の準備

コールスタックの情報を表示するためには、シンボルファイルが必要となり、シンボルファイルの入手方法についても How to download a sqlservr.pdb symbol file で情報が公開されています。

基本的な作業手順としては、次の環境を作成します。

Windows SDK で、Windows debugging tools をインストール
Windows debugging tools に含まれる symchk を使用して、次の DLL のシンボルファイルをダウンロード
- sqlservr.pdb
- sqldk.dll
- sqlmin.dll
- sqllang.dll
ダウンロードしたシンボルファイル (pdb) を SQL Server の Binn ディレクトリにコピーして、SQL Server のサービスを再起動
- SQL Server 2019 であれば「C:\Program Files\Microsoft SQL Server\MSSQL15.MSSQLSERVER\MSSQL\Binn」にコピー

この環境は、コールスタックを取得する SQL Server ではなく、コールスタックの分析を行う SQL Server で整えておけばよかったはずですので、情報の取得対象と解析環境は分離できたかと。

情報取得対象の SQL Server と解析に使用する SQL Server を別に構築する場合、マイナーバージョンまで合わせておかないと、コールスタックの解決が正常に行われません。
CU 等、パッチを適用した後は、シンボルファイルについても現在使用しているバージョンのシンボルを再ダウンロードする必要があります。

次のクエリは主要なロックの待機について、コールスタックを取得するための拡張イベントを取得するものです。

CREATE EVENT SESSION [CallStackTrace] ON SERVER 
ADD EVENT sqlos.wait_info(
    ACTION(package0.callstack)
    WHERE ([opcode]=(1) AND [wait_type]>=(1) AND [wait_type]<=(21)))
ADD TARGET package0.ring_buffer
WITH (MAX_MEMORY=4096 KB,EVENT_RETENTION_MODE=ALLOW_SINGLE_EVENT_LOSS,MAX_DISPATCH_LATENCY=30 SECONDS,MAX_EVENT_SIZE=0 KB,MEMORY_PARTITION_MODE=NONE,TRACK_CAUSALITY=OFF,STARTUP_STATE=OFF)
GO

Action として、callstack を取得するようにします。

コールスタックの解析

拡張イベントで取得したコールスタックですが、記事内で紹介されている次のようなクエリで、情報を確認することができます。

SELECT
    [event_session_address],
    [target_name],
    [execution_count],
    CAST ([target_data] AS XML)
FROM sys.dm_xe_session_targets [xst]
INNER JOIN sys.dm_xe_sessions [xs]
    ON [xst].[event_session_address] = [xs].[address]
WHERE [xs].[name] = N'CallStackTrace';
GO

通常の状態では、コールスタックは次のような表示となります。

拡張イベントの解析に使用する SQL Server でシンボルファイルを適切に配置し、TF 3656,2592 を有効にした環境でコールスタックの解析を行った場合は、シンボルファイルによって、コールスタックのメソッドの情報を表示することができるようになります。

DBCC TRACEON(3656,2592,-1)

SELECT
    [event_session_address],
    [target_name],
    [execution_count],
    CAST ([target_data] AS XML)
FROM sys.dm_xe_session_targets [xst]
INNER JOIN sys.dm_xe_sessions [xs]
    ON [xst].[event_session_address] = [xs].[address]
WHERE [xs].[name] = N'CallStackTrace';

拡張イベントは「wait_info」の「End」のタイミングで情報の取得を行うようにしていますので待機事象が解決した際の、コールスタックが表示されるようになっているはずです。

この情報により「どのような事象で該当の待機事象が発生しているのか？」の調査を行う際に、SQL Server のメソッドレベルで動作の推測を行うことができるようになります。

今回は拡張イベントを検索する SQL でコールスタックの解析を行っていますが、SQLCallStackResolver というツールも公開が行われています。(MS の社員の方が作られたツールです)

このツールでもコールスタックの解析を行うことができるのですが、ツールからシンボルのダウンロードや、コールスタックの内容を張り付けて分析を行うことができますので、SQL Server がない環境でも解析を行うことができるようになります。

各種 CU まで含めた、様々なバージョンの SQL Server のシンボルファイルをダウンロードできるようになっていますので、拡張イベントを直接解析するより、SQLCallStackResolver を使用したほうが分析は楽かもしれませんね。

まとめ

最初の待機事象の解析であれば DMV を使用して解析を行うことで必要な情報を得ることができます。

たださい、待機事象の情報を深く分析しようとした場合「該当の待機事象がどのような場合に発生するのか？」を把握し、「実際のワークロードではその状態がどのような場合に発生するのか？」を検討することが重要になるケースがあります。

SQL Server はプロプライエタリな製品ですので、利用者が、待機事象の解析を行おうとした際に、ソースコードでレベルで待機事象の発生要因を調査することはできません。

しかし、今回紹介したようなコールスタックの分析については利用者が実施することができるようになっており、実施するための情報も多数公開が行われています。

また、このようなコールスタックの解析を Windbg から行うというような内容は、海外の SQL Server のセミナーで実施されているものでもありますので、海外の SQL Server のエンジニアの方は結構知っている内容なのかもしれませんね。

一歩踏み込んだ分析を行いたい場合の手法として、待ち事象について、コールスタックから分析を行うという手法も知っておくと良いのではないでしょうか

月	火	水	木	金	土	日
1	2	3	4	5	6	7
8	9	10	11	12	13	14
15	16	17	18	19	20	21
22	23	24	25	26	27	28

SE の雑記