Robloxの昨年の73時間障害ポストモーテム

outsideris · 2022-01-31T21:31:10+09:00

障害の要約障害は72時間にわたって発生した根本原因は2つあった異常に高い読み取り/書き込み負荷がある状況でConsulの新しいストリーミング機能を有効化したことで、過度な競合と性能低下が発生特定の負荷状況で、Consulがリーダー選出とデータレプリケーションのためのwrite-ahead logを管理する際に使用するオープンソースのBoltDBで性能問題が発生単一のConsulクラスターがこれらの問題の影響を悪化させた Consul実装に潜んでいた、この2つの一見無関係な問題を突き止めるのに時間がかかり、障害が長期化した障害原因のより良い可視性を提供すべきだった監視システムが、Consulのように影響を受けたシステムに依存していたため、原因特定がさらに困難になったクラスター環境とHashiStack Robloxは18,000台のサーバーと170,000個のコンテナを運用中一般にHashiStackと呼ばれるNomad、Consul、Vaultを使用中当時Robloxではストリーミング機能を使うため、Consulを1.9から1.10へアップグレードした。初回検知（10/28 13:37） 10月28日午後、Vaultの性能が低下し、あるConsulサーバーのCPU負荷が高くなった。初期分類（10/28 13:37 – 10/29 02:00） Consulクラスターのメトリクスで書き込みレイテンシが増加原因としてハードウェア性能低下を疑い、Consulクラスターのノードの1つの交換を開始 HashiCorpのスタッフが合流し、共同で対応を開始ハードウェア交換後もConsulの性能は低下し続け、16:35にはプレイヤー数が通常の50%まで減少 Consulはサービスディスカバリーに使われ、NomadとVaultもConsulに依存していたため、ConsulがSPoFだったこの時点で、トラフィックが原因だという新たな仮説を立てた。高トラフィックによりConsulが負荷を処理できなくなったと考えた Consulクラスターの全ノードをより強力なシステムに交換（コア数2倍、より高速なNVMe SSD） Consulの移行はほぼ完了したが、クラスターは正常に戻らなかったサービス復旧の試み #1（10/29 02:00 – 04:00）障害前のConsulクラスターのスナップショットに戻すことを決定ユーザーデータは無事で、システムデータは一部失われるが許容できると判断スナップショット復旧後、Consulと継続的に通信するシステムによる負荷で再び問題が起きることを懸念し、iptablesでアクセスを遮断スナップショット復旧後は指標が良く見えたが、iptablesの遮断を解除すると再び元の障害状態に戻ったサービス復旧の試み #2（10/29 04:00 – 10/30 02:00）外部トラフィックを遮断し、必須でない利用を除去した結果、数百インスタンスで運用されていたサービスが1桁台まで減少再度サービス復旧を試みたが、Consulは再び異常状態になった当初想定していた性能低下要因以外にも問題があると気づき、Roblox視点のConsulではなくConsul内部を見始めた競合分析（10/30 02:00 – 10/30 12:00）さらに10時間分析した結果、Consulの書き込みが長時間ブロックされていたことが判明競合の原因は不明だったが、初期にCPUを64コアから128コアへ変更したことが競合をさらに悪化させたと判断 64コアに戻すことを決めて戻したが、効果はなかった根本原因の発見（10/30 12:00 – 10/30 20:00） Consulのストリーミング機能は数か月前から有効化しており、CPU使用率とネットワーク帯域幅を下げていたため、段階的に導入している途中だった。障害前日の27日14:00にトラフィックルーティングバックエンドでこの機能を有効化した。前日に有効化して正常に動作していたため、原因とは考えなかった性能分析の結果、ストリーミングコードが高いCPU使用率を引き起こしている証拠を確認ストリーミングを無効化し、デプロイ完了後にConsulのKV書き込みレイテンシが低下したことを確認（ついに！） HashiCorpによれば、ストリーミングはより効率的だが、実装ではロングポーリングより少ない数の並行制御要素（Goチャネル）を使用していた -> 高負荷時に単一のGoチャネルでの競合を悪化させ、効率を低下させた突破口は見えたが、依然として断続的なリーダー選出が見られ、一部のリーダーでは以前と似たレイテンシ問題が発生していた特定のリーダーだけが選出されなければクラスターは正常だと判断し、サービスを正常状態に戻すことに集中その後HashiCorpは根本原因の調査を継続し、一部リーダーが遅い問題はBoltDBに起因すると突き止めたキャッシュサービス復旧（10/30 20:00 – 10/31 05:00）障害発生から54時間後、サービス復旧の準備が整った障害中もデータベースは無事だったが、毎秒10億リクエストを処理するキャッシュシステムは異常な状態だった。このキャッシュを復旧し正常であることを確認した時点で、障害発生から61時間が経過していた。ユーザー復帰（10/31 05:00 – 10/31 16:00） 31日5時にサービス復帰の準備を開始し、10時に完了した。 DNS経由でアクセスするプレイヤー数を管理し、監視しながら増やしていった 73時間後、すべてのプレイヤーがアクセス可能になった。追加分析と障害による変更点 HashiCorpとRobloxは「compaction」プロセスを開発し、性能問題を解決テレメトリ改善: テレメトリシステムとConsulの間に循環依存があり、Consulに問題があるときはデータが不足していた。テレメトリシステムが監視対象システムに依存しないよう、循環依存を解消アベイラビリティゾーンとデータセンターを拡張他のストレージがあるにもかかわらずConsulに保存していたデータや不要なKVデータを整理 BoltDBの後継であるbboltに置き換えた新バージョンのConsulをテスト中ブートストラッププロセスのため復旧が遅れたため、これを自動化し、新しいツールとプロセスを開発中

