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

山崎 実久
SQL Engine Support Engineer

以前に、「DO's&DONT's #1: やらない方がいいこと – 運用環境で、Profiler GUI を使用してトレースする」、「SQL トレーススクリプトの作成、実行 (SQL Server 2000)」、「SQL トレーススクリプトの作成、実行 (SQL Server 2005, 2008, 2008 R2)」 というタイトルで、Profiler を利用したサーバートレースの採取方法について本 blog でご案内しました。

SQL Server 上で実行されたクエリが遅いなどの問題がある際、サーバートレースを採取し解析することで、問題のあるクエリを特定し、クエリの実行状況を確認することができます。問題のあるクエリを特定するため長期間サーバートレースを採取する場合、サーバートレースの出力ファイルサイズが数 GB と大きくなる場合があります。 採取したファイルを Profiler で開き確認することも可能ですが、非常に手間がかかります。そこで役立つのが、システム関数 fn_trace_gettable です。 システム関数 fn_trace_gettable を利用することで、サーバートレースの出力ファイルをテーブルに格納することができます。 格納したテーブルに対しクエリを実行し、ある程度調査対象のクエリを絞った上で、Profiler 上でトレースファイルを開き、該当のクエリの実行プランなどを確認することができます。

以下、サーバートレースで採取すべきトレースイベントの紹介も含め、fn_trace_gettable の利用方法をご案内します。

----------------------------------
a. クエリの実行状況を確認するために必要なトレースイベント
b. システム関数 fn_trace_gettable を利用しサーバートレースの出力ファイルをテーブルに格納
c. CPU Time の値が大きいクエリを検索
d. reads や writes の値が大きいクエリを検索
e. まとめ
----------------------------------

a. クエリの実行状況を確認するために必要なトレースイベント

SQL Server 上で実行されたクエリの開始と停止の状況を確認するために、以下のイベントを選択し、サーバートレースを採取します。
サーバートレースの採取方法については、「SQL トレーススクリプトの作成、実行 (SQL Server 2000)」、「SQL トレーススクリプトの作成、実行 (SQL Server 2005, 2008, 2008 R2)」 をご参照ください。

- エラーと警告
Attention
- パフォーマンス
ShowPlan Statistics Profile
ShowPlan XML Statistics Profile
- ストアド プロシージャ
RPC:Starting
RPC:Completed
SP:Starting
SP:Completed
SP:StmStarting
SP:StmtCompleted
- TSQL
SQL:BatchStarting
SQL:BatchCompleted
SQL:StmtStarting
SQL:StmtCompleted

+ 参考情報
SQL Server 2008 R2
SQL Server イベント クラスの参照

本blog
クエリタイムアウト - その仕組み

b. システム関数 fn_trace_gettable を利用しサーバートレースの出力ファイルをテーブルに格納

サーバートレースの出力ファイル (xxxx.trc) をテーブル (下記の例では、tracet) にインポートする場合、以下の例のようにクエリを実行します。
fn_trace_gettable の引数に指定している number_files の値が以下のクエリの例のように default の場合、連番の名前で出力された trc ファイル（例 xxx_1trc, xxx_2.trc, xxx_3.trc など）全てをテーブルに取り込む設定となります。
途中、連番が途切れている場合、途切れたところまでしか取り込まれませんので、注意が必要です。

(例)
--------------------------------------
use データベース名
go
select * into tracet from fn_trace_gettable ('C:\xxx.trc',default)
go
--------------------------------------
※SQL Server 2005、2008 , 2008 R2 では fn_trace_gettable を利用いただき、SQL Server 2000 では ::fn_trace_gettable を指定する必要があります。

+ 参考情報
SQL Server 2000
fn_trace_gettable

SQL Server 2008 R2
fn_trace_gettable (Transact-SQL)

(実行例)

 

c. CPU Time の値が大きいクエリを検索

b で作成したトレースのデータを含むテーブルに対し、以下の例のようにクエリを実行し、CPU Time の値が大きいクエリを特定します。

（例）
--------------------------------------
use データベース名
go
select ste.name,t.spid,t.TextData,t.duration,t.StartTime,t.EndTime,t.cpu,t.reads,t.writes from tracet t inner join sys.trace_events ste
on t.EventClass = ste.trace_event_id
where t.cpu >=0 order by t.cpu desc
--------------------------------------

(実行例)
以下の例では、CPU Time の値が大きい順に並べています。採取したトレースの中では、ストアドプロシージャ proc01 実行時の CPU Time が 32 ミリ秒と一番大きいことがわかります。
下記の cpu の単位はミリ秒、 duration の単位はマイクロ秒です。

- 参考情報
データ列を使用したイベントの説明

d. reads や writes の値が大きいクエリを検索

b で作成したトレースのデータを含むテーブルに対し、以下のようなクエリを実行し、Reads や Writes の値が大きいクエリを特定します。
Reads や Writes は、メモリ上の 8 KB からなるページの論理読み取りページ数、論理書き込みページ数を示しています。これらの値が大きいクエリは、ディスク I/O の負荷に関わるクエリの可能性があります。実際の物理読み取り数や、物理書き込み数は、パフォーマンスログや動的管理ビューから確認することができます。
該当のクエリについて、現象が発生していない状態で採取したログから、現象が発生していない場合の状態（reads や writes、クエリプラン）を確認後、現象発生時と比較し、クエリチューニングを行います。

（例）
--------------------------------------
use データベース名
go

select ste.name,t.spid,t.TextData,t.duration,t.StartTime,t.EndTime,t.cpu,t.reads,t.writes from tracet t inner join sys.trace_events ste
on t.EventClass = ste.trace_event_id where t.Reads >=0 order by t.Reads desc, t.Writes desc --------------------------------------

(実行例)
下記例では、Reads および Writes の値が大きい順に並べています。採取したトレースの中では、ストアドプロシージャ proc01 実行時の Reads および Writes の値が一番大きいことがわかります。
Reads および Writes の値の単位はページ となります（1 ページ は 8KB です）。

まとめ

上記を利用し、サーバーの CPU 負荷が高い時や、Disk I/O の負荷が高い時、SQL Server の処理に起因している問題か否か確認することができます。パフォーマンスログとサーバートレースの結果を照らし合わせて確認する方法は、第5回 サーバートレースの解析方法 2 でご紹介します。

サーバー負荷がある時の、CPU Time の値が大きいクエリや、Reads および Writes の値が大きいクエリを特定し、クエリの実行プランをサーバーの負荷のない場合と比較することで、問題のあるクエリのチューニングを行うこともできます。

 

★ SQL Server トラブルシューティング 6 回シリーズのご案内 ★ 本記事は、第 4 回目となります。他の記事は以下をご参照ください。 https://blogs.msdn.com/b/jpsql/archive/2012/03/30/sql-server-6.aspx 第1回 SQL Server のログ、イベントログの確認方法 (03/30 UP) 第2回 パフォーマンスログの採取方法 (04/20 UP) 第3回 パフォーマンスログの確認方法 (05/07 UP) 第4回 サーバートレースの解析方法 1 (★ 05/18 UP 本記事) 第5回 サーバートレースの解析方法 2 (02/18 UP) 第6回 ブロッキング情報の確認方法 (07/24 UP)