こんにちは。ECプラットフォーム部の廣瀬です。

弊社ではサービスの一部にSQL Serverを使用しています。今回は2020年度に発生していたSQL Serverに関連する障害について、調査から対策実施までの流れを紹介したいと思います。これまでも弊社テックブログにて、SQL Serverに関するトラブルシューティングをいくつか紹介してきました。

techblog.zozo.com techblog.zozo.com techblog.zozo.com

これらの記事と今回の記事の最大の相違点としては、「最後まで明確な原因の特定はできなかった」という点です。できる限り詳細な調査を実施しましたが、最後まで原因の特定には至りませんでした。そのような状況下において、どのようなフローで調査を実施し、最終的に障害が発生しない状況を作ることができたか紹介します。

SQL Server以外のデータストアを運用していて障害調査をすることがある方にも読んでいただけると幸いです。

障害の概要

弊社のサービスは、様々な要因でトラフィックが増大します。例えば、セールイベントや福袋発売イベントなどです。2020年の中頃から、ある機能を担っていたDBにおいて秒間のバッチ実行数が一定の閾値を超えると、アプリケーション側でタイムアウトエラーが多発するようになりました。尚、バッチとはSQL Serverにおける1つ以上のクエリのかたまりを指します。

上の図では、タイムアウトエラーの多発開始と同時に、秒間のバッチ実行数が急激に下がりDBサーバーのクエリ処理性能が落ちていることが分かります。また、バッチの総実行時間が急激に増えていることから、1クエリあたりの実行時間が大幅に伸びていることも分かります。

この事象を詳細に調査していきました。調査に用いた情報は、以下の3点です。

弊社のSQL Server障害調査フロー

弊社では、SQL Serverに関する障害が発生した際、以下のフローチャートに沿って調査を進めています。

以降では、このフローに沿って実際に障害を調査した事例を紹介します。

調査内容

1. 主要なメトリクスを確認

パフォーマンスモニタで取得したメトリクスのうち、主要なものを確認しました。フローチャートの①に該当します。

CPU使用率はピーク時で100％に近い値となっていました。Batch Resp Statisticsを確認すると、CPU使用時間が20msecから100msecのバッチがCPU使用率上昇の主な要因となっていました。その他、目立った変化のあったグラフを以下に列挙します。

これらのグラフから、以下のことが読み取れます。

ブロッキングの発生が確認できた
SQL Server観点でもエラー発生が確認できた
待ち事象としては非ページラッチが障害発生の初期にスパイクしていた
バッチ実行数の増加に伴ってコンパイル数も増加していた
ワークスペースメモリを獲得したクエリの数が増大していた
ワーカースレッド獲得待ちが多く発生しており、ワーカースレッドが枯渇していた可能性が高い

これらの情報を見ただけでは、「何らかの理由でクエリが滞留し、最終的にワーカースレッドが枯渇してタイムアウトエラー多発につながった」ということしか分かりません。

クエリが滞留した理由としては、以下のようなものが考えられます。

CPU使用率が高騰したことでSOS_SCHEDULER_YIELD待ちが多発
非ページラッチの競合の発生
アクセスが集中する領域に長時間ロックがかかったことでブロッキングが多発

このような可能性に留意しつつ、エラーが起き始めた変化点にフォーカスし、より短い時間軸でメトリクスを確認しました。「エラーが起き始めたタイミングと同タイミングで変化し始めたメトリクス」が障害に関連している可能性が高いと考えたからです。

青い線がCPU使用率ですが、Attentionが発生したタイミングではCPU使用率が低下しているためCPU使用率が障害発生の原因とは考えにくい状況でした。エラー発生前後の最初の変化としては、まずPage Latchの発生が確認でき、次にNon-Page Latch、ブロッキングの順番で発生が確認できました。この結果から、Page Latch、Non-Page Latch、ブロッキングの発生は、エラーが発生し始めた要因と関連性がありそうです。

このような可能性に留意しつつ、保存しておいた拡張イベントとDMVの情報を後追いしていきました。

2. 拡張イベントでブロッキング状態を確認

こちらの方法で、「blocked_process_report」イベントをクエリベースで確認しました。フローチャートの②に該当します。

