案件の概要
今回取り上げる話は、私が日本マイクロソフトに入社したばかりのころに担当した案件です。
内容は、SSISパッケージのパフォーマンスが急激に低下するというもの。入力データが400万件の時は数分で終わるのに、460万件になると急激におそくなり2.3時間もかかるというのです。遅延の原因究明と回避策を提示する必要がありました。
仮説と再現
この話を最初に聞いたとき、「ああ、460万件になってデータがメモリに乗り切らなくなったんだなぁ」と思いました。つまり、400万件の処理では、メモリが足りていたけれど、徐々に件数が増えてきて460万件となった時にデータが全部メモリに乗り切らなくなったのだと思いました。
私はこの仮説を証明するために、まずは再現環境を構築することから始めようと思いました。同じような現象が再現できれば、自分の手元で詳細な調査ができるし回避策の有効性も検証できると思ったからです。
再現環境を構築するためにいろいろとヒアリングしてみると、どうやらお客様は64ビットのマシンでSSISパッケージを32ビットモードで実行しているらしいことがわかりました。詳しい理由は覚えていませんが、確か64ビットモードで実行すると何か問題があって、32ビットモードだとその問題が発生しないとか、そんなことが理由だったと思います。問題のSSISパッケージはというと、複数のテキストファイルを読み込んでいろいろな加工をした後、マージ結合変換タスクを使用してデータを抽出し、最終的にSQL Serverへ一括登録するという内容でした。
一通りヒアリングを終えると、早速、再現環境の構築を行いました。お客様から入手したSSISパッケージを自分の環境でも動作するように変更します。2,3件のデータ入力で正しく動作することを確認し、続いてダミーの入力ファイルを生成するプログラムを書きました。460万件のデータを手作業で生成するのは大変だからです。プログラムを書き終えた後、まずは遅延が発生しないという400万件のデータで実行してみました。お客様の環境とは違って数分ではありませんでしたが、私の環境では十数分で終了します。
続いて460万件のデータで実行してみます。やはり、処理はなかなか終了しません。なかなか終了しないどころか、結局その日のうちに処理は終了しませんでした。あまりに遅いのでちょっと困ったなと思いましたが、ひとまずこれで「急激に遅くなる」という現象は再現できたようでした。
あとは、「460万件になってメモリに乗り切らなくなった」という仮説を証明するだけです。まず、遅延している箇所がSSISパッケージの処理なのか、それ以外の処理なのかを切り分けることにしました。パッケージの処理には、SQL Serverへ一括登録する処理もあるので、ひょっとしたらSSISパッケージの処理ではなく、SQL Server側の処理が遅延しているのかもしれません。
こうしたことを確認するため、現象が再現しているときのSSISパッケージの実行ログを確認することにしました。現象が再現しているときに実行ログの出力状況を確認すると、入力ファイルをいろいろと加工しているところまではスムーズにログが出力されるのですが、それらの処理がすべて終了してマージ結合変換タスクの処理に入るところから一向にログが出力されなくなります。どうやらマージ結合変換タスクの処理が遅延しているようだということがわかりました。マージ変換タスクはSQL Serverを使用していないので、SQL Server側の問題でないことがわかります。これで調査対象をSSISに絞ることができます。
