SE の雑記

SQL Server の情報をメインに Microsoft 製品の勉強内容を日々投稿

SQL Server / SQL Database パフォーマンスチューニング & トラブルシューティング シリーズ : sys.dm_exec_query_stats を使用したキャッシュされたクエリの分析 その 1

leave a comment

SQL Server と Azure SQL Database (Single Database (Elastic Pool) / Managed Instance / Hyperscale) でパフォーマンスチューニングやトラブルシューティングに利用できる情報を、本投稿のタイトルのシリーズでまとめていきたいと思います。

今回は「sys.dm_exec_query_stats」について紹介します。

SQL Server では、RECOMPILE ヒントoptimize for ad hoc workloads オプションを設定していない場合は、クエリのキャッシュ領域の枯渇やクエリキャッシュからのキャッシュアウトが発生していないのであれば、クエリの実行プランをキャッシュするクエリキャッシュの領域に実行プランや実行時の実行統計の情報がキャッシュされています。

このクエリのキャッシュ情報を確認するために参照するのが、「sys.dm_exec_query_stats」とう DMV (動的管理ビュー) です。

この DMV を参照することで、「キャッシュされているクエリの情報」を確認することができます。

SQL Server 2016 で クエリストア が実装されるまでは、この DMV または 関連する DMV と 拡張イベント を使用して情報を確認することが一般的な方法でした。

クエリストアが実装された以降のバージョンでも sys.dm_exec_query_stats を使用する方法は、トラブルのケースによっては活用することができ、バージョン / 設定に依存せずに活用できる方法として今日も使用することがあります。

sys.dm_exec_query_stats で取得できる情報とは?

それでは、この DMV ではどのような情報が取得できるでしょうか?

シンプルな取得方法としては次のようなクエリの実行となります。

SELECT 
       qs.plan_handle,
       qs.sql_handle,
       qs.query_hash,
       qs.query_plan_hash,
       qt.text,
       SUBSTRING(qt.text, qs.statement_start_offset / 2 + 1, 
       (CASE
            WHEN qs.statement_end_offset = -1
            THEN LEN(CONVERT(nvarchar(max), qt.text)) * 2
            ELSE qs.statement_end_offset
        END - qs.statement_start_offset) / 2) AS query_text, 
       qp.query_plan, 
       qs.creation_time, 
       qs.last_execution_time, 
       qs.plan_generation_num, 
       qs.execution_count, 
       qs.total_elapsed_time, 
       qs.total_worker_time, 
       qs.total_logical_reads, 
       qs.total_physical_reads, 
       qs.total_logical_writes
FROM sys.dm_exec_query_stats AS qs
     CROSS APPLY sys.dm_exec_sql_text(sql_handle) AS qt
     CROSS APPLY sys.dm_exec_query_plan(plan_handle) AS qp
WHERE qt.text LIKE '%/* TPC_H Query 1 - */%'
ORDER BY last_execution_time DESC
OPTION(RECOMPILE);

 

image

sys.dm_exec_query_stats では、キャッシュされているクエリから、

  • クエリのテキスト
  • クエリの実行プラン
  • 実行プランが作成された日時
  • 実行プランの最終実行日時
  • 実行プランの世代
  • 実行回数
  • クエリの実行時間
  • リソース (CPU / メモリ上のデータ参照 / ディスク上のデータ参照) の使用状況
  • クエリ / 実行プランのハッシュ
  • クエリ / 実行プランのハンドル

というような情報を取得することができます。

キャッシュされている情報ですが、最低限、次の特徴は把握しておくとよいかと思います。

  1. クエリはステートメント単位でキャッシュされる
  2. キャッシュされているプランにはコンパイル時のパラメーターが含まれている
  3. クエリの実行が完了した際に実行統計の情報が記録される
  4. 再コンパイル (リコンパイル) された場合は、再コンパイル以降の情報がキャッシュされる
  5. CPU 使用時間にはコンパイル時間は含まれない

 

クエリはステートメント単位でキャッシュされる


現在の SQL Server はクエリは「バッチ内のステートメント単位」でキャッシュが構築されます。

