SE の雑記

SQL Server ではコンパイル時間を確認する方法としては次のような方法があります。

• 実行プランの CompileTime / CompileCPU を確認する
• sys.query_store_plan の compile_duration を確認する
• SET STATISTICS TIME ON を実行して、実行時のコンパイル時間を確認する

これらの情報からクエリのコンパイルにかかった時間を確認することができるのですが、値を正しく把握しておかないとコンパイル時間についてミスリードをする可能性があります。

コンパイル時間とコンパイルの CPU 時間の関係を確認する

過去のクエリの実行状況を含めて、コンパイル時間を確認をしやすいのがクエリストアの sys.query_store_plan の情報となります。

SELECT
	*,
	T.query_plan.value('(//@CompileTime)[1]','int') AS CompileTime_ms,
	T.query_plan.value('(//@CompileCPU)[1]','int') AS CompileCPU_ms

FROM
(
	SELECT TOP 100
		query_id, plan_id, 
		CAST(avg_compile_duration / 1000 AS int) AS avg_compile_duration_ms, last_compile_duration / 1000 AS last_compile_duration_ms,
		CAST(query_plan AS xml) AS query_plan
	FROM sys.query_store_plan
	ORDER BY avg_compile_duration_ms DESC
) AS T

実際に取得した情報が以下となり、1,775 ms、コンパイルに時間がかかっているという情報となっています。

この情報だけで、該当のクエリがコンパイルに時間がかかっていると判断するとミスリードしている可能性があります。

上記のクエリではクエリプランから、CompileTime / CompileCPU の情報も出力を行っています。

クエリプランから取得した情報では、次のようになっています。

• CompileTime : 1,775 ms
• CompileCPU : 280 ms

「コンパイルにかかった時間」(CompileTime) はクエリストアの基本情報 (compile_duration) と同様に「1,775 ms」かかったことが確認できます。

しかし、「コンパイル時に使用された CPU 時間」(CompileCPU) については「280 ms」となっています。

実際に 1 秒程度コンパイルに時間がかかるクエリの生成方法としては、次のようなクエリを実行することで対応ができます。

SELECT
	*, 'INNER JOIN ' + QUOTENAME(DB_NAME()) + '.' + QUOTENAME(OBJECT_SCHEMA_NAME(object_id)) + '.' + QUOTENAME(OBJECT_NAME(object_id))  + ' ON ' + 
		QUOTENAME(DB_NAME()) + '.' + QUOTENAME(OBJECT_SCHEMA_NAME(object_id)) + '.' + QUOTENAME(OBJECT_NAME(object_id)) + '.' + QUOTENAME(name) + ' = #T1.C1' 
FROM
(
	SELECT 
		c.object_id,
		c.name , 
		ROW_NUMBER () OVER(PARTITION BY c.object_id ORDER BY c.object_id) AS row_num
	FROM sys.columns AS c
		INNER JOIN sys.tables AS t
		ON c.object_id = t.object_id
	WHERE system_type_id IN (56,127) AND OBJECT_SCHEMA_NAME(c.object_id) <> 'sys' AND t.type = 'U' AND t.is_memory_optimized = 0
) AS T
WHERE row_num = 1
ORDER BY name ASC
GO

CREATE TABLE #T1(C1 int)
GO
DBCC FREEPROCCACHE
SET STATISTICS TIME ON

SELECT * FROM #T1
<生成された JOIN 句を貼り付け>

このクエリを実行すると大量の JOIN が含まれたクエリが生成されるためクエリのコンパイルに時間がかかるクエリとなります。

以下が「SET STATISTICS TIME ON」の出力結果となりますが、コンパイルに 1.5 秒程度かかるクエリとなっていることが確認できます。

ここで確認しておきたいのが「CPU 時間」(CompileCPU) と「経過時間」(CompileTime) の関係です。

通常、コンパイルには CPU 使用時間が必要となるため、「CPU 時間 ≒ 経過時間」となります。

「1,531 ms ≒ 1,540 ms」となっているため、コンパイル時間相当の CPU 時間が使用されたことが確認できます。

しかし、前述のクエリストアの情報では、「280 ms < 1,775 ms」 となっており、コンパイルにかかった 1,775 ms の時間の中で実際に CPU が使用されていた時間は 280 ms となっています。

このような傾向になっているコンパイルは、該当のクエリが定常的にコンパイルに時間がかかっているのではなく次のような「CPU 使用時間が全体的に高かった状態でコンパイルが発生したため、CPU 使用時間の割り当て待ちでコンパイルに時間がかかったクエリ」となっている可能性があります。 (コンパイル や統計情報更新のロックのような論理的な競合が発生していた場合も、かい離が発生したように見えるケースがあります)

また、全体的な CPU 使用時間が高かった場合だけでなく、「統計情報の同期的更新が発生しコンパイルに時間がかかった」というケースも CPU 使用時間のミスリードとなりやすいケースです。このケースの場合、かい離が発生していることもあるのですが、それ以外にも CompileCPU/CompileTime が通常時より極端に高くなっていることがあります。このような場合も通常のコンパイルのコスト以外の要因がコンパイル時間に計上されている可能性を考慮する必要が出てきます。

経過時間と CPU 時間のかい離があっても、CPU 時間の値が高い場合には、プランガイドやクエリストアのプランの強制を行うことでコンパイル時間の負荷軽減につながる可能性がありますが、そうでない場合 (かい離があっても CPU 時間が低い) は、プラン固定化の作業を実施しても効果が低い可能性があります。

また、統計情報の更新起因でコンパイル時間が長くなっている場合は、統計情報の非同期更新の利用を検討してみる必要があります。

コンパイル時間に着目してチューニング対象を検討する場合、コンパイル時間だけでなく、コンパイルで使用された CPU 使用時間にも注目し、該当のクエリのコンパイルに CPU が占有されていたのか / 統計情報更新の影響を受けていないかどうかを意識して調査することが重要となるのではないでしょうか。