none
第4回 サーバートレースの解析方法 – (1) RRS feed

  • 質問

  • 山崎 実久
    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)

    (実行例)

     fn_trace_gettablwe


    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
    の単位はマイクロ秒です。

    cpu02

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


    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 です)。

    ReadsWrites01


    まとめ

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

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

     

    SQL Server トラブルシューティング 6 回シリーズのご案内

    本記事は、第 4 回目となります。他の記事は以下をご参照ください。

    https://social.technet.microsoft.com/Forums/ja-JP/79a8e9fe-8490-41aa-ba25-ca010efe5a82/sql-server-6-?forum=jpbidp

    第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)

     


    2019年4月8日 3:49
    所有者