昨日の障害報告＋明日からのG1予想大会(…大丈夫だろうか？)

まずは、昨日の障害についての原因を
報告させていただきます。

-----

(おそらく)一昨日の夜ごろから、昨日午前中にかけて
一部ページにおいて、大変アクセスしづらい状況が続いていました。

経過と原因です。(少々技術的な話になります。)


Webサーバ(Apacheの場合)において、
1回リクエストがあるごとに1つのプロセスが生成され
レスポンスを返し終わると、プロセスは消えます。

1つのリクエストの処理をしている間に、さらに1つリクエストされる
＝1つのプロセスが消える前に、さらに1つのプロセスが生成される
と、後からできたプロセスは「実行待ち」の状態になります。
つまり、前のリクエストへレスポンスが完了しないと、
次のリクエストへはレスポンスできません。

当然、システムの中ではWebサーバとしての処理だけではなく、
データベースのプロセス、メールのプロセスなど
複数のプロセスが実行(もしくは待機)しています。

CPUが1つの場合は、1つのプロセスしか処理ができません。


UNIX系OSで、システムの指標となる「Load Average」。
システム内においての単位時間当たりの「実行待ちプロセス数」です。
「top」などのコマンドで確認できます。

通常ですと、このサーバでの1分値Load Averageは0.4〜0.8程度。
1つのCPUに対して、処理されるのを待っているプロセスが1分間に0.4〜0.8。
つまり、ほとんど待つことなく、プロセスは処理されていくわけです。


ところが。
昨日朝、夜勤明けで帰ってきてサーバを確認したところ
1分値のLoad Averageが……なんと、93！
つまり、1分間に93個ものプロセスが処理されずに待っている状態。
しかも、待っているプロセスはほとんどがhttpd(Webサーバのプロセス)。

明らかにおかしい。
○ずほ銀行のシステムばりにおかしい。


負荷の大きいプロセスを探しました。
…見つかりません。

データベースが壊れた？
…エラーなし。オーバーヘッドも大きくない。
レスポンスも悪くない(全体のレスポンスが悪いから、多少は悪いけど。)
slow-log-queryの設定をいれ、データベースを再起動。
クエリ(データベースからデータを取得するロジック)が
特に遅いところをログに吐き出してみるも…手がかりは見つからず。


となると、アクセスの急激な増加…？

Webのアクセスログとエラーログを解析。
3つの検索エンジンがサイト内を徘徊している様子。
そのうちのもっともアクセスの多い検索エンジンを接続拒否設定してみる。
(tcpwrapperのhosts.allowにALL:(IP):denyで拒否。inetdプロセスをkill -HUP)

Load Averageは1.2〜4前後。

それでもおかしい…。
み○ほ銀行のシステムばりにおかしい。


自分のサイトを一通り徘徊してみる。

すると、特定のページ(3ページ)だけ、アクセスが遅いことに気付いた。
簡易版出馬表、各競走馬のデータページ、Favo馬一覧ページ。

前2ページは、明らかに日曜日に手を入れたところ。
他のページとの違いはなんだ………？



いままでのFavoユーザは、認証なしでログインできていた方が多いかと思います。
Cookie(クッキー)という機能。
登録時に入れていただいたユーザIDやその他の情報を
ご覧の皆様がお使いのパソコンに保存させていただいています。

実は、ご覧の皆様がお使いのパソコンにCookieとして保存していただいている情報は、
当サーバにsession(セッション)という形でも管理させていただいています。

当サイトの認証が必要なページにアクセスしていただいたときに、
Cookieファイルを読み取らせていただき、
また、sessionファイルをサーバ内から読み取ることで、
お使いのパソコンのCookieの情報と、当サーバに保管されているsessionを照合して
一致すれば、認証の手続きなく、ログインできる仕組みになっています。

照合して一致しなければ、認証画面が表示されて
再びCookieとsessionに情報が書き込まれて保存される仕組みになっています。


先に書いた3つのページ。
共通するのは、サーバ内のsessionファイルを開いているということ。

sessionファイルが存在しない場合には、
自動でsessionファイルを作成する仕組みになっています。

簡易版出馬表、各競走馬のデータページは
登録ユーザ以外でも自由に表示できるページです。
つまり、検索エンジンからも自由に見ることができるページ。
検索エンジンには、当然Cookieが保存されていませんから、
アクセスされるたびに、Sessionファイルがそのサーバ内に作成されていきます。


はぁ…。

Sessionファイルの保存先ディレクトリを見てみました。
……。

Sessionファイルが30000ファイル以上作成されていました。



簡易版出馬表ページ。
登録ユーザには、今週から始まる「G1予想大会」の「予想する」リンクを付けて、
未登録ユーザには、リンクを表示しないような仕組みを。

各競走馬のデータページ。
登録ユーザには、「Favo馬登録」リンクを付けて、
未登録ユーザには、「SBメンバーズ」の説明リンクをつける。


日曜日に追加したロジックです。

どちらのページも、Sessionを開くロジックは追加したものの
Cookieを開くロジックは追加しておらず。
Cookie情報が読み取れないため、アクセスがあるごとにSessionファイルは増えていく……。


重くなった原因はこれでした。





はっきり言います。

バグです。
管理人の不手際です。
みず○銀行ばりの不手際です。


皆様には、多大なるご迷惑をおかけしました。
本当に申し訳ありませんでした。


-----

こんな状況の中、
明日の16時前後には、日曜日の皐月賞の馬番が決定します。

同時に、「G1予想大会」が始まってしまいます。

こんなバグだらけのシステムで
本当に予想大会はうまくいくのだろうか……？

よりによって、明日管理人は
本職では夜勤。帰ってきません。
帰宅は金曜日の朝。


少しの期待と、大きな不安のなか
明日いよいよ企画がスタートします。

ぜひ多くの方に参加していただきたいと思います。