PLAIDEngineer Blog
エンジニア積極採用中

高トラフィックな分散システムのSLO改善事例

Rui Hakamata

Posted on

はじめに

KARTEでは、秒間10万を超えるトラフィックを支えるシステム運用を行っています。私たちのチームでは、この分散システムの健全性を保つため、日常的にバーンレートやバーンダウンチャートを含むSLOのモニタリングを行っています。

その運用の中で、一部のSLOにおいて将来的にブリーチが発生する可能性があると判断し、今回、SLOの改善と目標値の引き上げを実施することにしました。本記事では、その過程で直面した3つの主要な問題と、それらに対する解決アプローチについて紹介します。

改善対象のシステムとSLOについて

改善対象となったシステムの詳細や SLO の具体的なしきい値については、基本的に非公開となるのですが、問題ない範囲で公開します。

今回改善を行ったSLOは、受信したリクエストが一定時間内に正しく完了する割合を示す指標です。

処理の流れは以下の通りになります。

  • 外部からのリクエストを受信するサーバ（以下：RequestReceiver）がリクエストを受け取る
  • RequestReceiver は受信したリクエストをデータベースに書き込む
  • RequestReceiver は、単位キーごとにまとめて処理を行うサーバ（以下：BatchProcessor）に対して処理リクエストを送信する
  • BatchProcessor は、データベースから該当キーに紐づく直近のリクエスト履歴を取得し、集約処理を実行する
  • RequestReceiver は処理結果が確定するまでポーリングで待機する
  • 一定時間以内に対応する処理結果が取得できた場合を成功、取得できなかった場合を失敗とする

補足:

  • RequestReceiverとBatchProcessorはGCPのMIG(Managed Instance Group)で動作しています。
  • RequestReceiverが単位キーのリクエストを複数のインスタンスで受け付けることを考慮して、単位キーあたりでバッチ処理を行っています。

解消した問題

問題1: RequestReceiver → BatchProcessor間で503, 504が定期的に大量に発生

秒間十万を超えるリクエストをKARTEでは受け付けており、時折数万件を超える503, 504エラーが発生していました。

調査のアプローチ

RequestReceiver から BatchProcessor へのアクセスは GCP の Load Balancer を経由しています。503, 504エラーが発生しているものの、RequestReceiver からのリクエストが Load Balancer で弾かれて BatchProcessor に到達していないため、アプリ側のエラーログが残っていませんでした。

そこで調査のために Load Balancer のログを Datadog で見ようとしましたが、Datadog では Load Balancer のメトリクスについてバックエンドのホスト単位でレスポンスコードを見ることができず、解像度が低いという課題がありました。そこで、Load Balancer のログを一時的に取得し、Looker Studio で可視化しました。

Looker Studio で結果を見ると、特定のホストから504が最初に発生し、その後503を返却することがわかりました。504発生から503を返すまでの時間幅が、Load Balancer のヘルスチェックに失敗してからサービスアウトされるまでの猶予期間と一致していました。

対応

  • BatchProcessor が503を返却した場合、503を返却したサーバと別サーバに対してリトライを入れる対応を実施
  • Load Balancer のヘルスチェックの間隔を短くして、なるべく早く問題のあるインスタンスをサービスアウトさせる

補足:

BatchProcessor は単位キーごとに大きなローカルキャッシュを構築してバッチ処理を行うため、Load Balancer のセッションアフィニティを利用しています。 そのため、リトライしても同一インスタンスにルーティングされ、503の場合は再試行が無駄になる設計上の制約がありました。そこで、リトライ時にはセッションアフィニティのkeyを変更してリトライさせるようにしました。この場合、リトライ先のインスタンスには該当キーのローカルキャッシュが存在しないため、キャッシュミスが発生しますが、503エラーで失敗するよりも望ましいと判断しました。

共有したいこと

Datadog のような観測ツールは強力ですが、コストや制約から必ずしもすべての情報を常時収集できるわけではありません。 今回のケースでは、Load Balancer のログを Cloud Logging 経由で BigQuery にエクスポートし、SQL でクエリを書いて Looker Studio で可視化することで、クイックにバックエンドのホスト単位での詳細な分析を実現しました。

この手法の利点は以下の通りです。

  • GCP のログエクスポート機能により簡単にLBのログを収集可能
  • BigQuery の SQL により柔軟な集計・分析が可能
  • SQLの結果をシームレスに Looker Studio で可視化出来るので視覚的な分析が容易
  • Datadog でカーディナリティーの高いカスタムタグを追加するとコストが増加するため、一時的な深堀り調査にはこの方法が効果的

問題2: 503が起きる場合、必ずインスタンスがハングして異常終了してしまう

調査のアプローチ

インスタンスが異常終了する原因を特定する必要がありましたが、アプリケーションがロックでハングしていたため、通常のアプリケーションログからは有効な情報が得られませんでした。

そこで、Datadog の APM と Profiling を活用しました。

まず APM のメトリクスを分析したところ、該当時間帯に Lock Contention(ロック競合待ち時間)が継続的に高い値を示していることを発見しました。

次に、Profiling の Comparison 機能を使用して、通常時と Lock Contention が高騰している時間帯の Wall Time(スレッドが実際に消費した時間)を比較しました。この比較分析により、どのメソッドがロック待ちの原因となっているかを特定できます。結果、データベースへのread操作が何らかの理由で一時的に遅延した際に、複数スレッドが同一のオブジェクトに対してロックを取得しようとして競合が発生していることが判明しました。

※ 実際の画像をお見せしたいのですが、セキュリティの観点によりDatadogから画像引用しています