この結果から、以下のことが分かりました。

最初にブロッキングイベントが発生したのは、障害発生から15秒ほど経過した後
最初のブロッカーはbackgroundプロセスであり、自身も「ACCESS_METHODS_HOBT_VIRTUAL_ROOT」という種類のラッチで待たされていた

「ACCESS_METHODS_HOBT_VIRTUAL_ROOT」はドキュメントによると、「内部Bツリーのルートページの抽象化へのアクセスを同期するために使用されます」と説明してありました。ブロッキングイベントが発生したのは障害発生から15秒ほど経過してからでしたが、パフォーマンスモニタ上では障害発生前からわずかにブロッキングが発生していました。拡張イベントのブロッキングイベントは、「〇秒以上ブロッキングが続いたら発生」というように一定の閾値を超えたものだけが記録されるため、イベントが記録されるまでにタイムラグが発生していたようです。また、拡張イベントに記録された最初のブロッカーがどのような処理をしていたかは分からず、原因特定には至りませんでした。

3. DMVの各種データを使ってドリルダウン

フローチャートの③に該当します。

CPUのボトルネッククエリ調査

こちらの方法でCPUボトルネックとなっているクエリが無いかを調査しました。Batch Resp Statisticsの確認結果から、特にCPU使用時間が20msecから100msecのバッチを重点的に確認しました。しかし、今回はCPU負荷の観点でチューニングできそうなクエリは見つかりませんでした。

ラッチ

こちらのクエリを使って障害発生中の各種ラッチの待ち時間を確認しました。

ラッチによる総待機時間の大きい順に並べた結果、ACCESS_METHODS_ACCESSOR_CACHEが最も大きく、次いでBUFFER、ACCESS_METHODS_HOBT_VIRTUAL_ROOTという順番になりました。

ACCESS_METHODS_HOBT_VIRTUAL_ROOTについては、平均の待機時間が大きいようです。この待ちはページ分割時などに発生すると理解しており、特定のテーブルへのLast Page Insert多発が原因の可能性として挙げられます。その場合は、テーブルのキーの再設計などによって該当のラッチを減らせるかもしれないと考えました。

ACCESS_METHODS_ACCESSOR_CACHEについては、コンパイルの発生に伴って値が上昇する傾向にあるようです。したがってコンパイル回数の抑制によって該当のラッチ待ち時間を低減できる可能性があると考えました。

待ち事象

こちらのクエリを使って、障害発生中の待ち事象について確認しました。 THREADPOOLは二次的な待ちのため無視するとして、非ページラッチ、ページラッチ、ロックなどが待ち事象として多くを占めていました。

実施した対応策

時間をかけて調査しましたが、根本的な原因の特定には至りませんでした。したがって次善の策として、取得した情報を使って「障害発生中に観測できた事象の中から、無くしたり減らすことのできるものを探す」という観点で対応策を決めて実施していきました。

1. 特定のストアドプロシージャのプランガイドの固定化

別の日に同様の障害が発生した際、拡張イベントの「blocked_process_report」におけるwaitresourceごとのイベント件数を抽出してみました。その結果、特定のストアドプロシージャのコンパイル待ちが原因でブロッキングが発生していることが分かりました。

したがって、これら4つのストアドプロシージャのプランガイドを固定化することにしました。これは根本的な原因を特定したうえでの対応策ではありませんが、「もし同様の事象が発生しても、コンパイル起因でのブロッキングの発生を0にする」という効果が期待できます。

2. コンパイルとリコンパイル発生を抑制する施策

バッチ実行数の上昇に伴ってコンパイル数も上昇したことがパフォーマンスモニタのメトリクスから確認できていました。コンパイルやリコンパイルによって効率の悪い実行プランが採用されてしまい、CPU使用率が上昇した可能性も考えられます。したがって、コンパイルとリコンパイルの発生回数を抑制する対応を実施しました。コンパイルとリコンパイルの発生要因として代表的なものは、以下の2つです。

関連テーブルの統計情報が更新された
実行プランがキャッシュアウトされた

