[SQL Troubleshooting] 第5回 サーバートレースの解析方法 – (2)

福原 宗稚
SQL Server Support Engineer

第4回 サーバートレースの解析方法 – (1) では、サーバートレースの出力をテーブルに格納し、CPU Time の値が大きいクエリや、reads や writes の値が大きいクエリを、簡単に見つける方法をご案内しました。今回は、さらにサーバートレースとパフォーマンスログの結果を簡単に関連付けて確認する方法をご紹介します。

例えば、CPU 使用率の値が大きいクエリやreads や writes の値が大きいクエリがあったが、その時サーバー全体として負荷は高かったのか、逆に CPU 使用率が高い時間帯があったが、その時どのようなクエリが実行されていたのかということを SQL Server Profiler を使用して確認できます。

※ Books Online では、下記のトピックとしてご紹介しています。

トレースと Windows パフォーマンス ログ データの関連付け (SQL Server Profiler) 

a. サーバートレースとパフォーマンスログの準備

必要な情報は、サーバートレースとパフォーマンスログです。

サーバートレースの採取方法、採取するイベントは、第4回 サーバートレースの解析方法 – (1) をご参照ください。

パフォーマンスログの採取方法は、第2回 パフォーマンスログの採取方法 をご参照ください。また、下記のカウンタを採取します。

• Memory
• Physical Disk
• Process
• Processor
• SQL Server: Buffer Manager
• SQL Server: Memory Manager
• System

※ 実際の調査時に取得するカウンタは、第3回 パフォーマンスログの確認方法 を参照し、ご検討ください。

b. サーバートレースとパフォーマンスログの関連付け

SQL Server Profiler で、サーバートレースとパフォーマンスログを開き、関連付けます。

1) SQL Server Profiler を起動し、 [ファイル] – [開く] – [トレース ファイル] から、採取したサーバートレース (trc ファイル) を開きます。

2) [ファイル] – [パフォーマンス データのインポート] から、採取したパフォーマンスログ (blg ファイル、csv ファイル) を開きます。

3) [パフォーマンス カウンター制限ダイアログ ボックス] で、表示させたいカウンタを選択します。 

4) 画面上部にトレースが、画面下部にパフォーマンスログが表示されます。 

c. サーバートレースからの確認

確認したいクエリをトレース部分で選択します。

例えば、reads が高かったクエリ「exec proc1」 に関して、実行されていた時間帯のパフォーマンスを確認してみます。

1) 該当のサーバートレースの行を選択します。

2) するとパフォーマンスログが連動して、その時刻が赤い線で示されます。「exec proc1」 実行開始直後から、青色の線で示された Avg. Disk Queue Length 等のディスクの負荷を示す指標が他の時間帯と比べて高い値を示しており、ディスクがボトルネックとなっていた可能性が推測できます。

d. パフォーマンスログからの確認

確認したい時間帯のパフォーマンスログを選択します。

例えば、CPU 使用率が 100% に達して非常に負荷が高かった時間帯があったため、その時間帯にどのようなクエリが実行されていたかを確認してみます。

1) パフォーマンスログ部分で、緑色の線で示された %Processor Time の値が高い時間帯を選択します。

2) すると、その時間帯で実行されていたクエリの行がトレースで選択されます。

この行の前後を確認することで、該当の時間帯でどのようなクエリが実行されていたのかを特定できます。複数のクエリが実行されている場合、トレース部分で CPU 列に着目し、この値が特に大きいクエリが CPU 使用率を押し上げていると判断できます。

e. まとめ

SQL Server Profiler で実行されていたクエリを、Performance Monitor でパフォーマンスを、それぞれ別々に確認することはできますが、SQL Server Profiler 上で関連付けて表示させることで、より簡単に調査対象のタイミングのクエリ、パフォーマンスの関係性を確認することができます。是非ご活用ください。