(blog.roblox.com)

16 ポイント投稿者 outsideris 2022-01-31 | 1件のコメント | WhatsAppで共有

障害の要約

障害は72時間にわたって発生した
根本原因は2つあった
- 異常に高い読み取り/書き込み負荷がある状況でConsulの新しいストリーミング機能を有効化したことで、過度な競合と性能低下が発生
- 特定の負荷状況で、Consulがリーダー選出とデータレプリケーションのためのwrite-ahead logを管理する際に使用するオープンソースのBoltDBで性能問題が発生
単一のConsulクラスターがこれらの問題の影響を悪化させた
Consul実装に潜んでいた、この2つの一見無関係な問題を突き止めるのに時間がかかり、障害が長期化した
障害原因のより良い可視性を提供すべきだった監視システムが、Consulのように影響を受けたシステムに依存していたため、原因特定がさらに困難になった

クラスター環境とHashiStack

Robloxは18,000台のサーバーと170,000個のコンテナを運用中
一般にHashiStackと呼ばれるNomad、Consul、Vaultを使用中

当時Robloxではストリーミング機能を使うため、Consulを1.9から1.10へアップグレードした。

初回検知（10/28 13:37）

10月28日午後、Vaultの性能が低下し、あるConsulサーバーのCPU負荷が高くなった。

初期分類（10/28 13:37 – 10/29 02:00）

Consulクラスターのメトリクスで書き込みレイテンシが増加
原因としてハードウェア性能低下を疑い、Consulクラスターのノードの1つの交換を開始
HashiCorpのスタッフが合流し、共同で対応を開始
ハードウェア交換後もConsulの性能は低下し続け、16:35にはプレイヤー数が通常の50%まで減少
Consulはサービスディスカバリーに使われ、NomadとVaultもConsulに依存していたため、ConsulがSPoFだった
この時点で、トラフィックが原因だという新たな仮説を立てた。高トラフィックによりConsulが負荷を処理できなくなったと考えた
Consulクラスターの全ノードをより強力なシステムに交換（コア数2倍、より高速なNVMe SSD）
Consulの移行はほぼ完了したが、クラスターは正常に戻らなかった