参照: https://www.datadoghq.com/blog/code-optimization-datadog-profile-comparison/

対応

タイムアウトの原因は根深い問題があったため、この解決は別プロジェクトとして取り組むこととし、今回はデータベースへのread操作にタイムアウトを設定して、タイムアウト時はエラーとして扱うように変更しました。

結果

タイムアウトにより最悪数秒は応答に時間がかかるようになったため、RequestReceiverのポーリングタイムアウトとの兼ね合いで、SLOの数値自体は大きく改善しませんでした。しかし、インスタンスがハングして異常終了する問題は完全に解消され、サービスの安定性は向上しました。

共有したいこと

Datadogの APM と Profiling は、アプリケーションのパフォーマンス問題を特定する上で非常に便利です。

特に今回のようなケースでは、以下の点で有効でした。

  • 継続的なプロファイリング: 本番環境で常時プロファイリングが行われているため、問題発生時の詳細なデータを事後的に分析できる
  • 時系列でのメトリクス追跡: CPU使用率、Lock Contention、Memory allocation などのメトリクスをスレッド単位・時系列で追跡可能
  • Comparison機能: 正常時と異常時のプロファイルを比較することで、パフォーマンス劣化の原因となっているコードパスを迅速に特定できる
  • ログでは捉えられない問題の可視化: 今回のようにアプリケーションがハングしてログが出力されない状況でも、プロファイリングデータから問題箇所を特定できる

つい先日も、OOM(Out Of Memory) エラーで悩んでいるチームがProfilingを導入した結果、その日のうちに原因を特定して改善できていました。アプリケーションレベルのパフォーマンス問題に直面した際は、積極的に活用することをお勧めします。

問題3: インスタンスタイプを切り替えたあとにエラーバジェットの消費速度が加速

調査のアプローチ

上記2つの対応により目標の数値をクリアできる水準に達していました。しかし、パフォーマンス改善のためにインスタンスタイプを切り替えたところ、再び目標数値を下回る水準になってしまいました。 アプリケーションのログやLoadBalancerのステータスコードには全く異常がないので調査が難航しました。 コードを読み込み、BatchProcessor の ログが格納されたBigQueryのレコードで個別調査するなど地道な努力をして、考えうる可能性をほぼ潰しました。

それでも原因が特定できなかったため、問題の発生箇所を以下のように絞り込んで、システムの初期設計に関わったエンジニアに相談しました

  • RequestReceiverからBatchProcessorに対してリクエストは適切に行われているにもかかわらずバッチ処理がスキップされているように見える
  • インスタンス起動後、数分間のみこの事象は発生する

ここでNTP が怪しいという話になり、RequestReceiver で保存するリクエストが未来に対して行われていることがわかりました。

根本原因は以下の一連の流れでした。

  1. インスタンスタイプをよりパフォーマンスの良いものに変更したことで、インスタンスの起動速度が向上
  2. 起動が速くなったため、NTP による時刻同期が完了する前にアプリケーションがリクエストを受け付けるようになった
  3. 時刻同期前のサーバの時刻が未来にズレているケースでは、RequestReceiver が データベース にリクエストを保存する際のタイムスタンプが未来の時刻になっていた
  4. BatchProcessor は「現在時刻までのリクエスト」を取得してバッチ処理を行うため、未来のタイムスタンプを持つリクエストがバッチ処理対象から除外されてしまった

つまり、インフラの改善(インスタンスタイプの変更)が、意図せず時刻同期の問題を顕在化させていました。

補足:

NTP は設計上、起動直後に数 ms 程度の時刻ずれが発生し得ます。これは、NTP がネットワーク越しの時刻問い合わせ結果をもとに、往復遅延やジッタを考慮して統計的に時刻を推定し、段階的に時刻補正を行う仕組みであるためです。そのため、起動直後に即座に正確な時刻へ収束することは保証されません。

より厳密な時刻保証が必要な場合は PTP を利用することで、起動直後から高精度な時刻同期が可能です。一方で、PTP は利用可能なインスタンスタイプやゾーンに制約があり、今回変更先のインスタンスタイプでは未サポートでした。

対応

BatchProcessor でバッチ処理をする際、RequestReceiver 側のタイムスタンプが現在時刻より未来の場合は、時刻同期のズレと判断し、その分だけsleepして待機してから処理を行うように修正しました。

他の解決策として、DBのサーバサイドタイムスタンプを利用することや、NTP同期完了までリクエストを受け付けない方法などを考えましたが、以下の理由から現在の対応を選択しました。

  • DBの特性及び現在のスキーマ設計上、DBのサーバサイドタイムスタンプを利用するのは困難
  • 時刻のズレは起動時の1~5ms程度だが、NTP同期完了までの数分間は問題が発生
  • NTP同期完了待ちはインスタンス起動時間が延び、Auto Scalingの応答性に影響
  • 起動直後の数分間のみ集中して発生する一時的な問題であり、現時点ではこの対応で十分と判断

共有したいこと

可能性を一つづつ排除していき、それでも迷ったときは、システムの初期設計に関わったエンジニアに相談することが重要です。 開発時に懸念していた潜在的な問題や、設計上のトレードオフ、考慮していた制約条件など、ドキュメントには残っていない幅広い知識を持っています。今回も、そうした知見が問題解決の突破口となりました。

まとめ

3つの問題を解消、軽減することで、SLOを一段と引き上げることができました。SLO改善は終わりのない戦いですが、こうした地道な積み重ねがサービスの信頼性向上につながっていくと信じています。