none
プロファイラのイベントクラス(Audit Logout)について RRS feed

  • 質問

  • お世話になっております。
    海老原と申します。

    日々遅くなっているストアドがあり(10ヶ月で5秒遅延)プロファイラを取得しました。
    ※テンプレート:SQL Profiler TSQL_Sps(Duration,stmtCompletedを追加)

    Durationの値はstmtCompleted,stmtCompleted共に40を超える値は無かったのですが、
    Audit LogoutイベントのDurationは1000~3000と非常に大きな値となっていました。

    「Audit Logout」が大きな値となる原因はどういった事が考えられますでしょうか?

    以上

    2009年2月25日 10:01

回答

  • こんにちは、naginoです。

    バージョンが記載されていませんので、SQL Server 2008 という前提で以下記載します。

    Audit Logout が大きな値となる原因は単純で、その接続の接続時間が長い場合です。
    個々のクエリごとの時間ではなく、トータルの時間(概算)です。
    接続して 3 秒間何も処理をせずに切断したとしたら、3000 と記録されます。
    あるいは 30 ミリ秒の処理を 100 回繰り返し実行していても 3000 と記録されます。

    詳細は以下に記載されています。
    http://msdn.microsoft.com/ja-jp/library/ms175827.aspx

    なお、蛇足ながらボトルネックの調査であれば、残念ですが Audit Logout はあまり参考にはなりません。

    ご参考になれば幸いです。

    MCITP(Database Developer/Database Administrator)
    2009年2月25日 10:53
  •  テスト環境においても、 本番環境と同じく physical_io:18165、memUsage:32485 ぐらいの値になっていますでしょうか。
    (32485 * 8k = 253MB 使用されていますね。)

    TempDB に対する Insert に時間が掛かっているのであれば(本番環境とテスト環境との差異はこれのみ)、TempDB への I/O 周りをチェックしたほうが良いような気がします。
    TempDBへのI/O が増えた場合、パフォーマンスが低下する可能性がございます。

    一般的な TempDB のチューニングは、以下が有効であると言われています。

    1) TempDB の物理ファイル、トランザクションログファイルを、システムドライブ、その他データベースファイルが配置されているドライブ以外に配置
    2) TempDB の初期サイズを増やす。(頻繁に拡張が繰り返されている場合、有効)
    3) TempDB の物理ファイルを分割する。(ndf ファイルを作成)
    ※ これはちょっと一般的ではないかもしれませんが、例えば CPUが4つあるマシンの場合、TempDB の物理ファイルを4つに分割することにより、TempDBを使用する処理(ソート、一時テーブルなど)のパフォーマンスの向上が期待できます。
    出来れば、すべて違うドライブに配置することが望ましいのですが、同じドライブでも効果は期待できます。

    [参考情報]
    tempdb のパフォーマンスの最適化
    << http://technet.microsoft.com/ja-jp/library/ms175527(SQL.90).aspx >>

    tempdb に使用するディスク領域の計画
    << http://technet.microsoft.com/ja-jp/library/ms345368(SQL.90).aspx >>


    2009年2月26日 10:34

