SQLServerのサーバサイドトレースを使ったボトルネッククエリ解析方法

トレース系を使う場面

SQLServer2012以降では非推奨のSQLServerProfilerやサーバサイドトレースですが、なんだかんだで使うケースはあります。

■ 開発環境で実行中のクエリをリアルタイムで見たいとき
GUIベースのSQLServerProfilerが楽。また、現在実行中クエリだけならDMVでもとれるけど、Profilerだと時系列で表示されるため分かりやすい。
※ただし本番環境での使用はやめた方がいいです。詳細はこちら

■ 本番環境のボトルネッククエリを徹底的に調査およびチューニングしたいとき
SQLServerのバージョンが2008 R2まではサーバサイドトレースがベストだと思います。
2012以降はほかにも便利な方法が複数提供されているため、理想的にはそちらを使ったほうが良いと思います。トレースは将来のバージョンで廃止予定らしいので。。とはいえ全然問題なく使える印象です。

トレースは負荷が高いといわれていますが、GUIベースのSQLServerProfilerよりはサーバサイドトレースの方がかなり軽量なようです。実際、CPU使用率が常時98-100%くらいの環境下で1時間程度トレースしても問題なくデータ採取できました。

↓まだサーバサイドトレースを公式に推奨していた時代の書籍では、Profilerよりサーバサイドトレースの方が低負荷だよ、という数値も載っています。

出典： http://amzn.asia/e7lhBoO

SQL Server Profiler / サーバサイドトレースの代替ツールとしてMSが推奨しているのが拡張イベントです。

サーバーへの負荷は
SQL Server Profiler >> サーバサイドトレース > 拡張イベント
の順番なので、拡張イベントが本番環境での取得には最も適しています。
ただし、サーバサイドトレースでもメトリクス数や条件を絞れば十分本番環境でも実施できます。

トレース手順

サーバサイドトレースを使った解析方法は下記手順で実施します。

1. トレーススクリプトを作成する

やり方はこの記事が分かりやすいです。

↓設定するプロパティはこんな感じ

--TextData
　クエリの内容

--Duration
　所要時間(マイクロ秒)

--StartTime
　開始時間

--Reads
　読み取り数（単位はおそらくページ）

--CPU
　使用したCPU時間(ミリ秒)
　基本的にはDuration > CPU時間。
　ただし、並列クエリの場合は、各プロセッサの合計値になるので、 CPU時間 > Duration となる場合もあり得る。

※Duration/CPUで保存してある単位が違うので注意

--EventSequence
　イベントの発生順に格納されている数値。StartTimeより精密に実行順序を判断できる

ポイントとして、採取するメトリクスには、最低でもSQL:BatchCompletedとRPC:Completedを含めたほうがいいです。
SQL:StmtCompletedなどはステートメント単位での実行時間など細かく採取できるのですが、コンパイル時間が含まれていないため特にアドホッククエリが大部分をしめるような環境下では正確な数値がとれません。まずはBatch/RPC単位でボトルネックを探した後、必要に応じてステートメント単位でさらにドリルダウンという流れが良いと思います

↓さらに、列フィルターの設定でCPUまたはDurationに最低でも「次の値以上」を「1」にセットしたほうがいいです。
※実行回数の解析にはDMV（sys.dm_exec_query_stats）が便利です。

フィルタセットしないとトレースデータ量が膨大になるのと、CPUやDurationが0のクエリはよっぽど大量に打たれていない限りボトルネックになり得ないためトレース対象から除外したほうが良いです。

2. トレーススクリプトを実行

対象サーバにリモートログインし、マネジメントスタジオからトレーススクリプトを実行します。
実行後は下記のクエリ達を使ってトレース一覧を見たり、トレースの停止や削除が行えます。
※デフォルトで常にトレースは1つ実行されていますので、自分でトレースを実行すると実行中トレースは2つになっているのが確認できるかと思います。

--トレース一覧
select * from ::fn_trace_getinfo(NULL)

--トレースの停止
sp_trace_setstatus <TraceID>, 0

--トレース定義の削除
sp_trace_setstatus <TraceID>, 2

※1-2時間程度採取すれば十分かと思います。

3. 保存されたtrcファイルをテーブルとしてDBに取り込む

DBに取り込めばあとはSQLで好きなように集計できます。取り込み先は開発環境が良いです。（トレース採取したDBと、トレースデータを取り込むDBが異なっていても問題ありません）

↓ profilerを立ち上げて、

↓ trcファイルをウインドウ上にもっていくと読み取りが開始されます

↓ trcファイルが複数存在する場合は「ロールオーバーファイルの選択」ウインドウが途中で出てくるので毎回「はい」を押します

↓ 読み込みが完了したら、テーブルに保存します。[ファイル]-[名前を付けて保存]-[トレーステーブル]

↓ 認証情報入力後、「キャプチャ先テーブル」ウインドウが出てくるので、好きなDBを選択後、適当に新規テーブル名を入力します

あとは画面左下に進捗率が表示されるので、インポート状況を確認できます。

4. 取り込んだデータを使って高負荷クエリを調査

↓たとえばざっくりとクエリの先頭20文字でgroup byして、総実行時間が長い順に並び替えるときのクエリです。

SELECT
   max(cast(TextData as varchar(max))) as textdata_sample
  ,sum(cpu) as cpu_sum
  ,avg(cpu) as cpu_avg --ミリ秒単位
  ,avg(reads) as reads_avg
  ,avg(cast(duration as float) / 1000.0) as duration_avg --ミリ秒単位
  ,count(*) as cnt
  ,(sum(cast(cpu as float)) / (select sum(cpu) from トレーステーブル名 WHERE EventClass in (10,12)) * 100) as 'cpu 全体に占める割合(%)'
  ,(sum(cast(duration as float)) / (select sum(cast(duration as float)) from トレーステーブル名 WHERE EventClass in (10,12)) * 100) as 'duration 全体に占める割合(%)'
  ,(cast(count(*) as float) / (select count(*) from トレーステーブル名 WHERE EventClass in (10,12)) * 100) as '実行回数 全体に占める割合(%)'
FROM
  トレーステーブル名 with(nolock)
WHERE
  EventClass in (10,12)
group by  SUBSTRING(TextData, 1, 20)
order by (sum(cast(duration as float)) / (select sum(cast(duration as float)) from トレーステーブル名 WHERE EventClass in (10,12)) * 100) desc

たぶん、(SQL:BatchCompleted(12) + RPC:Completed(10)) = (SQL:StmtCompleted(41) + SP:stmtcompleted(45) + コンパイル時間) っていう関係のはずなので、

バッチ、プロシージャ単位で集計したい場合は where EventClass in (10,12)
ステートメント単位で集計したい場合は where EventClass in (41,45)

をそれぞれ指定すればOKです。

・総実行時間を特に削減したい場合はdurationベースでorderby
・CPU負荷を下げたい場合はcpuベースでorderby
・ディスクIOを減らしたい場合はreadsでorderby

と、チューニングの際に注力したい項目に応じて並び替えると良いと思います。

※そもそもアドホッククエリ大量に打たせるなよ、という話ではあるのですが、もしお使いの環境下でアドホッククエリが大量に打たれている場合は、実はプリペアドステートメントにしてコンパイル時間カットするだけで劇的にCPU負荷を減らせることもあります。アドホッククエリ沢山な環境の方は是非一度お試しください。

※サーバサイドトレースでも、本番環境下での実行はサーバーのハングを招く恐れもあります。そのため実行は自己責任でお願いいたします。