案件の概要
このバッチ処理というのは、もともと処理に5～6時間を要するバッチだったようで、お客様は金曜の夜に実行しておいて月曜日にその処理結果を確認しようとしたらしいのです。ところが、月曜日になっても処理は終了しておらず、処理経過をみても一向に終わりそうな気配がありません。5～6時間が7時間ぐらいになる程度ならまだ許容範囲ですが、さすがこれは時間がかかりすぎているということで調査を依頼されました。
遅延の原因を探る
再実行すればひょっとしたら実行プランが変化して問題が解決するのではないか、とお客様も何度か試したようなのですが、まったく解決する気配はなく、何度やっても同じでした。SQLのパフォーマンスは実行プランに大きく影響されます。実行プランは統計情報によって変わるので、統計情報を更新してからの再実行も試しましたが、それも効果がありませんでした。
一通り話を聞いてから、とりあえず現象が発生している状況をのぞかせてもらいました。本番稼働前ということで、まだ色々と触れられる環境だったのです。情報採取も好きにやって良いということで、問題のバッチ処理が流れている時にSQLトレースやDMVなどを確認しました。
ところが、SQL文や実行プランを詳細に確認しても遅延している様子がうかがえません。ブロッキングも発生していません。何しろサーバーで実行中の処理というのは問題のバッチ処理だけなのです。サーバー リソースも占有できるにもかかわらず、処理が遅いのです。問題のバッチ処理はカーソルを使用して大量のデータを更新していたので、この遅延はカーソルのループが原因なのかなとも考えましたが、はっきりとしたことは分かりませんでした。
CPU使用率が定期的にスパイクしている点が少し気になりましたが、使用率100%で張り付いているわけでもなく、ボトルネックになっているとは言えません。そもそも、実行プランの何らかのオペレータで負荷が上がっているような場合、それはパフォーマンス情報付きの実行プランやSQLトレースから状況が確認できるはずです。
CPU負荷が遅延の原因と因果関係があるのかは不明でしたが、どう考えてもこの遅延具合は異常です。私は心の中で「こりゃ、バグってんなぁ。」とつぶやきました。
現場でひととおり状況を確認した後、これ以上は詳細なデバッグ調査が必要だということをお客様へ伝えました。お客様の環境でSQL Serverのデバッグをするのは大変なので、自分の環境で再現できるよう、バッチプログラム一式とそれを動作させるために必要なテーブル定義をもらいました。現場で確認した具合だと、自分の環境でも比較的容易に再現できるだろうという見込みがあったのです。
バッチ処理の仕様については詳しくはわかりませんでしたが、テーブル構造やプログラムなどからある程度仕様を推測し、テーブルデータを用意してバッチ処理が動くように環境を整えました。お客様と同じ数百万件のデータを用意して、バッチ処理を実行します。テーブルの更新具合からバッチ処理の進捗状況を確認すると、どうやらそれほどパフォーマンスは悪くないようです。この処理スピードなら、5～6時間で処理が終了してしまいそうです。最初は「あれ、再現しないのかなぁ」と思っていました。
ところが、20～30分たったころでしょうか。改めて進捗状況を確認すると期待したほど処理が進んでいないのです。処理スピードを確認すると、バッチ処理を開始した直後と現在の処理スピードが極端に違っています。どうやら、バッチ処理が進むにつれて処理スピードが低下しているようなのです。
