本当にあった、何もしていないのに突然DBの負荷が爆増した話

こんにちは。 エキサイト株式会社の三浦です。

「何もしていないのに壊れた」という経験、皆さんはあるでしょうか? 今回はそのパターンの1つ、本当に私が体験した「何もしていないのに突然DBの負荷が爆増した話」をさせていただきます。

始まり

その日は、大きなリリースもユーザーの急激なアクセスもなく、特に何の変哲もない日でした。 いつもどおり開発をしていると、ふとSlackに、サービスで使用しているDB(RDS)のCPU使用率が高くなっているとの通知が届いていることに気づきました。

(あー、なんか急激にアクセスが来たか何かなのかな…)と思いながらAWSコンソールを開いて確認してみると…なんと、CPU使用率が100%に張り付いているのです。

一気に背筋が凍り、すぐにメンバーに連絡しつつ、調査に入りました。

調査

改めてAWSコンソールを見ると、ある時間から急にCPU使用率が急上昇し、そのまま100%まで行ってしまっているようです。 それまではせいぜい30 ~ 40%程度ですし、今までそんなことは起きていないので、明らかに異常事態でした。

とりあえずその時間帯に何かの新規リリースがあるか調べてみると…ありました。 ちょうど、DBを触るAPIの機能改修のリリースです。

ですが、コードを見る限りDBの負荷が上がるような変更ではありません。 メンバーと連携しつつ、祈るような気持ちで前バージョンに戻してみましたが、結果は残念ながら効果なしでした。

それと並行し、急激にアクセスが増えていないか、ユーザー全体だけでなくBotのアクセスだけが急激に増えていたりしないかなども調べてみましたが、全く変化している様子はありません。

更に、(急にスロークエリが出てきたともあまり思えませんが)スリークエリログを調べてみても、特段ヤバそうなものは見当たりません。

この時点で、この障害対応が長期戦になることを覚悟しました。

光明

それは、メンバーのメンタルがやられてきた時のことでした。 あるメンバーが一言、「プロセスリストはどうなっているんだろう?」と言ったのです。

プロセスリストとは、現在DBで実行されているプロセス一覧です。 確かに見ていないなと思い確認してみると、なんと10分以上に渡って実行され続けているプロセスが複数個あるではありませんか!

そのSQLをもとにどこからのリクエストか調べてみると、どうやらとあるバッチからのアクセスのようです。 実際にそのSQLを手動で流してみると、とても重いSQLであることが判明しました。 Explainを調べて見ると、Indexこそ当たっているものの、使用するIndexを手動で選択していたせいもありIndexの当たり方に問題があって、実行時間としては遅くなってしまっていたようでした。

取り急ぎバッチサーバを停止し、プロセスリストから手動で該当のプロセスを削除して見たところ、みるみるCPU使用率が下がっていき、ようやくこの騒動の終わりが見えたのでした。

原因

バッチサーバの再開、SQLの修正などの騒動の後始末の中、メンバーで今回の原因が何だったか話し合っていたのですが、「おそらくはレコードの増加が原因だろう」という結論に帰着しました。 今回のテーブルはバッチ等で自動的にレコード数が増えていくタイプのテーブルだったのですが、レコード件数がある一定値を超えてしまった結果、SQLが全く同じにもかかわらず重くなり、結果として今回の騒動に至ったというわけです。

まさしく(コードの修正という意味では)何もしていないのに、突然DBの負荷が爆増したわけでした。

最後に

今回のように、自動的にレコード数が増えるタイプのテーブルでは、何もしていなくても状況が急変する可能性があります。

そういった際、「新規リリース」や「アクセスの増加」などの外的要因が原因だと決めつけるのではなく、もしかしたらレコードの増加のような、一見見えにくい内的要因が原因の可能性もあると考えておくだけでも障害対応の速度が上がるのでは無いでしょうか。 皆さんの参考になれば幸いです。

なお今回は、RDSであることを最大限利用し、動的にReadインスタンス数を増やし、余剰のインスタンスを持った上でスペック(インスタンスタイプ)の変更や再起動をすることができました。 結果として、幸いにもユーザーから見る上ではサービスがそこまでDBの障害の影響を受けることはなく、大事に至らなかったので、そこだけは不幸中の幸いでした。