Shoeisha Technology Media

EnterpriseZine(エンタープライズジン)

EnterpriseZine(エンタープライズジン)

テーマ別に探す

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

edited by DB Online   2014/04/11 00:00

 過去に担当した案件を漁っていて、「そういえば、こんなことあったなぁ」というものを見つけました。SQL Serverが稼働しているサーバーのCPU使用率が、なぜか定期的にスパイクするというものです。

案件の概要

 お客様はSQL Serverの稼働状況を監視するため、SQL Server AgentのジョブからDMVへのクエリを定期的に発行し、その結果をテキストファイルに保存していました。お客様曰く、「アプリケーションが稼働していないにもかかわらず、CPU使用率が定期的にスパイクしているので、犯人となりそうなのはこのSQL Server Agentのジョブぐらいしかいないと思う。」とのことでした。

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

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

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

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

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

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

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

図1 「ステップでジョブを開始」を怪しそうなものから順番に実行していく
▲図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使用率をスパイクさせているのかを特定するだけです。

※この続きは、会員の方のみお読みいただけます(登録無料)。


※この続きは、会員の方のみお読みいただけます(登録無料)。


著者プロフィール

バックナンバー

連載:マイクロソフト古賀啓一郎の「今月のケースファイル」

もっと読む

All contents copyright © 2007-2019 Shoeisha Co., Ltd. All rights reserved. ver.1.5