none
SQL Serverサービス再起動に伴う処理について RRS feed

  • 質問

  • SQL Serverにてプロシージャを使って処理を行っています。
    現状発生している問題は、本来プロシージャを実行して処理が完了するまでに
    平均で1~2秒ほどで完了するものが、日によっては10秒~30秒ほど
    かかってしまうことがあります。

    統計情報を更新しても早くなることもあればず遅いままのこともあり原因不明ですが、
    先日はSQL Serverサービスの再起動を行うと平常時のように早くなりました。
    この時は統計情報を更新していなかったので、統計情報なのか他の情報がクリアされたからなのか
    はっきり原因がわからない状態です。

    そこで質問となりますが、SQL Serverサービスを再起動すると
    キャッシュ以外でクリアされるような情報はありますか?
    もしくはそれ以外の要因などで考えられるものはありますでしょうか?

    漠然とした質問になりますが、どなたか情報を教えて頂けると幸いです。


    ◆各種情報
    【OS】Windows Server 2012(CPU8コア、メモリ16GB )
    【SQL Server】2012 Standard
    【プロシージャ処理内容】
      あるシステムの月末処理を行っており、それなりのコード量があるものです。
      各顧客毎でプロシージャを実行し、連続で1000回近く実行します。
      顧客ごとにそれぞれ別セッションで実行します。

    • 編集済み ぬつ 2018年6月15日 0:33
    2018年6月15日 0:28

回答

  • ぬつさん

    >うーん、OUTPUTパラメータに指定された引数の変更はしてますが
    >これもやめた方がいいんですかね。。。

    OUTPUTパラメータへの変更は問題ないと思います。ただ、もし

    select * from SomeTable where Column = @OutputParameter

    みたいに、OUTPUT指定しているパラメータをWHERE句に使う、みたいな使い方をしているとマズいかもしれません。(そもそもこういう使い方ができるのか分かりませんが、、)
    普通に set @OutputParameter = *** とか、プログラム側に返すための値をセットする分には全く問題ないはずです。

    >長時間待つときは、「SOS_SCHEDULER_YIELD」が表示されています。

    この待ち状態が頻繁に表示される場合は、CPUリソースを多く使うクエリプランになっています。サーバーのCPU使用率が高騰していませんでしょうか?もし100%近くに張り付いているとすると、そもそもSQLServer以外のプログラムがCPUリソースを使っていたり、SQLServer内でほかのクエリがCPUリソースを使いまくっていることで、クエリの実行が遅くなっている可能性もあります。

    でもサーバーのCPU使用率はそこまで高くなっていないのではと予想しています。

    個人的に一番可能性が高いと思っているのは、最適でない実行プランが生成されているケースです。そのためwith recompileをつけることで都度コンパイルされるので効果的かなと思った次第です。

    これ以上は実際に詳細な状況が分かりかねるため回答が難しいかもしれません。。

    今までの僕の見解をまとめますと、以下のようになります。

    ・いつもは速いクエリがSOS_SCHEDULER_YIELD待ちでずっと実行中のときは、最適なプランが選択されていない可能性が高い

    ・再起動 / dbcc freeproccacheで速くなるということは、パラメータスニッフィングで初回コンパイル時に非典型パラメータが渡されてコンパイルされた可能性が高い。そのためそれ以外のパラメータのときは遅いのでは

    ・with recompileをストアドにつけると、キャッシュに存在する実行プランは使われず、都度コンパイルされるため、dbcc reeproccacheと同様の効果があるはず。ただし、ぬつさんのお話をうかがうかぎりwith recompileでも遅い場合がある。この原因は謎い。

    ・実行プランまわりの問題であるとすると、遅くなったらdbcc freeproccacheを実行するようにプログラムを書き換える、というぬつさんの対応案もありだとおもいます。

    といったところです。がんばってください!

    • 回答としてマーク ぬつ 2018年6月21日 4:10
    2018年6月20日 7:40

