none
SQLServer2008R2でSQL SERVER AGENTサービスの停止に失敗する

    質問

  • お世話になります。

    オフラインバックアップ処理の為、毎日夜間にバッチファイルを使ったSQLサービスの停止起動を行っております。
    半年ほど異常なく動作しておりましたが、先日SQL SERVER AGENTサービスの停止に失敗しました。

    <システム環境>
    Windows Server 2008 R2
    SQL Server 2008 R2

    SQLログに以下の内容が記録されていました。
    -------------------------------------------------------------------------------------------
    05/09/2012 01:08:47,,Warning,[098] SQLServerAgent terminated (forcefully)
    05/09/2012 01:08:42,spid51,Unknown,FILESTREAM: effective level = 0<c/> configured level = 0<c/> file system access share name = 'MSSQLSERVER'.
    05/09/2012 01:08:42,spid51,Unknown,Configuration option 'Agent XPs' changed from 1 to 0. Run the RECONFIGURE statement to install.
    05/09/2012 01:08:36,,Error,[311] Thread 'JobInvocationEngine' (ID 4028) is still running
    05/09/2012 01:08:36,,Error,[240] 1 engine thread(s) failed to stop after 30 seconds of waiting
    05/09/2012 01:08:04,,Information,[131] SQLSERVERAGENT service stopping due to a stop request from a user<c/> process<c/> or the OS...
    -------------------------------------------------------------------------------------------

    [311] Thread 'JobInvocationEngine' (ID 4028) is still runningを元に検索し、以下の情報に辿り着きました。
    http://msdn.microsoft.com/en-us/library/aa937507%28v=sql.80%29.aspx

    内容を読む限り、サービスを停止する際にアクティブなスレッドが存在する場合は
    Agentがスレッドを強制終了させる動きをするようですが、
    スレッド終了処理がうまく行かない場合にこのメッセージが記録されるようです。(認識違いあればご指摘頂けると幸いです)

    サービスが停止できなかったのはこのことに起因していると推測しておりますが、
    1.Thread 'JobInvocationEngine'とはどのような働きをしているのでしょうか。
    2.Thread 'JobInvocationEngine'はなぜ終了されなかったのでしょうか。
    3.再発を防ぐにはどのような手立てが有効でしょうか。(ライブラリにあるレジストリ変更以外で)

    宜しくお願い致します。
    2012年5月12日 4:32