例としては次のようなクエリを実行したとします。

/* TPC_H Query 1 - */
SELECT L_RETURNFLAG, L_LINESTATUS, SUM(L_QUANTITY) AS SUM_QTY,
 SUM(L_EXTENDEDPRICE) AS SUM_BASE_PRICE, SUM(L_EXTENDEDPRICE*(1-L_DISCOUNT)) AS SUM_DISC_PRICE,
 SUM(L_EXTENDEDPRICE*(1-L_DISCOUNT)*(1+L_TAX)) AS SUM_CHARGE, AVG(L_QUANTITY) AS AVG_QTY,
 AVG(L_EXTENDEDPRICE) AS AVG_PRICE, AVG(L_DISCOUNT) AS AVG_DISC, COUNT(*) AS COUNT_ORDER
FROM LINEITEM2
WHERE L_SHIPDATE <= dateadd(dd, -90, cast('1998-12-01' as datetime))
GROUP BY L_RETURNFLAG, L_LINESTATUS
ORDER BY L_RETURNFLAG,L_LINESTATUS

/* TPC_H Query 2 - Minimum Cost Supplier */
SELECT TOP 100 S_ACCTBAL, S_NAME, N_NAME, P_PARTKEY, P_MFGR, S_ADDRESS, S_PHONE, S_COMMENT
FROM PART, SUPPLIER, PARTSUPP, NATION, REGION
WHERE P_PARTKEY = PS_PARTKEY AND S_SUPPKEY = PS_SUPPKEY AND P_SIZE = 15 AND
P_TYPE LIKE '%%BRASS' AND S_NATIONKEY = N_NATIONKEY AND N_REGIONKEY = R_REGIONKEY AND
R_NAME = 'EUROPE' AND
PS_SUPPLYCOST = (SELECT MIN(PS_SUPPLYCOST) FROM PARTSUPP, SUPPLIER, NATION, REGION
 WHERE P_PARTKEY = PS_PARTKEY AND S_SUPPKEY = PS_SUPPKEY
 AND S_NATIONKEY = N_NATIONKEY AND N_REGIONKEY = R_REGIONKEY AND R_NAME = 'EUROPE')
ORDER BY S_ACCTBAL DESC, N_NAME, S_NAME, P_PARTKEY

 

TPC-H の Q1 と Q2 の 「2 つのステートメント」を「1 つのバッチ」として実行していることになります。

このようなクエリ実行の場合は、Q1 と Q2 の各ステートメント単位でキャッシュの情報が生成されています。

image

一つのバッチ内で複数のステートメントを実行しているため、同一の plan_handle / sql_handle のクエリの情報となっており、text や、query_plan を確認した場合も同一の情報となっています。

しかし、query_hash や query_plan_hash は異なっています。

text の情報はバッチの全体を表しており、各行には「バッチ内のどのステートメントなのかを表すオフセット (位置情報)」も含まれていますので、text をオフセットで分割することで、ステートメントの情報を抽出することができるようになっています。

クエリの再コンパイルについてもステートメント単位で実施されますので、バッチが複数のステートメントで構成されている場合は、ステートメントによって再コンパイルの状況が変わってきます。

実際にバッチ内の一つのステートメントのみで再コンパイルを発生させるようにした時の情報がこちらになります。

image

「plan_generation_num」が実行プランの世代を表したものとなります。

バッチ内の全てのステートメントの実行プランの世代が進んでいるのではなく、バッチ内で再コンパイルが発生したステートメントのみ実行プランの世代が進んでいることが確認できます。

このように、実行プランの情報は、「ステートメント単位」でキャッシュが行われています。

 

キャッシュされているプランにはコンパイル時のパラメーターが含まれている


キャッシュの情報からは、「クエリの実行プラン」が含まれています。

この実行プランは「コンパイル時に指定されたパラメーター」についても含まれています。

例として、次のようなクエリを実行してみます。

