SQL Server 2016 以降では、クエリ情報の取得はクエリストアを使用して取得を行うことができるようになり、SQL Server / Azure SQL Database では、この機能 (または、クエリストアを活用した機能) により、クエリ実行情報を取得することが一般的な方法となってきているのではないでしょうか。
SQL Server 2016 より前のバージョンでは、次のような DMV を使用して情報の取得が行われるケースが多かったかと思います。
SQL Server 2016 以降の環境で、クエリストアが有効になっている環境でも、これらの DMV を活用した方が、クエリの実行状態を細かに分析することができるケースがあります。
本投稿では sys.dm_exec_requests を使用したクエリの実行状況の取得について見ていきたいと思います。
クエリストアとの違い
最初にクエリストアと sys.dm_exec_requests の違いを考えてみます。
クエリストアは過去に遡ってクエリの実行状況を確認することができますが、クエリの実行状態の統計については「統計の収集間隔」(デフォルトは 1 時間) の設定に依存することになります。 
この統計の収集間隔の中で、「最大」「最小」「平均」「標準偏差」という観点で、クエリの実行結果を確認することが可能となっています。
例として、14:03 に、あるクエリの実行状況に異変が発生したとします。
このクエリは 14:00～14:59 の期間に実行されたクエリの中に含まれる情報となるため、14:03 時点の情報を確認することはできません。
収集間隔の中で、複数回の異変の発生と通常の実行状況が混在した場合、「最大」で見ることである程度の推測ができる可能性もありますが、平均として平準化されてしまうケースも考えられます。
また、クエリの情報が集約されるのはクエリが完了したタイミングとなりますので「時間のかかるクエリの実行中のリソースの使用状況の動き」を確認するということはクエリストアでは難しいです。
sys.dm_exec_requests は「DMV 参照時点の実行中のクエリの情報」となります。
クエリの実行に時間がかかっている場合は、この DMV を複数回参照することで、クエリ実行時のリソースの使用状況を詳細に確認することができます。
例としては次のようなクエリを実行します。
(SQL Server 2019 をターゲットとして作成したクエリのため、それ以外のバージョンについては、使用できない項目を削除することで実行できるかと)
SET NOCOUNT ON;
SET TRANSACTION ISOLATION LEVEL READ UNCOMMITTED;
DECLARE @collect_date datetime2(3) = SYSUTCDATETIME()
SELECT
@collect_date AS collect_date,
es.session_id,
DB_NAME(er.database_id) AS database_name,
@@SERVERNAME AS server_name,
CONVERT(varchar(30), er.query_hash, 1) AS query_hash,
CONVERT(varchar(30), er.query_plan_hash, 1) AS query_plan_hash,
er.blocking_session_id,
es.host_name,
es.program_name,
es.login_name,
es.status,
er.command,
er.wait_type,
er.last_wait_type,
er.wait_time, -- msec
er.wait_resource,
DATEADD(hour, -9, es.login_time) as login_time,
DATEADD(hour, -9, er.start_time) as start_time,
DATEADD(hour, -9, es.last_request_start_time) as last_request_start_time,
DATEADD(hour, -9, es.last_request_end_time) as last_request_end_time,
er.percent_complete,
er.estimated_completion_time,
er.total_elapsed_time,
er.cpu_time,
er.reads,
er.writes,
er.logical_reads,
er.row_count,
er.granted_query_memory,
er.dop,
er_text.text,
er.is_resumable,
er.page_server_reads
FROM
sys.dm_exec_requests AS er
INNER JOIN sys.dm_exec_sessions AS es WITH (NOLOCK)
ON
es.session_id = er.session_id
INNER JOIN (SELECT * FROM sys.dm_exec_connections WITH (NOLOCK) WHERE most_recent_sql_handle <> 0x0) AS ec
ON
es.session_id = ec.session_id
AND es.session_id <> @@SPID
AND es.program_name <> 'TdService'
AND es.is_user_process = 1
OUTER APPLY sys.dm_exec_sql_text(er.sql_handle) AS er_text
OUTER APPLY sys.dm_exec_sql_text(ec.most_recent_sql_handle) AS ec_text
OUTER APPLY sys.dm_exec_query_plan(er.plan_handle) as er_plan
WHERE
er.total_elapsed_time >= 100
ORDER BY
total_elapsed_time DESC,
cpu_time DESC,
session_id ASC
OPTION (RECOMPILE);
このクエリは、DMV を参照したタイミングで 100ms 以上、実行に時間がかかっているクエリの情報を取得するものとなります。
実際に実行を行うと次のような情報を確認することができます。
この情報から、
- 実行中のクエリでどのような待ち事象が発生していたか
- 実行していたクエリで CPU の使用率 / I/O の発生状況がどのようになっていたか
を確認することができます。
sys.dm_exec_requests の情報を連続して取得し、情報が確認できるようにすることで、クエリストアでは確認できない、特定のクエリについて指定した時間内のリソース使用状況を時系列で確認するということができるようになります。
実行するクエリについては、上記のクエリですが、データの格納先については「自分がデータの操作をしやすいデータストア」に格納をすればよいかと思います。
取得の間隔ですが、できれば 1 秒間隔程度の間隔で情報を取得しておきたいですね。
情報取得用のクエリは、大量のデータを取得するのでないのであれば、シンプルなクエリにしておけば、ハードウェアリソースの消費は少ないです。
リソース消費量を抑えたクエリになっていれば、DB サーバーに1Batch/sec のクエリ実行が増えても負荷増はたかが知れていますので。
今回の投稿では Azure の Log Analytics に HTTP データコレクター API を使用してデータを格納しています。
どこに情報を格納するかは「データの利用者が、分析がしやすいデータソース」であれば、どこでもよいと思いますので、「どこにデータを格納するか」は正解はないかと。
SQL Server のテーブルにデータを格納したいのであれば、上記のクエリの実行結果を 「INSERT INTO SELECT ～」で定期的に格納すれば問題はありません。
(情報の取得対象の SQL Server 自身に取得データを格納する場合は、その格納の情報自体がノイズにならないように意識しておく必要があります。
sys.dm_exec_requests の情報を実際に活用する
それでは、1 秒間隔で、上記のクエリの結果を Log Analytics に送信するようにし、時間のかかるクエリを実行してみます。
以下の積み重ねグラフは、クエリハッシュ単位で CPU 使用時間の最大値をプロットしたものとなります。
単一の棒グラフは「情報取得タイミングでどのクエリハッシュのクエリが CPU 使用時間が長かったか」を示しています。
今回のグラフであれば突出して面積を占めているクエリハッシュが存在していることが確認できますね。
面積が大きいクエリが、情報を取得したタイミングで CPU を使用していたクエリという判断をすることができます。
時間の経過とともに CPU 使用時間の面積も広くなっていますが、もし途中のタイミングで面積の変化がなくなってきている場合は、CPU リソース以外の要因で処理の進行が止まっているという判断につなげることができます。
上記のグラフから「どのクエリハッシュのクエリが CPU を使用しているか」がわかりましたので、グラフ化はせずにグリッドとして、該当のクエリハッシュの情報を確認してみます。
sys.dm_exec_requests には、リソースの使用状況を示す cpu_time や I/O 関連の情報も含まれています。
これを短い期間でダンプすることで、どのようにリソースを使用しているかについても確認することができます。
今回取得した情報であれば、次の情報に着目してみます。
下に向かって、情報取得タイミングが後の時間となっています。
total_elapsed_time の変化に合わせて、
- SOS_SCHEDULER_YIELD
- PAGEIO_LATCH_SH
の待ち事象が発生し、cpu_time や reads の値が上昇していることが確認できます。
(SOS_SCHEDULER_YIELD は CPU の利用状況が高いタイミングで発生する待機事象であり、PAGEIOLATCH はディスクからメモリにデータを読み取る際の待ちとなります)
クエリストアを使用した場合は「実行が完了したタイミングで、合計としてどれだけのリソースを使用していたか」の情報の確認取りますが、sys.dm_exec_requests を連続してダンプすることで、このように「時間の経過に合わせて該当のクエリで発生していた待ち事象とクエリで使用されていたリソースの使用状況」を詳細に確認することができます。
クエリの情報を確認する際には、結果としてどれだけリソースを使用していたかではなく、時系列でどれだけのリソースを使用していたかの情報が、分析に必要となることがありますので、このような情報の取得は重要となります。
「情報を連続してダンプすることで、特定のクエリの変化点を見出す」ということはクエリの分析を行う際には強力なデータとなることがあります。
SQL Server 2016 以降での応用
DMV の情報を連続でダンプするというクエリの分析手法は、sys.dm_exec_requests 以外でも応用することができます。
SQL Server 2016 では、sys.dm_exec_session_wait_stats という DMV が追加されています。
この DMV はセッションで発生した待ち事象の状態が記録されているものであり、クエリの実行中に連続してダンプすることで、クエリで発生していた待ち事象を時系列で確認することができます。
取得の例としては次のようなクエリとなります。
SELECT
@collect_date AS collect_date,
ws.session_id,
er.command,
er.status,
DB_NAME(er.database_id) AS database_name,
@@SERVERNAME AS server_name,
CONVERT(varchar(30), er.query_hash, 1) AS query_hash,
CONVERT(varchar(30), er.query_plan_hash, 1) AS query_plan_hash,
DATEADD(hour, -9, er.start_time) as start_time,
er_text.text,
es.program_name,
es.host_name,
er.total_elapsed_time,
er.cpu_time,
er.reads,
er.logical_reads,
er.writes,
er.row_count,
ws.wait_type,
ws.waiting_tasks_count,
ws.wait_time_ms,
ws.max_wait_time_ms,
ws.signal_wait_time_ms
FROM
sys.dm_exec_session_wait_stats AS ws
INNER JOIN sys.dm_exec_requests AS er
ON er.session_id = ws.session_id
AND er.total_elapsed_time >= 100
INNER JOIN sys.dm_exec_sessions AS es
ON es.session_id = ws.session_id
AND es.is_user_process = 1
AND es.session_id <> @@SPID
AND es.program_name <> 'TdService'
AND es.is_user_process = 1
OUTER APPLY sys.dm_exec_sql_text(er.sql_handle) AS er_text
この情報を連続して取得すると、次のような形式に加工することができます。
この情報は「該当のセッションで発生していた待ち事象の時系列データ」となり明日。
クエリを実行する中でどのような待ち事象がどれだけ発生していたかを示したものとなり、この情報で高い待ち事象を解消することでクエリの処理効率を大きく改善することができる可能性があります。
この情報はグリッドだけでなく、積み重ねグラフや面グラフにしても活用できます。
全体で発生した待ち事象の中で、面積の多い待ち事象がクエリの実行効率を低下させている要因となると考えられます。
時系列データとすることで「どのタイミングでどのような待ち事象が発生し、それがどの程度クエリの実行効率を低下させているか」の分析の容易性が向上します。
SQL Server の DMV の情報は「クエリを実行したタイミングのスナップショットのデータ」を取得するものとなります。
特定の「面 (点)」 の情報が取得されていると言えるのではないでしょうか。
この面の情報を連続して取得して、必要な情報を時系列として「線」の情報とすることで、クエリの詳細な動きを見ることができるケースがあります。
DMV の情報を取得する際には、このような「連続してダンプ」することにより新たな情報として活用を行うという観点も意識しておくと、SQL Server の情報の解析の強力な武器となるのではないでしょうか。