回答

  • このキーワードそのもののをご存じのプロの方がいらっしゃいましたら、
    一段階早く回答に行ける可能性がありますので、以下は、参考までに。

    これは文字通りJobではないのですか?

    スレッドがとかレジストリとかじゃなく、ジョブが実行されているからサービスを止められないと、
    英語をストレートに読んでみてはと思いました。

    SQL文の処理以外に、その停止しようとした時間帯に何かJobなど動作してないか、
    とか、そういう停止できない時間帯に実行されているものから推定しても結論に行ける気がします。

    どうでしょうか。

    という、最終ご質問内容にあった、キーワードだけから上記のように記載しましたが、質問の前提に含まれている、夜間バッチファイルという記載からもその可能性は高いと考えられます。

    もともと想定されていたジョブの実行時間よりも稼働が長くなったことで想定以上のジョブの実行時間になったのではないでしょうか。この仮定通りの問題なら、ジョブがきちんと終了したかどうか確認してからサービスの終了処理をすれば直る問題だと想定できます。

    2012年5月29日 6:15
  • 抜粋されているログを見る限り、SQL Server Agent サービス自体は正常に停止していて、特に失敗しているようには見えません。

    "1 engine thread(s) failed to stop after 30 seconds of waiting" は、文面からは、30 秒待ったけど停止しなかったスレッドが 1 つあるというだけで、SQL Server Agent サービスの停止に失敗した訳ではないと思います。

    実行中のジョブがあれば、当然そのジョブは中断されることになると思いますが、実際に実害が出ていないのであれば、特に対応も不要なのではないでしょうか。

    2012年6月4日 8:14
  • 正確には分かっていないですが、英語のログの文面から、読み取るべき対処法が違う気がしています。

    あとで、MKIIIさんも指摘されていますが、読み方ひとつ、またそれをみて対処するかしないかはその人次第です。
    mito5さんは、warning, errorに対処したいということで記載をすると。
    (エラーを見ても営業に実害がないから何もしないと判定する方は確かにいると思いますので。)

    以下、本論、

    私がもしこれを順に追えと言われたなら、

    05/09/2012 01:08:36,,Error,[311] Thread 'JobInvocationEngine' (ID 4028) is still running

    のこのJobInvocationEngine がなんなのか。
    ユーザーが設定したJobなのか、システムのJobなのか。

    (ID 4028)はユニークな番号なのか。動的に変わるものなのか。

    そのあたりだけまずは調べて、4028が終わるのには本来どれくらい時間がかかるのか。
    なぜ急に遅くなったか調べます。

    冒頭に書きました通り、特に問題を調べる気がないのなら、このジョブが必ず発生するということにして、
    ジョブが終わったタイミングを条件判定してそのタイミングでAgentを終了するようなバッチを組みなおすということをします。

    >詳しくないのですが、SQLAgentのジョブが存在する場合、
    >このジョブが実行されている最中にサービス停止しようとして失敗する、
    >ということはあり得るでしょうか。
    >アプリケーション依存と思われるジョブが数十分おきにスケジュールされています。

    私も詳しくはないですが、ジョブが存在というより、ジョブが実行中に、
    ユーザー操作によりAgentを終了という命令があったからと言って、実行を止めるようなシステムはそれはそれで怖いです。
    (本当におかしい処理をしているから強制終了という命令を出すというのはあると思うのですが。)
    例えば小売り店舗の一日の大きな締め作業のようなこと、あるかと思うのですが、これを夜間バッチで回すというような業務があるかと思います。
    それを、SQL Serverで処理しようと思ったら Agentなわけで、Agentを間違えて、[停止]と押してしまった人がいたら、
    バッチを途中でいきなり終わらせるということですよね。(途中で停止されても問題のないバッチを組んでいることって珍しいと思うのです。)

    ですので、SQL Serverとしては停止命令があったなら、以後の新規受け付けを停止して、現在実行中のジョブを処理してから、終了する。
    そういう動きをすることは妥当かと思います。

    >05/09/2012 01:08:47,,Warning,[098] SQLServerAgent terminated (forcefully)
    この最後のログですが、結局、強制終了した。ということですよね。強制終了してよかったのでしょうか。


    2012年6月6日 1:28