すべての返信

  • ぬつさん

    実際の状況をみてみないと正直何ともいえないのですが、書いていただいている情報から可能性が高いシナリオを考えてみました。

    サーバー再起動によってクリアされるすべての情報を知っているわけではありませんが、
    今回のケースですと実行プランをキャッシュしているプランキャッシュが再起動によりクリアされたことが、再起動により速くなった原因かと思われます。

    また、日によって実行速度が違うということは、日によって異なる実行プランが生成されている可能性を疑っています。

    なぜ日によって異なる実行プランが生成されるかというと、クエリコンパイルの際に渡されたパラメータ値に最適な実行プランを生成しようとするため、そのパラメータ値次第でプランが変わることがあるからです。

    詳しくはこちらが参考になります。

    https://blogs.msdn.microsoft.com/jpsql/2011/02/16/dosdonts-3/

    僕のおすすめとしては、with recompile を該当プロシージャにつけることで、毎回実行時にコンパイルさせる、というのをお試しいただければと思います。
    やり方は以下の通り、with recompileとつければOKです。(上記URLからの抜粋)

    CREATE PROCEDURE p (@param1 int) WITH RECOMPILE
    AS
    SELECT …



    こちらをつけることによる懸念点としては、毎回コンパイルするのでその分CPUリソースを使ってしまいます。ただ、月末処理に使うような、ある期間でのみ使用するプロシージャとのことですので、そこまで問題はないかなと思っています。
    もし実際にwith recompileをつけてお試しいただく場合は、一応サーバーのCPUリソースを監視しながら実行してみてください。

    ---------------------------------------------------------------------

    参考になった投稿には回答としてマークいただけると嬉しいです!

    2018年6月15日 2:39
  • ご回答ありがとうございます。

    やはりキャッシュ絡みの可能性が高い気がしますよね

    一度リコンパイルを組み込んで様子を見てみます。

    2018年6月15日 8:31
  • 丁度遅くなったタイミングがあったので試してみました。

    結果的に(多分)効いています。

    時間経過で早くなったりするので正確じゃないかもしれませんが

    重くなってからプロシージャ本体と実行にリコンパイルを付けると

    当分何回か処理を実行してみて様子見は必要ですけど、早くなったので解決してそうです。

    有用な情報有難うございました!

    2018年6月15日 9:14
  • ぬつさん、解決してそうでよかったです!
    その場合、ぜひ回答としてマークしていただけると嬉しいです。
    2018年6月15日 10:31
  • 様子見でやってみました。

    残念ながらダメみたいですね。。。

    また処理が遅くなってたので処理をやらせてみましたが

    全く改善されておらず。

    またDB再起動することにより処理速度は元に戻っている状況でした。

    他の情報をクリアする必要がありそうですね。。

    2018年6月18日 0:28
  • ぬつさん


    だめでしたか、、

    再起動前後で何かが変わっているはずです。僕が考えつくのは

    A:再起動の前後で実行プランが変わる

    B:再起動の前後でサーバーリソースの占有状況が変わる

    の2つの可能性です。Aに関しては、with recompileをつけて都度コンパイルされるようにすれば解消されるはずです。(再起動により統計情報が更新されることは無いと思うので)

    ただし、下記の記事の内容は少し気になるので、ご一読してみて使用されているストアドに該当箇所があれば、修正を検討してみてはいかがでしょうか。

    ■DO’s&DONT’s #6: 絶対にやってはいけないこと – ストアドプロシージャ内でのパラメータ値の変更

    https://blogs.msdn.microsoft.com/jpsql/2011/03/25/dosdonts-6-1/

    こちらに該当しないか、ストアドプロシージャを確認してみてください。

    該当しない場合でも、遅い時と速い時で実行プランが変わっているかチェックしてみてください。

    また、Bに関しても気になっています。クエリが遅い時に、下記DVMクエリを実行してみてください。

    select top 100 der.session_id
    	,DB_NAME(der.database_id) as database_name
    	,des.host_name
    	,des.program_name
    	,der.status -- Status of the request. (background / running / runnable / sleeping / suspended)
    	,dest.text as command_text
    	,SUBSTRING(dest.text, der.statement_start_offset / 2, (case when der.statement_end_offset = - 1 then LEN(CONVERT(nvarchar(MAX), dest.text)) * 2 else der.statement_end_offset end - der.statement_start_offset) / 2) as current_running_stmt
    	,datediff(s, der.start_time, GETDATE()) as time_sec
    	,wait_resource --ロックされているリソース名
    	,last_wait_type --最後または現在の待機の種類の名前
    	,der.wait_time as wait_time_ms
    	,der.blocking_session_id
    	,der.open_transaction_count
    	,der.command
    	,der.percent_complete --一部コマンドの進捗状況を表示してくれるらしい
    	,der.cpu_time
    	,(case der.transaction_isolation_level when 0 then 'Unspecified' when 1 then 'ReadUncomitted' when 2 then 'ReadCommitted' when 3 then 'Repeatable' when 4 then 'Serializable' when 5 then 'Snapshot' else cast(der.transaction_isolation_level as varchar) end) as transaction_isolation_level
    	,der.granted_query_memory * 8 as granted_query_memory_kb --キロバイト単位
    	,deqp.query_plan -- 実行プラン
    from sys.dm_exec_requests der
    join sys.dm_exec_sessions des on des.session_id = der.session_id
    outer apply sys.dm_exec_sql_text(sql_handle) as dest
    outer apply sys.dm_exec_query_plan(plan_handle) as deqp
    where des.is_user_process = 1 and datediff(s, der.start_time, GETDATE()) >= 1 -- 例:1秒以上実行中のクエリに限定
    	and dest.text like '%%' -- クエリの中身でlike検索したいときはここを編集
    order by datediff(s, der.start_time, GETDATE()) desc
    

    このクエリは、サーバーで実行中のクエリリストを取得できます。

    これを実行すること、該当のストアドが実行中である様子が確認できると思います。

    確認できたら、下記手順で問題となっているlast_wait_typeを特定してみてください。

    1.クエリが実行中の場合は、last_wait_typeカラムをチェック。
    2.何度かクエリを実行し直してみて、last_wait_typeカラムがずっと同じ値のままであれば、そのwait_typeが原因でクエリの完了を待っているという判断を下す。
     → 1回のクエリ実行でさまざまな待ち状態が発生するのは普通のことなので、↑のクエリ実行のたびにlast_wait_typeが変化している場合は気にしなくてよい場合が多い。

    以上を調査のうえで、

    1.特定できたlast_wait_type

    2.遅い時と速い時で実行プランが違うかどうか

    の2点を教えていただければ、もう少し対応策を考えられるかもしれません。

    2018年6月19日 6:15
  • 更に詳しい情報ありがとうございます。

    こちらでも調査は進めていたところで、ひとまずそれらしい成果が見えてきているところでした。

    まさにご提案頂いている実行プランに関することで、

    「DBCC FREEPROCCACHE」により実行プランキャッシュがクリアされると

    早くなる可能性が高いです。

    詳しく実行プランを見る方法についてはご提示いただいた内容が目からうろこなものなので

    裏付け調査に使用させて頂きます。

    再度調査し、結果がまとまり次第ご報告させて頂きます。

    大変貴重な情報有難うございます。

    2018年6月19日 10:32
  • ぬつさん

    DBCC FREEPROCCACHEの実行で速くなる場合は、パラメータスニッフィングが関係している可能性がやはり考えられます。

    それだとwith recompileをつけたストアド実行でも同様の効果があるはずなのですが、、もしかするとストアド内でクエリ文字列を構築して、sp_executesql をつかって構築した動的クエリを実行しているストアドなのかな、、という気もします。

    調査いただいているとのことで、結果次第ではまた何かお役にたてるかもしれません。

    ご報告いただければ確認させていただきますね。調査がんばってください!

    2018年6月20日 1:30
  • まだ調査中ですが、一旦報告です。

    >■DO’s&DONT’s #6: 絶対にやってはいけないこと – ストアドプロシージャ内でのパラメータ値の変更
    うーん、OUTPUTパラメータに指定された引数の変更はしてますが
    これもやめた方がいいんですかね。。。
    プロシージャは、VB.netプログラムから呼び出す大元のプロシージャに加えて
    その大元から10以上のプロシージャを呼び出しており、
    各プロシージャに引き渡してエラー発生時の情報をパラメータにセットしているので
    若干手間がかかりそうです。
    そもそも戻り値なので、プロシージャ内SQL文に条件としては組み込んでおらず
    影響はなさそうですが。


    >1.特定できたlast_wait_type
    長時間待つときは、「SOS_SCHEDULER_YIELD」が表示されています。


    >2.遅い時と速い時で実行プランが違うかどうか
    遅いときは拾えるのですが、早いときは1秒以下で終わってしまって
    拾うのが難しい状態です。微妙にデータ量が多い顧客を対象に処理して
    拾えるかを試してみます。


    >それだとwith recompileをつけたストアド実行でも同様の効果があるはずなのですが、、
    そうなんですか。。。
    もしかするとたまたま早くなったタイミングで実行して勘違いしたのかもしれません。

    補足情報として、数万~数十万のデータを持つ顧客を処理(10分前後かかる)した後、
    その後に続く本来1秒以下とかで終わる顧客の処理が3秒前後~かかるようになることが確認が出来ています。
    ただし、処理を行ったいくつかの顧客情報を処理前に戻し(1・2秒程の処理)、
    すぐにまたそれらを月末処理を実行すると平常通りの速度に戻ることがあります。
    ※なぜか今日やってみると上記の通り処理速度が何もせずともすぐに戻りました。
     昨日は同じことをやっても戻らず、キャッシュクリアすると早くなってました(タイミング?)


    まだ難航する可能性が高いですが、VBアプリの処理側で、時間がかかるようになったら
    キャッシュクリアを実行するように組み込む予定です。
    それで早くなればいいんですが・・・


    • 編集済み ぬつ 2018年6月20日 4:43
    2018年6月20日 4:37
  • ぬつさん

    >うーん、OUTPUTパラメータに指定された引数の変更はしてますが
    >これもやめた方がいいんですかね。。。

    OUTPUTパラメータへの変更は問題ないと思います。ただ、もし

    select * from SomeTable where Column = @OutputParameter

    みたいに、OUTPUT指定しているパラメータをWHERE句に使う、みたいな使い方をしているとマズいかもしれません。(そもそもこういう使い方ができるのか分かりませんが、、)
    普通に set @OutputParameter = *** とか、プログラム側に返すための値をセットする分には全く問題ないはずです。

    >長時間待つときは、「SOS_SCHEDULER_YIELD」が表示されています。

    この待ち状態が頻繁に表示される場合は、CPUリソースを多く使うクエリプランになっています。サーバーのCPU使用率が高騰していませんでしょうか?もし100%近くに張り付いているとすると、そもそもSQLServer以外のプログラムがCPUリソースを使っていたり、SQLServer内でほかのクエリがCPUリソースを使いまくっていることで、クエリの実行が遅くなっている可能性もあります。

    でもサーバーのCPU使用率はそこまで高くなっていないのではと予想しています。

    個人的に一番可能性が高いと思っているのは、最適でない実行プランが生成されているケースです。そのためwith recompileをつけることで都度コンパイルされるので効果的かなと思った次第です。

    これ以上は実際に詳細な状況が分かりかねるため回答が難しいかもしれません。。

    今までの僕の見解をまとめますと、以下のようになります。

    ・いつもは速いクエリがSOS_SCHEDULER_YIELD待ちでずっと実行中のときは、最適なプランが選択されていない可能性が高い

    ・再起動 / dbcc freeproccacheで速くなるということは、パラメータスニッフィングで初回コンパイル時に非典型パラメータが渡されてコンパイルされた可能性が高い。そのためそれ以外のパラメータのときは遅いのでは

    ・with recompileをストアドにつけると、キャッシュに存在する実行プランは使われず、都度コンパイルされるため、dbcc reeproccacheと同様の効果があるはず。ただし、ぬつさんのお話をうかがうかぎりwith recompileでも遅い場合がある。この原因は謎い。

    ・実行プランまわりの問題であるとすると、遅くなったらdbcc freeproccacheを実行するようにプログラムを書き換える、というぬつさんの対応案もありだとおもいます。

    といったところです。がんばってください!

    • 回答としてマーク ぬつ 2018年6月21日 4:10
    2018年6月20日 7:40
  • 様々な情報のご提示ありがとうございます。

    残念ながらプログラム側にキャッシュクリア処理を追加しましたが変化は見られませんでした。。。

    大量データをもつ顧客処理の後に、連続で処理が投入されると処理速度が遅くなるようです。

    少し時間を置くと早くなることが多い状況です。

    OUTPUTパラメータについては、例で示して頂いたような使用の仕方はしていませんでした。

    CPUについては、お客様の本番サーバーに検証用DBを作って検証しているので日中帯処理も動いていますが

    月末処理を流してもタスクマネージャ上は全体CPU負荷率10~15%付近をうろついている感じです。(CPU8コア中4コアが使用されている様子)

    まだ調査は続けるのですが、処理が重い原因となっているプロシージャがあるので、そちらの処理を根本的に作り替えないといけないかもしれません。。。

    多大なご助力ありがとうございました。

    2018年6月20日 8:29