「あるタイミングから」処理が遅くなり、再起動しても再現されてしまう（パフォーマンストラブル）：SQL Serverトラブルシューティング（50）（1/2 ページ）

本連載は、「Microsoft SQL Server」で発生するトラブルを「どんな方法で」「どのように」解決していくか、正しい対処のためのノウハウを紹介します。今回は、「あるタイミングで処理遅延が発生し、それが継続して発生するようになってしまった場合の対処例」を解説します。

[内ヶ島暢之，ユニアデックス株式会社]

連載バックナンバー

　本連載では、「Microsoft SQL Server（以下、SQL Server）」で発生するトラブルについて、「なぜ起こったか」の理由とともに具体的な対処方法を紹介していきます。

トラブル 37（カテゴリー：処理遅延）：「あるタイミングから」処理が遅くなった

目次

• トラブルの実例
• トラブルの原因
• 解決方法

　「Windows Server 2012 R2」上に「SQL Server 2016 RTM」をインストールした環境を想定して解説します。

トラブルの実例：運用するECサイトのシステムで、ある日、急にアプリケーションの処理遅延が発生。顧客ユーザーによると、アクセスが「あるところから進まなくなった」という。

　データベースサーバの再起動を行ったが、遅いまま状況は変わらない。売上に大きな影響が出るために「早期解決」が望まれている。

トラブルの原因を探る

　前回は「不定期に発生するトラブル」でしたが、今回は「あるときに急に発生し、それが継続してしまう」トラブルの事例です。

　顧客ユーザーからのクレーム内容とアプリケーションチームの分析から、以下のことが分かりました。

• 処理遅延が発生しているアプリケーションは複数ある。しかし、全てではない
• アプリケーションでは、SQL Serverからの処理待ちが多くを占めているようである
• アプリケーションの新規リリースなどは、ここ1週間行っていない

　併せてデータベースチーム側では「データベースサーバのリソースとエラーログを確認」しました。しかし、問題のあるボトルネック発生などの要因は確認されませんでした。また、データベースサーバを再起動しても処理遅延状況が再現されることから、一時的な問題ではありません。

　これらを確認した後で次に取る対処は、「SQL Server Profiler」を使って、追加資料となる「トレースを確認」することです。稼働している本番システムのトレースを取得することで、別の遅延が発生する可能性はあります。しかし、このまま待っていても状況は何も変わりません。今回は顧客と「トラブル解消のために、時間を限定して実行する方針」を合意した上で、トレースの取得に踏み切ることにしました。

　トレースは、「SQL:StmtCompleted」イベントを採取します（図1）。

図1　遅延発生時のトレースログを「SQL Server Profiler」で確認。Duraiton列に「SQLの実行時間」が記録される

　SQL:StmtCompletedは「SQL文の終了」を示す値で、SQL Server ProfilerのDuraiton列に「SQLの実行時間」が記録されます。図1では、あるSQL文が「123733」ミリ秒、つまり約2分も実行に時間を要していたことが分かりました。

　遅いSQLを特定できたので、今度はその実行プランがどうなっているかを確認します。今回はSQL Server Profilerから直接プランを確認できました（図2）。なお、遅いSQLを突き止められたならば、アプリケーションから処理を再実行して確かめなくとも、「SSMS（SQL Server Management Studio）」でも現象を再現できます。

図2　遅いSQLの実行プランに含まれるオペレーターから特徴的なものを抜き出した

　確認できた図2の情報から、該当するSQLでは「SQL Serverのクエリオプティマイザーが推定した行数」と「実際の実行時に操作された行数」が大きく異なっていることが分かりました。

　このことから今回のトラブルは、「統計情報に問題があった」ことが原因であることを突き止められました。統計情報が実際のテーブルの実態を反映していなければ、作られる実行プランが非効率的になり、結果として遅延が発生します。また、実行プランはプランキャッシュに格納され、以降、同じ処理が呼び出されるたびに使い回されます。そして、SQL Serverを再起動したとしても同じ統計情報からプランが作られるので、やはりこのトラブルは再発してしまうのです。

目次に戻る