すべての返信

  • こんにちは、naginoです。

    バージョンが記載されていませんので、SQL Server 2008 という前提で以下記載します。

    Audit Logout が大きな値となる原因は単純で、その接続の接続時間が長い場合です。
    個々のクエリごとの時間ではなく、トータルの時間(概算)です。
    接続して 3 秒間何も処理をせずに切断したとしたら、3000 と記録されます。
    あるいは 30 ミリ秒の処理を 100 回繰り返し実行していても 3000 と記録されます。

    詳細は以下に記載されています。
    http://msdn.microsoft.com/ja-jp/library/ms175827.aspx

    なお、蛇足ながらボトルネックの調査であれば、残念ですが Audit Logout はあまり参考にはなりません。

    ご参考になれば幸いです。

    MCITP(Database Developer/Database Administrator)
    2009年2月25日 10:53
  • ストアドプロシージャの処理が遅延する処理についてですが、OSを再起動後は、現象は改善されますか?
    2009年2月25日 12:25
  • 申し訳ございません。

    バージョンは下記でございます。

    OS:Windows2003 SP2
    DB:SQLServer2000 SP4

    再起動を行ってもストアドの処理速度遅延が改善されず、苦慮しておりプロファイラを取得
    した次第です。。。

    ご指摘のMSDNを確認させていただきました。Audit Logoutは参考にならない事が分かりました。
    ありがとうございました。

    今一度プロファイラの結果を解析してみます。

    2009年2月25日 14:43
  • OS再起動後も現象が改善されないのであれば、コネクションプールの問題の可能性が低くなりましたね。

    ただ、SQL Server エンジン内の処理が 全て 40 ミリ秒未満で終了しているのであれば、詳しい本環境の構成は分からないのですが、データベース - クライアント間、もしくは、 データベース - アプリケーションサーバー 間、もしくは アプリケーションに問題がある可能性が考えられます。

    尚、この手の問題を解決するには、一般的に非常に時間と手間が掛かります。

    あとSQL Server マシン上で採取して有効な情報は、ストアドプロシージャ実行時に sysprocesses 情報を複数回採取して、その際の WaitTypeを確認することでしょうか。

    [例]

    select * from sysprocesses
    where spid > 50


    ちなみに、ストアドプロシージャの処理が遅延とありますが、実際の問題としては、アプリケーション上から処理を実行後、その結果セットが返ってくる時間が掛かるという現象が発生しておりますでしょうか。

    上記が正しい場合、まずは処理が遅いとされるアプリケーションの各関数のどの部分にて時間が掛かっているかを把握後、BIDとレース、パケットキャプチャを採取し、アプリケーション - データベース間の処理の流れを調査する事になります。

    SQL Server 2005 でのデータ アクセスのトレース
    << http://msdn.microsoft.com/ja-jp/library/aa964124(SQL.90).aspx >>

    少しでもお役に立てれば良いのですが。
    2009年2月25日 16:31
  • 本スレとは多少ずれてしまい申し訳ないですが。。。

    select * from sysprocesses where spid > 50
    →を複数回試してみました。
     WaitTypeはどのプロセスも「0x0000」でした。
     が、今回問題となっているストアドを呼び出しているEXEでphysical_io:18165、memUsage:32485
     となっていました。

     また、プロファイラを再度取得し、解析した所、動的SQLを使用してtempDbにInsertをかけている複数の
     ステートメントの処理時間がそれぞれ1秒を超えており、そこに問題があるかと考えています。
     がしかし、テスト環境に本番データを復元し、試してみても本処理は全て合わせても1秒にも満たないのです。
     
     やはり「physical_io:18165、memUsage:32485」が怪しいのでしょうか?


    2009年2月26日 7:41
  •  テスト環境においても、 本番環境と同じく physical_io:18165、memUsage:32485 ぐらいの値になっていますでしょうか。
    (32485 * 8k = 253MB 使用されていますね。)

    TempDB に対する Insert に時間が掛かっているのであれば(本番環境とテスト環境との差異はこれのみ)、TempDB への I/O 周りをチェックしたほうが良いような気がします。
    TempDBへのI/O が増えた場合、パフォーマンスが低下する可能性がございます。

    一般的な TempDB のチューニングは、以下が有効であると言われています。

    1) TempDB の物理ファイル、トランザクションログファイルを、システムドライブ、その他データベースファイルが配置されているドライブ以外に配置
    2) TempDB の初期サイズを増やす。(頻繁に拡張が繰り返されている場合、有効)
    3) TempDB の物理ファイルを分割する。(ndf ファイルを作成)
    ※ これはちょっと一般的ではないかもしれませんが、例えば CPUが4つあるマシンの場合、TempDB の物理ファイルを4つに分割することにより、TempDBを使用する処理(ソート、一時テーブルなど)のパフォーマンスの向上が期待できます。
    出来れば、すべて違うドライブに配置することが望ましいのですが、同じドライブでも効果は期待できます。

    [参考情報]
    tempdb のパフォーマンスの最適化
    << http://technet.microsoft.com/ja-jp/library/ms175527(SQL.90).aspx >>

    tempdb に使用するディスク領域の計画
    << http://technet.microsoft.com/ja-jp/library/ms345368(SQL.90).aspx >>


    2009年2月26日 10:34
  •  NOBTAさんのご指摘を参考にさせて頂き、TempDBのチューニングを来週してみます。
     ※本番環境がしばらく物理的(距離的)に触れなくなってしまったので、作業が来週になってしまいます。。。

    また結果報告いたします。
    2009年2月26日 15:46
  • プロファイラの結果の再検証をしまして、極端に処理の遅いプロシージャが存在しましたのでそちらを改善し
    処理時間の短縮を図る事が出来ました。(許容値となりました。)

    ですが、よく分からないのが上記のプロシージャをテスト環境(データも同じ)で動作させても遅くなく、やはり
    TempDBのチューニングは必要だと思いますので、そちらはまた後日行う予定です。
    ※TempDbのチューニングについてはTempDBの初期サイズを増やすことは行いました。

    NOBTA様 nagino様 ご助言ありがとうございました。

     

     

    2009年3月11日 8:05