サービス復旧の試み #1（10/29 02:00 – 04:00）

障害前のConsulクラスターのスナップショットに戻すことを決定
ユーザーデータは無事で、システムデータは一部失われるが許容できると判断
スナップショット復旧後、Consulと継続的に通信するシステムによる負荷で再び問題が起きることを懸念し、iptablesでアクセスを遮断
スナップショット復旧後は指標が良く見えたが、iptablesの遮断を解除すると再び元の障害状態に戻った

サービス復旧の試み #2（10/29 04:00 – 10/30 02:00）

外部トラフィックを遮断し、必須でない利用を除去した結果、数百インスタンスで運用されていたサービスが1桁台まで減少
再度サービス復旧を試みたが、Consulは再び異常状態になった
当初想定していた性能低下要因以外にも問題があると気づき、Roblox視点のConsulではなくConsul内部を見始めた

競合分析（10/30 02:00 – 10/30 12:00）

さらに10時間分析した結果、Consulの書き込みが長時間ブロックされていたことが判明
競合の原因は不明だったが、初期にCPUを64コアから128コアへ変更したことが競合をさらに悪化させたと判断
64コアに戻すことを決めて戻したが、効果はなかった

根本原因の発見（10/30 12:00 – 10/30 20:00）

Consulのストリーミング機能は数か月前から有効化しており、CPU使用率とネットワーク帯域幅を下げていたため、段階的に導入している途中だった。
障害前日の27日14:00にトラフィックルーティングバックエンドでこの機能を有効化した。
前日に有効化して正常に動作していたため、原因とは考えなかった
性能分析の結果、ストリーミングコードが高いCPU使用率を引き起こしている証拠を確認
ストリーミングを無効化し、デプロイ完了後にConsulのKV書き込みレイテンシが低下したことを確認（ついに！）
HashiCorpによれば、ストリーミングはより効率的だが、実装ではロングポーリングより少ない数の並行制御要素（Goチャネル）を使用していた -> 高負荷時に単一のGoチャネルでの競合を悪化させ、効率を低下させた
突破口は見えたが、依然として断続的なリーダー選出が見られ、一部のリーダーでは以前と似たレイテンシ問題が発生していた
特定のリーダーだけが選出されなければクラスターは正常だと判断し、サービスを正常状態に戻すことに集中
その後HashiCorpは根本原因の調査を継続し、一部リーダーが遅い問題はBoltDBに起因すると突き止めた

キャッシュサービス復旧（10/30 20:00 – 10/31 05:00）

障害発生から54時間後、サービス復旧の準備が整った
障害中もデータベースは無事だったが、毎秒10億リクエストを処理するキャッシュシステムは異常な状態だった。
このキャッシュを復旧し正常であることを確認した時点で、障害発生から61時間が経過していた。

ユーザー復帰（10/31 05:00 – 10/31 16:00）

31日5時にサービス復帰の準備を開始し、10時に完了した。
DNS経由でアクセスするプレイヤー数を管理し、監視しながら増やしていった
73時間後、すべてのプレイヤーがアクセス可能になった。

追加分析と障害による変更点

HashiCorpとRobloxは「compaction」プロセスを開発し、性能問題を解決
テレメトリ改善: テレメトリシステムとConsulの間に循環依存があり、Consulに問題があるときはデータが不足していた。テレメトリシステムが監視対象システムに依存しないよう、循環依存を解消
アベイラビリティゾーンとデータセンターを拡張
他のストレージがあるにもかかわらずConsulに保存していたデータや不要なKVデータを整理
BoltDBの後継であるbboltに置き換えた新バージョンのConsulをテスト中
ブートストラッププロセスのため復旧が遅れたため、これを自動化し、新しいツールとプロセスを開発中

1件のコメント

xguru 2022-02-01

翻訳ありがとうございます。

あの規模で72時間の障害は本当に恐ろしいですね