とあるエンドポイントのレスポンスタイムが落ちているとの報をうける。サーバのメトリクスをみてみると、前日 23 時ごろから急激にプロセスの busy 数が増えていた。平常時の 3 から 4 倍という急上昇だ。

当該サーバでは複数のアプリが動いている。それぞれが別ポートで立ち上がっていて、nginx でリバースプロキシしリクエストをふっている。それぞれのアプリは数十程度の worker がリクエストを処理する。worker がいくつ埋まっているかを定期的に監視している。

いくつかあるアプリのうち、当該時間帯以降に busy worker が急激にふえているものとそうでないものがあった。また埋まり具合もまちまちだ。

もっとも悪化が激しいアプリは、そのアプリへのリクエストが増えると、連動して他の特定のアプリへのリクエストも増えるという性質がある。今回 busy が増加しているのはこれらのアプリのみで、その他はほぼ変化がなかった。よってなんらかの要因でリクエストが急増したというのが、まず考えうる原因だった。

まずはこの仮説をうらづけるため、ログの調査をおこなう。nginx とアプリの両方のログを対象とし、障害発生時点の前後で件数を調査する。またリクエスト元をおおざっぱにわけて、当該時間から急増したリクエスト元がないか調べる。今回の場合は複数の web 面からリクエストが飛ぶものだったので、リクエスト元のドメインごとに件数を集計した。

しかし、平時とほとんどかわらないという結果になる。同時にインフラ担当からも、スイッチが受けているトラフィックが平常だという情報をもらう。リクエスト増加によるものではないようだ。

リクエストの数が変わらないのであれば、残る原因は 1 リクエストあたりにかかる時間がふえてしまっているということだけだ。

ここでも、やはり最も悪化の激しかったアプリに的をしぼり調査していく。このアプリは、起動時に設定情報をメモリにロードし、設定情報におうじてリクエストを判断し、結果を KVS に書きこむものだ。KVS は複数のアプリから読み書きされており、今回問題になっているところ以外ではとくにエラーがでていない。ロジックはしばらく変更されていないので、のこるはインプットにあたる設定情報だ。ここが増えると、特定のリクエスト時に計算量がおおきくなり、結果全体として busy がふえるというシナリオ。これは考えられなくもない。

しかし、このインプットデータが夜間に、これほどのパフォーマンスの急激な悪化をともなうほどに、データがふえるというのは相当なことだ。現時点でのデータセットを目検、データの差分ログから当該時間帯の変更をおう。しかしこれといった決定打がみつからない。

いったん手詰まり。もういちど各種ログをながめる。よくみると KVS へのセットの失敗をしめすログが多くでている。他のアプリのログをみてみても同様だ。これは KVS が怪しい。

KVS サーバのメトリクスをみると一目瞭然だった。KVS のプロセスに問題がおこっていて、プロセスは立ち上がっているが書き込みができない状態だった。悪いタイミングがかさなり、設定不備によりアラートメールも適切に飛んでいなかった。そのことにより発覚がおくれた。

おなじ KVS をさわっているのに問題が表面化していなかった部分もある。その理由は次の通りだった。

• ほかのアプリは主に KVS から get している。今回エラーが多発していたのは set 中心のアプリだった
• KVS からの get にはタイムアウトを設けていたので、情報の取得に失敗しても worker を専有してしまうことはなかった。set は多少遅くても確実にかきこみたかったので、タイムアウトを入れていなかった。

というわけで、こんかいの問題点をあげると:

• まずはアラートが適切にとばなかったこと、これが大きかった。
• つぎにアプリのログが多すぎたこと。無駄なログがなければ、KVS のセット失敗のログが埋もれることがなかった。
• 最初にめどをつけた方針ひひっぱられすぎた。とくにリクエスト量がかわらないとわかったあとの一手。当初の仮説が否定されたのに、まだ最初にあたりをつけた部分を疑ってしまっている。
• 特定のあたりをつけたログ・サーバメトリクスだけでなく、とりあえず関わっているところ全体をざっと目を通す。異常値はそれでもみつかるはず。