CPU使用率が高い？―謎のスパイクを追え！

犯人のプロセスは特定、しかし…

　SQL Server Agentジョブの定義を頂いたので、早速自分の環境でも同じ現象が発生するかどうか環境を構築してみました。採取するDMVごとにジョブが定義されており、その実行間隔はまちまちです。それぞれのジョブが実行を開始されるのを待って、パフォーマンスカウンターを観察してみました。

　すると、しばらくしてからCPU使用率を表すパフォーマンスカウンターの値が跳ね上がりました。なんとも、あっさりと現象が再現したのです。この時に観察していたパフォーマンスカウンターはサーバーのCPU使用率を表すものでしたので、今度はどのプロセスがこのスパイクを引き起こしているのかを、プロセス単位のパフォーマンスカウンターで観察してみることにしました。スパイクする時はユーザーモードのCPU使用率が高いことを確認していたからです。今の時点で怪しいのは、SQL Serverのプロセスか、SQL Server Agentのプロセスのどちらかですから、観察するのはこの2つのプロセスに絞りました。

　パフォーマンスカウンターをセットして、スパイクを引き起こす何らかのジョブが実行されるのを待ちます。どれほどの間隔だったかは記憶が定かではありませんが、しばらくしてから、やっぱりまたスパイクしました。跳ね上がったカウンターは、SQL Serve Agentのプロセスです。

　これで犯人のプロセスは特定できました。しかし、SQL Server Agentの何の処理がスパイクを引き起こしているのか、また、どのジョブが実行されたときに発生するのかがわかっていませんでしたので、これらのいずれかを調査しようと考えました。

　まぁ、どちらから手を付けてもよかったとは思うのですが、どのジョブが引き起こしているのかを特定してしまえば、SQL Server Agentを調査する時にいちいちジョブのスケジュール実行を待たずに済むだろうと思い、まずは犯人のジョブを特定することにしました。

　お客様は、結構な数のDMVデータを採取していたので、ジョブは数十個あったと思います。これまでの状況から、なんとなくサイズの大きいデータを返すようなクエリが実行されていると問題になりそうだなぁと思っていたので、ジョブの定義をざっと眺めてから怪しそうなものを順に手動で実行していきました。

▲図1 「ステップでジョブを開始」を怪しそうなものから順番に実行していく

　すると、以下のクエリを発行するジョブが実行されるタイミングでスパイクが発生することがわかりました。実行時間の長いSQLを抽出するためのクエリです。

SET TEXTSIZE 327680

SELECT TOP 50
	r.session_id, 
	status,
	qt.dbid, 
	qt.objectid, 
	blocking_session_id,
	r.wait_type,
	r.wait_time,
	r.last_wait_type,
	r.wait_resource,
	r.total_elapsed_time,
	r.cpu_time,
	r.reads, 
	r.writes,
	r.logical_reads,
	r.scheduler_id,
	r.plan_handle,
	convert(text, SUBSTRING (qt.text,r.statement_start_offset/2, (case when r.statement_end_offset = -1 then len(convert(nvarchar(max), qt.text)) * 2 else r.statement_end_offset end - r.statement_start_offset)/2)) AS query_text
FROM sys.dm_exec_requests r
CROSS APPLY sys.dm_exec_sql_text(sql_handle) AS qt
WHERE r.session_id > 50
ORDER BY r.total_elapsed_time DESC

 これで、手軽に現象を再現させることができるようになりました。後はSQL Server Agentのどういった処理がCPU使用率をスパイクさせているのかを特定するだけです。