0.はじめに
SaaSの開発・保守運用をしています。
今日は、たった数行の改修で、大規模サービスのテスト環境が全て停止しかけた話をします。
1.経緯
PHPで書かれたシステムの改修時に発生した問題になります。
for ($i = 0; $i <= $num; $i++) {
// ～～～数百行に渡る処理
}
上記のような処理があり、$numにはユーザーが任意で入力した1～100の値が入ります。
この処理の内部を改修する事になりました。
for ($i = 0; $i <= $num; $i++) {
// ～～～数百行に渡る処理
for ($i = 0; $i <= 3; $i++) {
// ～～～簡単な処理
}
// ～～～数百行に渡る処理（PDOを介したデータベースへのインサート処理）
}
大雑把な内容はこのような改修になります。
この時点で何が起きるかは分かると思いますが、外側のループ変数に使われる$iは、内部ループに入った時にリセットされ、$i = 0からセットされ、最終的に$i = 4がセットされた状態で外側のループ先頭に戻る事になります。
その際に判定に使われるループ変数はもちろん$i = 4で固定されるため、つまり、、、
「$numが5以上に設定された場合には処理が無限ループ、更に4以下の場合は1度しかループしない」という結果になります。
しかもこちらはウェブアプリケーション上で実行されていましたが、該当処理の前に
set_time_limit(0);
の記述があり、タイムアウトも期待できない状態になりました。
2.予見
最初の予見は朝、テストサーバー全体がなんとなく重いと言われた事でした。
平日の朝はそもそもテストサーバーへアクセスが集中しやすいため、アクセス負荷はある程度ありましたが、ウェブサーバーのプロセス数、CPU使用率、LA、メモリ等のスタッツは普段の同時間帯と変わらず、特に違和感に気づく事はできませんでした。
その後も感覚的に重いなと感じる状況は何度かありましたが、明らかな原因は分からず、即時何か対応は行いませんでした。
3.発覚
昼になり、まだ重いと声が上がっていて、何か起きているのかと再度確認を行いました。
その際にようやく気付きましたが、書き込み用のデータベースサーバーのストレージ使用率が95%近くになっていました。
GeneralLogの保存は行っていなかったため、とりあえずshow processlistを連打したところ、あるレコードのインサートが毎秒何十回も送られている事に気づきました。
直近のソースの変更履歴を確認した際に、上記ループ文が無限ループとなる可能性がある事に気づきました。
4.対処
ソースコードはもちろん発覚後、2，3分で修正を行いました。
for ($i = 0; $i <= $num; $i++) {
// ～～～数百行に渡る処理
for ($cnt = 0; $cnt <= 3; $cnt++) {
// ～～～簡単な処理
}
// ～～～数百行に渡る処理（PDOを介したデータベースへのインサート処理）
}
この時点でマスターデータベースの容量は98%に達していました。
（容量を圧迫していた直接の原因はバイナリログでした）
ソースコードを修正しましたが、走り出したプロセスは止まる事無く、修正前のソースコードでインサートを続けていました。
次にMySQLのトランザクションをキルしました。
しかし新たなトランザクションが作成され続け、まだインサートは止まりませんでした。
最終的にすべてのウェブサーバーを再起動し、プロセス毎強制停止し、インサートが停止しました。
5.その後の対応
無限にインサートされたレコードは関係テーブルを合わせて計数千万レコードに及んでしました。
予期せずインサートされてしまったすべてのレコードの削除を行いました。
一気にすべてのレコードをDELETEした際に、大幅なレプリケーション遅延が発生する可能性があったため、10万レコードずつDELETEを行いました。
その後、データベースの断片化解消を行うため、OPTIMIZE TABLEを実行し、復旧となりました。
6.発生要因
冒頭に書いたようなソースコードですが、あの状態で見れば一目危ない事に気づけますが、実際にはその間に数百行のソースコードが入っており、外側のループ変数で何が使われていたか、気づく事はできませんでした。
gitのウェブ上でコードレビューを行った際にも、表示されるのは多少の前後行のみで、ループの冒頭を確認する事はありませんでした。
7.対策
forループを使う際は$i以外のループ変数を使うか、range関数で生成した配列をforeachするようにしました。
foreach (range(0, 10) as $num) {
// ～～～処理
}
8.良かった事
本番環境ではなく、テスト環境で発覚したため、最悪の事態は回避できました。
あと発覚が数十分ほど遅れてしまった場合は新たなバイナリログの出力ができなくなり、マスターデータベースのMySQLが停止していたので、テスト環境を再構築するハメになっていました。
ギリギリで間に合ったことは不幸中の幸いでした。
9.悪かった事
朝から再三、確認する機会があったものの、この状況に達するまで気づく事ができませんでした。
何かあった際に確認するスタッツは一覧化した上で正常な値のレンジをドキュメント化しておく必要があると思いました。
10.反省
テスト環境にアップする前のコードレビューの段階で気づく必要があったので、その後はループ変数をしっかり確認するようになりました。
良ければ他の記事も読んでください