1.については、統計情報の更新が今回の環境におけるリコンパイルの理由として本当に正しいのかをまず検証しました。拡張イベントで「sql_statement_recompile」イベントを取得することで、リコンパイルの理由を確認できます。

拡張イベントの作成後、以下のようにリコンパイルイベントの発生が確認できました。

リコンパイルの理由は「recompile_cause」に記載されており、図の中では「Statistics changed」となっています。つまり、統計情報の更新がリコンパイルの理由だと分かります。

リコンパイルの各理由の内訳を確認するために「recompile_cause」でグループ化してみると、下図のようにリコンパイルの原因の大多数は統計情報の更新であることが確認できました。

したがって、障害発生時のリコンパイルについても統計情報の自動更新が起因となったものが大多数であるはずだと判断しました。次に、こちらのクエリを使って障害が発生した時間帯で「統計情報が1回以上更新されたテーブル」をリストアップしました。この情報をもとに、トラフィック増が見込まれる時間帯だけ、リストアップしたテーブル群の統計情報の自動更新を一時的に無効化するようにしました。統計情報の自動更新を無効化するには、以下のクエリを実行すればOKです。

UPDATE  STATISTICS tablename WITH NORECOMPUTE

これによって、統計情報の更新が起因となったリコンパイルの発生を抑止できます。しかし、自動更新を常に無効化しておくのは、最適な実行プランが生成されなくなる確率を上昇させる高リスクな行為です。したがって、トラフィックが落ち着いてきたタイミングで自動更新を再度有効化するようにしました。自動更新の有効化は、以下のクエリのように「WITH NORECOMPUTE」無しで統計情報を更新すればOKです。

UPDATE  STATISTICS tablename

2.のプランキャッシュアウトについては、SQL Serverがメモリの利用状況をコントロールしているため、こちらで制御できません。ベストエフォートな対応として、メモリに載っているデータキャッシュのうち、容量が大きいインデックスを圧縮することでメモリの利用効率アップを試みました。尚、メモリに載っているサイズが大きいインデックスを抽出するにはこちらのクエリを使用しました。

結果

各種対策を実施したことで、障害が発生しなくなりました。対策実施前と後での各メトリクスの変化を紹介します。

同程度のバッチ実行数の増加でも、クエリの滞留が起きなくなったため、対策実施後はコネクションの上昇が顕著に抑えられるようになりました。エラーが発生することもなくなり、明らかにパフォーマンスが改善しました。

CPU使用率はピーク時100％近くだったのを、ピーク時60％ほどまで抑えられるようになりました。

コンパイル数とリコンパイル数も顕著に発生回数を抑えられるようになりました。リコンパイルについては、統計情報の自動更新を一時的に無効化したことが顕著に効いています。コンパイルの発生回数が抑えられた要因については、仮説として「データ圧縮によりデータキャッシュのサイズが減少し、プランキャッシュが安定したことでキャッシュアウトしづらくなった」と考えられます。

対策実施前はクエリの総実行時間が障害時に大幅に増加していたのに対し、対策実施後は安定しました。トラフィック増により秒間のバッチ実行数が増えても、同時実行性が低下することなく、安定して処理できていることが分かります。

ロック競合の発生状況も大幅に改善しており、対策実施後は秒間のバッチ実行数が最大に達したタイミングでも、ロック競合は確認されませんでした。

このように、各種メトリクスに大幅な改善傾向がみられ、結果としてトラフィック増大時でも障害が発生しない状況をつくることができました。

まとめ

本記事では、2020年度に発生していたSQL Serverに関連する障害について、調査から対策実施までの流れを紹介しました。まずは特異な変化が起きているメトリクスを確認し、原因の仮説を立てながらDMVや拡張イベントを使ってドリルダウンしていきました。また、障害発生の前後数秒間で起きた変化を細かく見ていく調査も実施しました。いくつか障害原因の仮説は立てられたものの、特定にまでは至りませんでした。

こうした根本的な原因が特定できない状況において、「障害発生中に観測できた事象の中から、無くしたり減らすことのできるものを探す」という観点で対応策を決めて実施しました。その結果、最終的に障害が発生しない状況を作ることができました。原因が特定できない障害調査における対応策の実施について、今回紹介した考え方が参考になれば幸いです。