DECLARE @sql nvarchar(max) = N'
SELECT L_RETURNFLAG, L_LINESTATUS, SUM(L_QUANTITY) AS SUM_QTY,
 SUM(L_EXTENDEDPRICE) AS SUM_BASE_PRICE, SUM(L_EXTENDEDPRICE*(1-L_DISCOUNT)) AS SUM_DISC_PRICE,
 SUM(L_EXTENDEDPRICE*(1-L_DISCOUNT)*(1+L_TAX)) AS SUM_CHARGE, AVG(L_QUANTITY) AS AVG_QTY,
 AVG(L_EXTENDEDPRICE) AS AVG_PRICE, AVG(L_DISCOUNT) AS AVG_DISC, COUNT(*) AS COUNT_ORDER
FROM LINEITEM2
WHERE L_SHIPDATE <= dateadd(dd, -90, @date)
GROUP BY L_RETURNFLAG, L_LINESTATUS
ORDER BY L_RETURNFLAG,L_LINESTATUS
'
EXEC sp_executesql @sql, N'@date date', @date = '1998-12-01'

 

このクエリは「パラメーター化クエリ」として実行しているため、コンパイルが発生したタイミングで指定されたパラメーターによって実行プランの生成が行われます。

このような動作は「パラメーター スニッフィング」と呼ばれ、コンパイル時に指定されたパラメーターによって実行プランが生成されますので、すべてのパラメーターで効率的な実行プランではない可能性があります。

クエリの実行効率が突然低下した場合は「どのようなパラメーターでコンパイルされたクエリが使用されているのか?」は、問題を分析するためには重要な情報です。

キャッシュされている実行プランには、「パラメーターリスト (ParameterList)」という情報が含まれており、この情報を確認することでコンパイル時にどのような値によって生成された実行プランなのかを確認することができます。

image

クエリの実行効率が低下した場合は、このパラメーターリストの情報は再現性を確認するうえで重要な情報となります。

 

クエリの実行が完了した際に実行統計の情報が記録される


クエリのキャッシュ情報については、「クエリの実行が完了した際に記録される」ことになります。

コマンドタイムアウト等でクエリの実行が完了しなかった場合、該当のクエリの情報はキャッシュに載ってきませんので、クエリのタイムアウトについては Attention イベント等を活用して情報の取得を行う必要があります。

 

再コンパイル (リコンパイル) された場合は、再コンパイル以降の情報がキャッシュされる


plan_generation_num が 1 より大きい場合は、ステートメントが再コンパイルされたクエリであると判断することができます。

image

新しい実行プランが生成された場合、クエリキャッシュの実行統計は現在の実行プランで集計された値となります。

creation_time は、plan_generation_num = 1 のプランが生成されたタイミングを示すのではなく、現在の plan_generation_num が生成されたタイミングを示すことになります。

また、total_elapsed_time 等の実行時間や total_logical_reads 等のリソースの使用状況を示す項目についても、現在の実行プランの情報に初期化されており、以前の実行プランからの累計値にはなっていません。

クエリキャッシュから実行時間や累計時間を調査する場合は、

  • どの期間 / どの実行プランについてのリソース使用状況の集計値なのか?

は意識して確認をしておくことも重要です。

 

CPU 使用時間にはコンパイル時間は含まれない


sys.dm_exec_query_stats に記載されていますが、CPU 使用時間を表す total_worker_time には、クエリのコンパイル時間は含まれていません。

(実行時間を示す total_elapsed_time にもコンパイル時間は含まれていません)

total_worker_time

bigint

コンパイル後にプランの実行で使用された CPU 時間の合計 (マイクロ秒単位)。ただし、精度はミリ秒単位までです。

複雑なクエリの場合、コンパイルに時間かかることもありますが、コンパイルの時間はキャッシュには含まれていませんので「どのような時間がキャッシュから判断できる時間に含まれているか?」を意識しておくことも重要です。

sys.dm_exec_query_stats の情報の分析方法については、まだまだポイントがありますので、その他のポイントについては次回以降で記載したいと思います。

Share

Written by Masayuki.Ozawa

5月 3rd, 2020 at 7:59 pm

Leave a Reply