すべての返信

  • このキーワードそのもののをご存じのプロの方がいらっしゃいましたら、
    一段階早く回答に行ける可能性がありますので、以下は、参考までに。

    これは文字通りJobではないのですか?

    スレッドがとかレジストリとかじゃなく、ジョブが実行されているからサービスを止められないと、
    英語をストレートに読んでみてはと思いました。

    SQL文の処理以外に、その停止しようとした時間帯に何かJobなど動作してないか、
    とか、そういう停止できない時間帯に実行されているものから推定しても結論に行ける気がします。

    どうでしょうか。

    という、最終ご質問内容にあった、キーワードだけから上記のように記載しましたが、質問の前提に含まれている、夜間バッチファイルという記載からもその可能性は高いと考えられます。

    もともと想定されていたジョブの実行時間よりも稼働が長くなったことで想定以上のジョブの実行時間になったのではないでしょうか。この仮定通りの問題なら、ジョブがきちんと終了したかどうか確認してからサービスの終了処理をすれば直る問題だと想定できます。

    2012年5月29日 6:15
  • daisuky様
    情報提供頂きありがとうございます。

    バッチ処理の流れとしては以下の通りです。
     1.アプリケーションのインスタンスを停止
     2.アプリケーションのサービスを停止
     3.SQLのサービスを停止
    それ以外に意図的にスケジュールしているジョブなどはありません。
    アプリケーション側には特にエラーが無かったためSQLの動きを疑っております。

    詳しくないのですが、SQLAgentのジョブが存在する場合、
    このジョブが実行されている最中にサービス停止しようとして失敗する、
    ということはあり得るでしょうか。
    アプリケーション依存と思われるジョブが数十分おきにスケジュールされています。

    何か情報をお持ちの方がいらっしゃいましたらご教授頂けますでしょうか。
    宜しくお願い致します。

    2012年5月31日 10:06
  • 抜粋されているログを見る限り、SQL Server Agent サービス自体は正常に停止していて、特に失敗しているようには見えません。

    "1 engine thread(s) failed to stop after 30 seconds of waiting" は、文面からは、30 秒待ったけど停止しなかったスレッドが 1 つあるというだけで、SQL Server Agent サービスの停止に失敗した訳ではないと思います。

    実行中のジョブがあれば、当然そのジョブは中断されることになると思いますが、実際に実害が出ていないのであれば、特に対応も不要なのではないでしょうか。

    2012年6月4日 8:14
  • 正確には分かっていないですが、英語のログの文面から、読み取るべき対処法が違う気がしています。

    あとで、MKIIIさんも指摘されていますが、読み方ひとつ、またそれをみて対処するかしないかはその人次第です。
    mito5さんは、warning, errorに対処したいということで記載をすると。
    (エラーを見ても営業に実害がないから何もしないと判定する方は確かにいると思いますので。)

    以下、本論、

    私がもしこれを順に追えと言われたなら、

    05/09/2012 01:08:36,,Error,[311] Thread 'JobInvocationEngine' (ID 4028) is still running

    のこのJobInvocationEngine がなんなのか。
    ユーザーが設定したJobなのか、システムのJobなのか。

    (ID 4028)はユニークな番号なのか。動的に変わるものなのか。

    そのあたりだけまずは調べて、4028が終わるのには本来どれくらい時間がかかるのか。
    なぜ急に遅くなったか調べます。

    冒頭に書きました通り、特に問題を調べる気がないのなら、このジョブが必ず発生するということにして、
    ジョブが終わったタイミングを条件判定してそのタイミングでAgentを終了するようなバッチを組みなおすということをします。

    >詳しくないのですが、SQLAgentのジョブが存在する場合、
    >このジョブが実行されている最中にサービス停止しようとして失敗する、
    >ということはあり得るでしょうか。
    >アプリケーション依存と思われるジョブが数十分おきにスケジュールされています。

    私も詳しくはないですが、ジョブが存在というより、ジョブが実行中に、
    ユーザー操作によりAgentを終了という命令があったからと言って、実行を止めるようなシステムはそれはそれで怖いです。
    (本当におかしい処理をしているから強制終了という命令を出すというのはあると思うのですが。)
    例えば小売り店舗の一日の大きな締め作業のようなこと、あるかと思うのですが、これを夜間バッチで回すというような業務があるかと思います。
    それを、SQL Serverで処理しようと思ったら Agentなわけで、Agentを間違えて、[停止]と押してしまった人がいたら、
    バッチを途中でいきなり終わらせるということですよね。(途中で停止されても問題のないバッチを組んでいることって珍しいと思うのです。)

    ですので、SQL Serverとしては停止命令があったなら、以後の新規受け付けを停止して、現在実行中のジョブを処理してから、終了する。
    そういう動きをすることは妥当かと思います。

    >05/09/2012 01:08:47,,Warning,[098] SQLServerAgent terminated (forcefully)
    この最後のログですが、結局、強制終了した。ということですよね。強制終了してよかったのでしょうか。


    2012年6月6日 1:28
  • MKIII様、daisuky様

    情報頂きありがとうございます。
    確認・返信が遅れまして申し訳ありません。

    また説明不足で申し訳ありません。
    以下の通りログ上はSQLサービスを(強制)終了したとあったのですが
    実際は停止されていない状態だったと考えています。
    >05/09/2012 01:08:47,,Warning,[098] SQLServerAgent terminated (forcefully)
    理由としては以下です。
    ①SQLサービス停止→②DBバックアップ→③SQLサービス起動の順で夜間処理を回していますが、
    ③SQLサービス起動の際に、既にサービスが起動状態の為に失敗となっていました。

    実害という意味では、今回はそもそも開発者用のシステムだったので対応不要なのですが
    今後本番環境での発生を防止する為
    原因を究明したく、ご相談させて頂いておりました。

    ただしdaisuky様のおっしゃる通り
    サービス停止処理とAgentジョブ実行が被らない様にする、
    サービス起動に失敗したことを気付ける様にする、
    など回避するための手段は考えられますのでそちらを検討したいと思います。

    ありがとうございました。

    2012年6月11日 11:31